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

On Sat, Jun 1, 2019 at 5:30 PM Tom K <tomkcpr(at)gmail(dot)com> wrote:

>
>
> On Sat, Jun 1, 2019 at 4:52 PM Adrian Klaver <adrian(dot)klaver(at)aklaver(dot)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(at)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.
>
>
>
Spoke too soon. There's no tables when it's started without the
recovery.conf file.

>
>
>>
>>
>> --
>> Adrian Klaver
>> adrian(dot)klaver(at)aklaver(dot)com
>>
>