macOS homebrew: database system was not properly shut down; automatic recovery in progress

Question

I'm noticing some errors in my logs when restarting PG 9.6. I also tried upgrading to 10.1, and the problem continues. This is on macOS via a homebrew installation.

First, I shut down with "brew services stop postgres":

2017-12-16 13:56:09.778 EST [34295] LOG: received smart shutdown request 2017-12-16 13:56:09.779 EST [34295] LOG: worker process: logical replication launcher (PID 34316) exited with exit code 1 2017-12-16 13:56:14.787 EST [34317] FATAL: terminating connection due to unexpected postmaster exit

Then I restart it with "brew services start postgres":

2017-12-16 13:56:43.152 EST [5604] LOG: listening on IPv6 address "::1", port 5432 2017-12-16 13:56:43.152 EST [5604] LOG: listening on IPv4 address "127.0.0.1", port 5432 2017-12-16 13:56:43.153 EST [5604] LOG: listening on Unix socket "/tmp/.s.PGSQL.5432" 2017-12-16 13:56:43.215 EST [5619] LOG: database system was interrupted; last known up at 2017-12-16 10:43:27 EST 2017-12-16 13:56:43.407 EST [5619] LOG: database system was not properly shut down; automatic recovery in progress 2017-12-16 13:56:43.409 EST [5619] LOG: redo starts at 0/5B51E580 2017-12-16 13:56:43.409 EST [5619] LOG: invalid record length at 0/5B51E660: wanted 24, got 0 2017-12-16 13:56:43.409 EST [5619] LOG: redo done at 0/5B51E628 2017-12-16 13:56:43.435 EST [5604] LOG: database system is ready to accept connections

This is with a default postgres.conf. I believe the brew services script ends up running:

/usr/local/opt/postgresql/bin/postgres -D /usr/local/var/postgres stop

I also tried using pg_ctl -D /usr/local/var/postgres stop, but that just gives:

waiting for server to shut down......................................... failed pg_ctl: server does not shut down

What is the proper way to stop and then re-start postgres?

Answer 1

It looks like "brew services stop postgres" is sending a signal to shutdown, and then following up 5 seconds later with a hard-kill. That seems like a rather hostile thing for it to do, but I have zero experience with brew. Maybe that is configurable?

But the other question is, why does it take more than 5 seconds to shut down? Unless you have a lot of dirty data in memory which needs to be written out, shutting down should be pretty quick. When you tried to shutdown with the pg_ctl command, what ended up in the server log file after that attempt? When pg_ctl reports that the shutdown failed, that just means that pg_ctl got sick of waiting for it, it doesn't mean the shutdown permanently failed (i.e. it doesn't shoot the postmaster in the head the way brew seems to). So you can keep checking the log file even after pg_ctl reports a failure. You can use the -t option to make pg_ctl more patient.

Also, you should turn log_checkpoints=on, and then try the pg_ctl stop -t 3600 ... again and look in the server log files.