Обсуждение: Re: Issue in PG start

Hello,

PG 11.8 in Windows 10 and currently PG 11.11

Yesterday [07th May] morning when we switched on the computer and subsequently PGAdmin, we got the message following message

FATAL: the database system is starting up

I uninstalled PG and installed [v 11.11] PG with the same data directory.  Fortunately it worked even when we switched off /on the computer for lunch.   NO issues yesterday.

But today morning [08th May], again we have the same issue and same message.   The log file is with the following message only

2021-05-08 10:26:20.783 IST [7360] LOG:  database system was interrupted; last known up at 2021-05-07 18:46:00 IST

How / where to debug the issue and correct it ?

On 5/7/21 10:14 PM, sivapostgres@yahoo.com wrote:
> Hello,
> 
> PG 11.8 in Windows 10 and currently PG 11.11
> 
> Yesterday [07th May] morning when we switched on the computer and 
> subsequently PGAdmin, we got the message following message
> FATAL: the database system is starting up
> 
> I uninstalled PG and installed [v 11.11] PG with the same data 
> directory.  Fortunately it worked even when we switched off /on the 
> computer for lunch.   NO issues yesterday.

First why switch the computer off for lunch?

Second did you stop the Postgres server before shutting down the machine?

> 
> But today morning [08th May], again we have the same issue and same 
> message. The log file is with the following message only


In postgresql.conf what is log_min_messages set to?

See here:

https://www.postgresql.org/docs/11/runtime-config-logging.html#RUNTIME-CONFIG-LOGGING-WHEN

Table 19.2. Message Severity Levels

for more information on what the levels represent.

Do you have replication set up with this server?

> 
> 2021-05-08 10:26:20.783 IST [7360] LOG:  database system was 
> interrupted; last known up at 2021-05-07 18:46:00 IST
> 2021-05-08 10:28:36.159 IST [7048] FATAL:  the database system is 
> starting up

> Happiness Always
> BKR Sivaprakash
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com

On 5/8/21 10:53 AM, Adrian Klaver wrote:
> On 5/7/21 10:14 PM, sivapostgres@yahoo.com wrote:
>> Hello,
>>
>> PG 11.8 in Windows 10 and currently PG 11.11
>>
>> Yesterday [07th May] morning when we switched on the computer and 
>> subsequently PGAdmin, we got the message following message
>> FATAL: the database system is starting up
>>
>> I uninstalled PG and installed [v 11.11] PG with the same data 
>> directory.  Fortunately it worked even when we switched off /on the 
>> computer for lunch.   NO issues yesterday.
>
> First why switch the computer off for lunch?

If it's a desktop and he's a developer, then that's reasonable.

>
> Second did you stop the Postgres server before shutting down the machine?

Is Windows Postgresql a service?  If so then Windows "should" shut it down 
cleanly when you cleanly power off the machine.

-- 
Angular momentum makes the world go 'round.

On 5/8/21 9:23 AM, Ron wrote:
> On 5/8/21 10:53 AM, Adrian Klaver wrote:
>> On 5/7/21 10:14 PM, sivapostgres@yahoo.com wrote:
>>> Hello,
>>>
>>> PG 11.8 in Windows 10 and currently PG 11.11
>>>
>>> Yesterday [07th May] morning when we switched on the computer and 
>>> subsequently PGAdmin, we got the message following message
>>> FATAL: the database system is starting up
>>>
>>> I uninstalled PG and installed [v 11.11] PG with the same data 
>>> directory.  Fortunately it worked even when we switched off /on the 
>>> computer for lunch.   NO issues yesterday.
>>
>> First why switch the computer off for lunch?
> 
> If it's a desktop and he's a developer, then that's reasonable.
> 
>>
>> Second did you stop the Postgres server before shutting down the machine?
> 
> Is Windows Postgresql a service?  If so then Windows "should" shut it 
> down cleanly when you cleanly power off the machine.
> 

The log would indicate otherwise:

2021-05-08 10:26:20.783 IST [7360] LOG:  database system was 
interrupted; last known up at 2021-05-07 18:46:00 IST

So something is not working as it should.


-- 
Adrian Klaver
adrian.klaver@aklaver.com

Adrian Klaver <adrian.klaver@aklaver.com> writes:
> On 5/8/21 9:23 AM, Ron wrote:
>> Is Windows Postgresql a service?  If so then Windows "should" shut it 
>> down cleanly when you cleanly power off the machine.

> The log would indicate otherwise:
>
>>> 2021-05-08 10:26:20.783 IST [7360] LOG:  database system was 
>>> interrupted; last known up at 2021-05-07 18:46:00 IST
>
> So something is not working as it should.

Yeah, that's bad news.  In theory, as long as you didn't set
fsync = off, Postgres should be able to recover from an unclean
shutdown.  In practice, that requires all the levels of the
hardware and software stack to pay strict attention to write
ordering requirements.  It is, um, pretty common for inexpensive
Windows gear to not be very careful about that.  I'd say this
particular machine has clearly failed the plug-pull test [1].

If the OP is in the habit of just hitting the power switch
at lunchtime, I'd say he's got to stop doing that.  Telling
Windows to shut down will add a few seconds, but greatly
reduce the risk of problems (and not only for Postgres).
If he *did* tell Windows to shut down, then there's something
else that needs adjustment.

            regards, tom lane

[1] https://wiki.postgresql.org/wiki/Reliable_Writes

1.  First why switch the computer off for lunch?  

        It's a development machine and I'm a developer.   We used to shut down every computer for lunch.  We shut down the windows and not just hit the power switch.   We advice and follow every users and client to shut down the windows properly and we follow it.

2.  In postgresql.conf what is log_min_messages set to?

        Warning

