On Sat, Jun 1, 2019 at 5:30 PM Tom K <tomk...@gmail.com> wrote: > > > On Sat, Jun 1, 2019 at 4:52 PM Adrian Klaver <adrian.kla...@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. > > > Spoke too soon. There's no tables when it's started without the recovery.conf file.
> > >> >> >> -- >> Adrian Klaver >> adrian.kla...@aklaver.com >> >
