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. > > > -- > Adrian Klaver > adrian.kla...@aklaver.com >