3.  Do you have replication set up with this server?

        No

4.   Is Windows Postgresql a service?  If so then Windows "should" shut it down cleanly when you cleanly power off the 

        machine.

        Yes, Postgresql is a service and windows is shut down properly.    We do shut down computers during lunch and when closing office, regularly and properly for the past 6 months [ since PG was installed ] without any issue.   This is the first time that we face this issue.  

Need to find a solution that will be helpful if that happens in a production machine. 

On 5/8/21 7:32 PM, sivapostgres@yahoo.com wrote:
> Yesterday's log file.   Till we shut down the windows the message was:
> 2021-05-08 19:03:32.151 IST [10376] FATAL:  the database system is 
> starting up
> 2021-05-08 19:03:42.210 IST [7568] FATAL:  the database system is 
> starting up


Comments in line below.

> 
> 
> Today morning log file, I tried to start the service [ after setting the 
> startup type to Manual ] twice
> ***********************************
> 2021-05-09 07:43:02.122 IST [16776] LOG:  test message did not get 
> through on socket for statistics collector

Something is blocking the socket.
Do you have anti-virus software on this machine?

> 2021-05-09 07:43:02.122 IST [16776] LOG:  trying another address for the 
> statistics collector
> 2021-05-09 07:43:02.624 IST [16776] LOG:  test message did not get 
> through on socket for statistics collector
> 2021-05-09 07:43:02.624 IST [16776] LOG:  disabling statistics collector 
> for lack of working socket
> 2021-05-09 07:43:02.624 IST [16776] WARNING:  autovacuum not started 
> because of misconfiguration
> 2021-05-09 07:43:02.624 IST [16776] HINT:  Enable the "track_counts" option.

You should take care of this by following the HINT.

> 2021-05-09 07:43:02.685 IST [17144] LOG:  database system was 
> interrupted; last known up at 2021-05-07 18:46:00 IST
> 2021-05-09 07:43:04.489 IST [17196] FATAL:  the database system is 
> starting up

...

> 2021-05-09 07:45:14.796 IST [17144] LOG:  database system was not 
> properly shut down; automatic recovery in progress
> 2021-05-09 07:45:14.864 IST [17144] LOG:  redo starts at 2/88985C80
> 2021-05-09 07:45:14.866 IST [17144] LOG:  invalid record length at 
> 2/889872B8: wanted 24, got 0
> 2021-05-09 07:45:14.866 IST [17144] LOG:  redo done at 2/88987280
> 2021-05-09 07:45:14.866 IST [17144] LOG:  last completed transaction was 
> at log time 2021-05-07 18:48:44.227574+05:30
> 2021-05-09 07:45:15.046 IST [16776] LOG:  database system is ready to 
> accept connections
> 2021-05-09 07:50:17.295 IST [17204] ERROR:  canceling statement due to 
> user request

So did you or someone else do the above and the below manually or was 
this coming from the system?

> 2021-05-09 07:50:17.300 IST [16776] LOG:  received fast shutdown request
> 2021-05-09 07:50:17.322 IST [4408] LOG:  could not receive data from 
> client: An existing connection was forcibly closed by the remote host.

Are you connecting to database from outside the machine and if so is 
that from a local network or a remote one?
> 
> 2021-05-09 07:50:17.412 IST [16776] LOG:  aborting any active transactions
> 2021-05-09 07:50:17.419 IST [16776] LOG:  background worker "logical 
> replication launcher" (PID 17204) exited with exit code 1
> 2021-05-09 07:50:17.548 IST [11032] LOG:  shutting down
> 2021-05-09 07:50:17.607 IST [16776] LOG:  database system is shut down
> **********************************************

See more below.

> 
> Log file after a re-start
> ***************************************
> 2021-05-09 07:52:40.341 IST [13220] LOG:  test message did not get 
> through on socket for statistics collector
> 2021-05-09 07:52:40.342 IST [13220] LOG:  trying another address for the 
> statistics collector
> 2021-05-09 07:52:40.844 IST [13220] LOG:  test message did not get 
> through on socket for statistics collector
> 2021-05-09 07:52:40.844 IST [13220] LOG:  disabling statistics collector 
> for lack of working socket
> 2021-05-09 07:52:40.845 IST [13220] WARNING:  autovacuum not started 
> because of misconfiguration
> 2021-05-09 07:52:40.845 IST [13220] HINT:  Enable the "track_counts" option.
> 2021-05-09 07:52:40.904 IST [13860] LOG:  database system was shut down 
> at 2021-05-09 07:50:17 IST
> 2021-05-09 07:52:41.122 IST [13220] LOG:  database system is ready to 
> accept connections
> 2021-05-09 07:55:23.628 IST [11188] LOG:  using stale statistics instead 
> of current ones because stats collector is not responding
> *****************************************
> 
> Not sure what happened, it's working now.  Any idea of what happened and 
> what should we do to prevent re-occurance ?

It's up but not really working. Both the statistics collector and the 
autovacuum processes are down. They are both important for the operation 
of the database.

> 
> Happiness Always
> BKR Sivaprakash
> 



-- 
Adrian Klaver
adrian.klaver@aklaver.com

On Sat, 2021-05-08 at 05:14 +0000, sivapostgres@yahoo.com wrote:
> Yesterday [07th May] morning when we switched on the computer and subsequently PGAdmin, we got the message following
message
> FATAL: the database system is starting up

You will have to wait until startup is completed.

Either you didn't shut down PostgreSQL cleanly, or some server process
crashed.  The log should tell you which of the two happened.

Did you set "checkpoint_timeout" to a high value?  That will make the
startup process potentially take longer to recover.

Yours,
Laurenz Albe
-- 
Cybertec | https://www.cybertec-postgresql.com