Re: psql: FATAL: the database system is starting up

On Sat, Jun 1, 2019 at 4:52 PM Adrian Klaver <adrian.klaver@aklaver.com> wrote:

On 6/1/19 12:42 PM, Tom K wrote:
>
>

>
> Of note are the characters f2W below.  I see nothing in the postgres
> source code to indicate this is any recognizable postgres message.  A
> part of me suspects that the postgres binaries got corrupted.   Had this
> case occur with glib-common and a reinstall fixed it.  However the
> postgres binaries csum matches a standalone install perfectly so that
> should not be an issue.

It comes from timeline.c:

https://doxygen.postgresql.org/bin_2pg__rewind_2timeline_8c.html

pg_log_error("syntax error in history file: %s", fline);

...

There should be another error message after the above.

Nope.  Here's the full set of lines in the postgres logs when running the above line:

2019-06-01 17:13:03.261 EDT [14909] LOG:  database system was shut down at 2019-05-22 01:55:13 EDT
2019-06-01 17:13:03.261 EDT [14909] DEBUG:  primary_slot_name = 'postgresql2'
2019-06-01 17:13:03.261 EDT [14909] DEBUG:  standby_mode = 'on'
2019-06-01 17:13:03.261 EDT [14909] DEBUG:  recovery_target_timeline = latest
2019-06-01 17:13:03.261 EDT [14909] WARNING:  recovery command file "recovery.conf" specified neither primary_conninfo nor restore_command
2019-06-01 17:13:03.261 EDT [14909] HINT:  The database server will regularly poll the pg_wal subdirectory to check for files placed there.
2019-06-01 17:13:03.263 EDT [14909] LOG:  entering standby mode
2019-06-01 17:13:03.263 EDT [14909] FATAL:  syntax error in history file: f2W
2019-06-01 17:13:03.263 EDT [14909] HINT:  Expected a numeric timeline ID.
2019-06-01 17:13:03.263 EDT [14909] DEBUG:  shmem_exit(1): 1 before_shmem_exit callbacks to make
2019-06-01 17:13:03.263 EDT [14909] DEBUG:  shmem_exit(1): 4 on_shmem_exit callbacks to make
2019-06-01 17:13:03.263 EDT [14909] DEBUG:  proc_exit(1): 2 callbacks to make
2019-06-01 17:13:03.263 EDT [14909] DEBUG:  exit(1)
2019-06-01 17:13:03.264 EDT [14909] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2019-06-01 17:13:03.264 EDT [14909] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2019-06-01 17:13:03.264 EDT [14909] DEBUG:  proc_exit(-1): 0 callbacks to make
2019-06-01 17:13:03.265 EDT [14907] DEBUG:  reaping dead processes
2019-06-01 17:13:03.265 EDT [14907] LOG:  startup process (PID 14909) exited with exit code 1
2019-06-01 17:13:03.265 EDT [14907] LOG:  aborting startup due to startup process failure
2019-06-01 17:13:03.265 EDT [14907] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2019-06-01 17:13:03.266 EDT [14907] DEBUG:  shmem_exit(1): 5 on_shmem_exit callbacks to make
2019-06-01 17:13:03.266 EDT [14907] DEBUG:  cleaning up dynamic shared memory control segment with ID 1669075945
2019-06-01 17:13:03.268 EDT [14907] DEBUG:  proc_exit(1): 2 callbacks to make
2019-06-01 17:13:03.268 EDT [14907] LOG:  database system is shut down
2019-06-01 17:13:03.268 EDT [14907] DEBUG:  exit(1)
2019-06-01 17:13:03.268 EDT [14907] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2019-06-01 17:13:03.268 EDT [14907] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2019-06-01 17:13:03.268 EDT [14907] DEBUG:  proc_exit(-1): 0 callbacks to make
2019-06-01 17:13:03.270 EDT [14908] DEBUG:  logger shutting down
2019-06-01 17:13:03.270 EDT [14908] DEBUG:  shmem_exit(0): 0 before_shmem_exit callbacks to make
2019-06-01 17:13:03.270 EDT [14908] DEBUG:  shmem_exit(0): 0 on_shmem_exit callbacks to make
2019-06-01 17:13:03.270 EDT [14908] DEBUG:  proc_exit(0): 0 callbacks to make
2019-06-01 17:13:03.270 EDT [14908] DEBUG:  exit(0)
2019-06-01 17:13:03.270 EDT [14908] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2019-06-01 17:13:03.270 EDT [14908] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2019-06-01 17:13:03.270 EDT [14908] DEBUG:  proc_exit(-1): 0 callbacks to make
^C
-bash-4.2$

