Re: Issue in PG start

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 up2021-05-08 19:03:42.210 IST [7568] FATAL:  the database system is starting up

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 collector2021-05-09 07:43:02.122 IST [16776] LOG:  trying another address for the statistics collector2021-05-09 07:43:02.624 IST [16776] LOG:  test message did not get through on socket for statistics collector2021-05-09 07:43:02.624 IST [16776] LOG:  disabling statistics collector for lack of working socket2021-05-09 07:43:02.624 IST [16776] WARNING:  autovacuum not started because of misconfiguration2021-05-09 07:43:02.624 IST [16776] HINT:  Enable the "track_counts" option.2021-05-09 07:43:02.685 IST [17144] LOG:  database system was interrupted; last known up at 2021-05-07 18:46:00 IST2021-05-09 07:43:04.489 IST [17196] FATAL:  the database system is starting up2021-05-09 07:43:14.538 IST [17332] FATAL:  the database system is starting up2021-05-09 07:43:24.577 IST [2716] FATAL:  the database system is starting up2021-05-09 07:43:34.638 IST [12840] FATAL:  the database system is starting up2021-05-09 07:43:44.782 IST [6472] FATAL:  the database system is starting up2021-05-09 07:43:54.852 IST [5288] FATAL:  the database system is starting up2021-05-09 07:44:04.885 IST [17292] FATAL:  the database system is starting up2021-05-09 07:44:14.949 IST [17304] FATAL:  the database system is starting up2021-05-09 07:44:25.021 IST [15816] FATAL:  the database system is starting up2021-05-09 07:44:35.216 IST [15892] FATAL:  the database system is starting up2021-05-09 07:44:45.251 IST [7704] FATAL:  the database system is starting up2021-05-09 07:44:55.432 IST [15644] FATAL:  the database system is starting up2021-05-09 07:45:05.549 IST [3188] FATAL:  the database system is starting up2021-05-09 07:45:14.796 IST [17144] LOG:  database system was not properly shut down; automatic recovery in progress2021-05-09 07:45:14.864 IST [17144] LOG:  redo starts at 2/88985C802021-05-09 07:45:14.866 IST [17144] LOG:  invalid record length at 2/889872B8: wanted 24, got 02021-05-09 07:45:14.866 IST [17144] LOG:  redo done at 2/889872802021-05-09 07:45:14.866 IST [17144] LOG:  last completed transaction was at log time 2021-05-07 18:48:44.227574+05:302021-05-09 07:45:15.046 IST [16776] LOG:  database system is ready to accept connections2021-05-09 07:50:17.295 IST [17204] ERROR:  canceling statement due to user request2021-05-09 07:50:17.300 IST [16776] LOG:  received fast shutdown request2021-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.
2021-05-09 07:50:17.322 IST [11700] LOG:  could not receive data from client: An existing connection was forcibly closed by the remote host.
2021-05-09 07:50:17.322 IST [16744] LOG:  could not receive data from client: An existing connection was forcibly closed by the remote host.
2021-05-09 07:50:17.322 IST [16960] LOG:  could not receive data from client: An existing connection was forcibly closed by the remote host.
2021-05-09 07:50:17.322 IST [14856] LOG:  could not receive data from client: An existing connection was forcibly closed by the remote host.
2021-05-09 07:50:17.412 IST [16776] LOG:  aborting any active transactions2021-05-09 07:50:17.419 IST [16776] LOG:  background worker "logical replication launcher" (PID 17204) exited with exit code 12021-05-09 07:50:17.548 IST [11032] LOG:  shutting down2021-05-09 07:50:17.607 IST [16776] LOG:  database system is shut down**********************************************
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 collector2021-05-09 07:52:40.342 IST [13220] LOG:  trying another address for the statistics collector2021-05-09 07:52:40.844 IST [13220] LOG:  test message did not get through on socket for statistics collector2021-05-09 07:52:40.844 IST [13220] LOG:  disabling statistics collector for lack of working socket2021-05-09 07:52:40.845 IST [13220] WARNING:  autovacuum not started because of misconfiguration2021-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 IST2021-05-09 07:52:41.122 IST [13220] LOG:  database system is ready to accept connections2021-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 ?
Happiness Always
BKR Sivaprakash
On Sunday, 9 May, 2021, 07:49:57 am IST, sivapostgres(at)yahoo(dot)com <sivapostgres(at)yahoo(dot)com> wrote:

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.  
Happiness Always
BKR Sivaprakash

On Saturday, 8 May, 2021, 10:24:03 pm IST, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

Adrian Klaver <adrian(dot)klaver(at)aklaver(dot)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