What's interesting is that f2W isn't a string you'd expect to be printed as part of the code logic   ( I mean, what is f2W? ).  

postgresql10-server-10.8-1PGDG.rhel7.x86_64
postgresql10-libs-10.8-1PGDG.rhel7.x86_64
postgresql10-contrib-10.8-1PGDG.rhel7.x86_64
postgresql10-10.8-1PGDG.rhel7.x86_64

Without the recovery.conf file it actually started up.  Going to try to get a dump then continue to try and recover in place.

2019-06-01 17:17:29.777 EDT [14936] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2019-06-01 17:17:29.777 EDT [14936] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
2019-06-01 17:17:29.778 EDT [14937] DEBUG:  received inquiry for database 0
2019-06-01 17:17:29.778 EDT [14937] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2019-06-01 17:17:29.779 EDT [14937] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2019-06-01 17:17:29.790 EDT [15013] DEBUG:  InitPostgres
2019-06-01 17:17:29.790 EDT [15013] DEBUG:  my backend ID is 3
2019-06-01 17:17:29.791 EDT [15013] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2019-06-01 17:17:29.801 EDT [15013] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
2019-06-01 17:17:29.801 EDT [15013] DEBUG:  autovacuum: processing database "postgres"
2019-06-01 17:17:29.801 EDT [14937] DEBUG:  received inquiry for database 13806
2019-06-01 17:17:29.801 EDT [14937] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2019-06-01 17:17:29.801 EDT [14937] DEBUG:  writing stats file "pg_stat_tmp/db_13806.stat"
2019-06-01 17:17:29.801 EDT [14937] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2019-06-01 17:17:29.811 EDT [15013] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2019-06-01 17:17:29.811 EDT [15013] DEBUG:  pg_statistic: vac: 0 (threshold 129), anl: 0 (threshold 89)
2019-06-01 17:17:29.811 EDT [15013] DEBUG:  pg_type: vac: 0 (threshold 125), anl: 0 (threshold 88)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_authid: vac: 0 (threshold 51), anl: 0 (threshold 51)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_attribute: vac: 0 (threshold 566), anl: 0 (threshold 308)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_proc: vac: 0 (threshold 629), anl: 0 (threshold 339)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_class: vac: 0 (threshold 118), anl: 0 (threshold 84)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_index: vac: 0 (threshold 77), anl: 0 (threshold 63)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_operator: vac: 0 (threshold 207), anl: 0 (threshold 129)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_opclass: vac: 0 (threshold 77), anl: 0 (threshold 63)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 51)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_amop: vac: 0 (threshold 192), anl: 0 (threshold 121)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_amproc: vac: 0 (threshold 132), anl: 0 (threshold 91)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_aggregate: vac: 0 (threshold 78), anl: 0 (threshold 64)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_rewrite: vac: 0 (threshold 74), anl: 0 (threshold 62)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_cast: vac: 0 (threshold 94), anl: 0 (threshold 72)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_namespace: vac: 0 (threshold 51), anl: 0 (threshold 51)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_tablespace: vac: 0 (threshold 50), anl: 0 (threshold 50)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  pg_toast_2618: vac: 0 (threshold 95), anl: 0 (threshold 73)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  shmem_exit(0): 7 on_shmem_exit callbacks to make
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  proc_exit(0): 2 callbacks to make
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  exit(0)
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2019-06-01 17:17:29.812 EDT [15013] DEBUG:  proc_exit(-1): 0 callbacks to make
2019-06-01 17:17:29.814 EDT [14930] DEBUG:  reaping dead processes
2019-06-01 17:17:29.814 EDT [14930] DEBUG:  server process (PID 15013) exited with exit code 0
2019-06-01 17:18:29.785 EDT [14936] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2019-06-01 17:18:29.785 EDT [14936] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
2019-06-01 17:18:29.785 EDT [14937] DEBUG:  received inquiry for database 0
2019-06-01 17:18:29.785 EDT [14937] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2019-06-01 17:18:29.786 EDT [14937] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2019-06-01 17:18:29.797 EDT [15020] DEBUG:  InitPostgres
2019-06-01 17:18:29.797 EDT [15020] DEBUG:  my backend ID is 3
2019-06-01 17:18:29.798 EDT [15020] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2019-06-01 17:18:29.800 EDT [15020] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
2019-06-01 17:18:29.800 EDT [15020] DEBUG:  autovacuum: processing database "postgres"
2019-06-01 17:18:29.800 EDT [14937] DEBUG:  received inquiry for database 13806
2019-06-01 17:18:29.800 EDT [14937] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2019-06-01 17:18:29.800 EDT [14937] DEBUG:  writing stats file "pg_stat_tmp/db_13806.stat"
2019-06-01 17:18:29.801 EDT [14937] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  pg_statistic: vac: 0 (threshold 129), anl: 0 (threshold 89)
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  pg_type: vac: 0 (threshold 125), anl: 0 (threshold 88)
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  pg_authid: vac: 0 (threshold 51), anl: 0 (threshold 51)
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  pg_attribute: vac: 0 (threshold 566), anl: 0 (threshold 308)
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  pg_proc: vac: 0 (threshold 629), anl: 0 (threshold 339)
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  pg_class: vac: 0 (threshold 118), anl: 0 (threshold 84)
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  pg_index: vac: 0 (threshold 77), anl: 0 (threshold 63)
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  pg_operator: vac: 0 (threshold 207), anl: 0 (threshold 129)
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  pg_opclass: vac: 0 (threshold 77), anl: 0 (threshold 63)
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 51)
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  pg_amop: vac: 0 (threshold 192), anl: 0 (threshold 121)
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  pg_amproc: vac: 0 (threshold 132), anl: 0 (threshold 91)
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  pg_aggregate: vac: 0 (threshold 78), anl: 0 (threshold 64)
2019-06-01 17:18:29.811 EDT [15020] DEBUG:  pg_rewrite: vac: 0 (threshold 74), anl: 0 (threshold 62)
2019-06-01 17:18:29.812 EDT [15020] DEBUG:  pg_cast: vac: 0 (threshold 94), anl: 0 (threshold 72)
2019-06-01 17:18:29.812 EDT [15020] DEBUG:  pg_namespace: vac: 0 (threshold 51), anl: 0 (threshold 51)
2019-06-01 17:18:29.812 EDT [15020] DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
2019-06-01 17:18:29.812 EDT [15020] DEBUG:  pg_tablespace: vac: 0 (threshold 50), anl: 0 (threshold 50)
2019-06-01 17:18:29.812 EDT [15020] DEBUG:  pg_toast_2618: vac: 0 (threshold 95), anl: 0 (threshold 73)
2019-06-01 17:18:29.812 EDT [15020] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
2019-06-01 17:18:29.812 EDT [15020] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make
2019-06-01 17:18:29.812 EDT [15020] DEBUG:  shmem_exit(0): 7 on_shmem_exit callbacks to make
2019-06-01 17:18:29.812 EDT [15020] DEBUG:  proc_exit(0): 2 callbacks to make
2019-06-01 17:18:29.812 EDT [15020] DEBUG:  exit(0)
2019-06-01 17:18:29.812 EDT [15020] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2019-06-01 17:18:29.812 EDT [15020] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2019-06-01 17:18:29.812 EDT [15020] DEBUG:  proc_exit(-1): 0 callbacks to make
2019-06-01 17:18:29.814 EDT [14930] DEBUG:  reaping dead processes
2019-06-01 17:18:29.814 EDT [14930] DEBUG:  server process (PID 15020) exited with exit code 0
^C
[root@psql03 log]#

The point of the POC and the LAB is to test these things across failures as well as various configurations.  To that end, I'm just as curious how to recover from these error conditions as I am just getting things to work.  

 

--
Adrian Klaver
adrian.klaver@aklaver.com