Home > mailing lists

Re: Recovery_target_time misinterpreted? - Mailing list pgsql-general

From	Klaus Ita
Subject	Re: Recovery_target_time misinterpreted?
Date	August 2, 2013 12:29:56
Msg-id	CAK9oVJy+vHNHg2=Nu5sLs6grenx9W8Ld1rPKJrBekXYM3cH=bQ@mail.gmail.com Whole thread Raw
In response to	Re: Recovery_target_time misinterpreted? (Albe Laurenz <laurenz.albe@wien.gv.at>)
List	pgsql-general

Tree view

No, it's super frustrating. While I do the recovery, it says it reaches a consistent recovery state, and i just cannot find a way how to convince pg to stop at that state:

2013-08-02 09:23:25 GMT DEBUG: postgres: PostmasterMain: initial environment dump:
2013-08-02 09:23:25 GMT DEBUG: -----------------------------------------
2013-08-02 09:23:25 GMT DEBUG:          PG_GRANDPARENT_PID=9077
2013-08-02 09:23:25 GMT DEBUG:          PGLOCALEDIR=/usr/share/locale
2013-08-02 09:23:25 GMT DEBUG:          PGSYSCONFDIR=/etc/postgresql-common
2013-08-02 09:23:25 GMT DEBUG:          LANG=en_US.utf8
2013-08-02 09:23:25 GMT DEBUG:          PWD=/var/lib/postgresql
2013-08-02 09:23:25 GMT DEBUG:          PGDATA=/var/lib/postgresql/9.1/main
2013-08-02 09:23:25 GMT DEBUG:          LC_COLLATE=en_US.utf8
2013-08-02 09:23:25 GMT DEBUG:          LC_CTYPE=en_US.utf8
2013-08-02 09:23:25 GMT DEBUG:          LC_MESSAGES=en_US.utf8
2013-08-02 09:23:25 GMT DEBUG:          LC_MONETARY=C
2013-08-02 09:23:25 GMT DEBUG:          LC_NUMERIC=C
2013-08-02 09:23:25 GMT DEBUG:          LC_TIME=C
2013-08-02 09:23:25 GMT DEBUG: -----------------------------------------

2013-08-02 11:23:26 CEST DEBUG: invoking IpcMemoryCreate(size=32399360)
2013-08-02 11:23:26 CEST DEBUG: removing file "pg_notify/0000"
2013-08-02 11:23:26 CEST DEBUG: max_safe_fds = 982, usable_fds = 1000, already_open = 8
2013-08-02 11:23:26 CEST LOG: database system was interrupted while in recovery at log time 2013-07-29 11:45:24 CEST
2013-08-02 11:23:26 CEST HINT: If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.
2013-08-02 11:23:26 CEST DEBUG: restore_command = 'cp /home/validad-pg-backups/pgmaster/wal_files/%f.gz /tmp/%f.gz && gunzip /tmp/%f.gz && mv /tmp/%f %p'
2013-08-02 11:23:26 CEST DEBUG: trigger_file = '/var/lib/postgresql/9.1/main/stop_replication_trigger'
2013-08-02 11:23:26 CEST LOG: starting archive recovery
2013-08-02 11:23:26 CEST DEBUG: executing restore command "cp /home/validad-pg-backups/pgmaster/wal_files/000000010000027A0000002C.gz /tmp/000000010000027A0000002C.gz && gunzip /tmp/000000010000027A0000002C.gz && mv /tmp/000000010000027A0000002C pg_xlog/RECOVERYXLOG"
2013-08-02 11:23:26 CEST DEBUG: forked new backend, pid=9090 socket=9
2013-08-02 11:23:26 CEST LOG: incomplete startup packet
2013-08-02 11:23:26 CEST DEBUG: shmem_exit(0): 0 callbacks to make
2013-08-02 11:23:26 CEST DEBUG: proc_exit(0): 1 callbacks to make
2013-08-02 11:23:26 CEST DEBUG: exit(0)
2013-08-02 11:23:26 CEST DEBUG: shmem_exit(-1): 0 callbacks to make
2013-08-02 11:23:26 CEST DEBUG: proc_exit(-1): 0 callbacks to make
2013-08-02 11:23:26 CEST DEBUG: reaping dead processes
2013-08-02 11:23:26 CEST DEBUG: server process (PID 9090) exited with exit code 0
2013-08-02 11:23:26 CEST LOG: restored log file "000000010000027A0000002C" from archive
2013-08-02 11:23:26 CEST DEBUG: got WAL segment from archive
2013-08-02 11:23:26 CEST DEBUG: checkpoint record is at 27A/2CB77750
2013-08-02 11:23:26 CEST DEBUG: redo record is at 27A/2CB77750; shutdown TRUE
2013-08-02 11:23:26 CEST DEBUG: next transaction ID: 0/381985248; next OID: 1201662
2013-08-02 11:23:26 CEST DEBUG: next MultiXactId: 130079; next MultiXactOffset: 272843
2013-08-02 11:23:26 CEST DEBUG: oldest unfrozen transaction ID: 197713560, in database 331065
2013-08-02 11:23:26 CEST DEBUG: transaction ID wrap limit is 2345197207, limited by database with OID 331065
2013-08-02 11:23:26 CEST DEBUG: resetting unlogged relations: cleanup 1 init 0
2013-08-02 11:23:26 CEST LOG: redo starts at 27A/2CB777A8
2013-08-02 11:23:26 CEST DEBUG: executing restore command "cp /home/validad-pg-backups/pgmaster/wal_files/000000010000027A0000002D.gz /tmp/000000010000027A0000002D.gz && gunzip /tmp/000000010000027A0000002D.gz && mv /tmp/000000010000027A0000002D pg_xlog/RECOVERYXLOG"
2013-08-02 11:23:27 CEST DEBUG: forked new backend, pid=9098 socket=9
2013-08-02 11:23:27 CEST FATAL: the database system is starting up
2013-08-02 11:23:27 CEST DEBUG: shmem_exit(1): 0 callbacks to make
2013-08-02 11:23:27 CEST DEBUG: proc_exit(1): 1 callbacks to make
2013-08-02 11:23:27 CEST DEBUG: exit(1)
2013-08-02 11:23:27 CEST DEBUG: shmem_exit(-1): 0 callbacks to make
2013-08-02 11:23:27 CEST DEBUG: proc_exit(-1): 0 callbacks to make
2013-08-02 11:23:27 CEST DEBUG: reaping dead processes
2013-08-02 11:23:27 CEST DEBUG: server process (PID 9098) exited with exit code 1
2013-08-02 11:23:27 CEST LOG: restored log file "000000010000027A0000002D" from archive
2013-08-02 11:23:27 CEST DEBUG: got WAL segment from archive
2013-08-02 11:23:27 CEST DEBUG: executing restore command "cp /home/validad-pg-backups/pgmaster/wal_files/000000010000027A0000002E.gz /tmp/000000010000027A0000002E.gz && gunzip /tmp/000000010000027A0000002E.gz && mv /tmp/000000010000027A0000002E pg_xlog/RECOVERYXLOG"
2013-08-02 11:23:27 CEST DEBUG: forked new backend, pid=9105 socket=9
2013-08-02 11:23:27 CEST FATAL: the database system is starting up
2013-08-02 11:23:27 CEST DEBUG: shmem_exit(1): 0 callbacks to make
2013-08-02 11:23:27 CEST DEBUG: proc_exit(1): 1 callbacks to make
2013-08-02 11:23:27 CEST DEBUG: exit(1)
2013-08-02 11:23:27 CEST DEBUG: shmem_exit(-1): 0 callbacks to make
2013-08-02 11:23:27 CEST DEBUG: proc_exit(-1): 0 callbacks to make
2013-08-02 11:23:27 CEST DEBUG: reaping dead processes
2013-08-02 11:23:27 CEST DEBUG: server process (PID 9105) exited with exit code 1
2013-08-02 11:23:28 CEST LOG: restored log file "000000010000027A0000002E" from archive
2013-08-02 11:23:28 CEST DEBUG: got WAL segment from archive
2013-08-02 11:23:28 CEST LOG: consistent recovery state reached at 27A/2E3F42E8
2013-08-02 11:23:28 CEST PANIC: _bt_restore_page: cannot add item to page
2013-08-02 11:23:28 CEST CONTEXT: xlog redo split_r: rel 1663/16405/797541 left 4743, right 18008, next 9681, level 0, firstright 194
2013-08-02 11:23:28 CEST DEBUG: reaping dead processes
2013-08-02 11:23:28 CEST LOG: startup process (PID 9086) was terminated by signal 6: Aborted
2013-08-02 11:23:28 CEST LOG: terminating any other active server processes
2013-08-02 11:23:28 CEST DEBUG: sending SIGQUIT to process 9092
2013-08-02 11:23:28 CEST DEBUG: shmem_exit(-1): 0 callbacks to make
2013-08-02 11:23:28 CEST DEBUG: proc_exit(-1): 0 callbacks to make
2013-08-02 11:23:28 CEST DEBUG: reaping dead processes
2013-08-02 11:23:28 CEST DEBUG: shmem_exit(1): 3 callbacks to make
2013-08-02 11:23:28 CEST DEBUG: proc_exit(1): 3 callbacks to make
2013-08-02 11:23:28 CEST DEBUG: exit(1)
2013-08-02 11:23:28 CEST DEBUG: shmem_exit(-1): 0 callbacks to make
2013-08-02 11:23:28 CEST DEBUG: proc_exit(-1): 0 callbacks to make

now with debug5 setting.

I have like 3 different wal_files, but they were all generated by pg in this way. The backup script actually always takes the original and uses this as source to copy it to 3 different locations. But the sha1sum of the files is always the same :(

I don't so much mind that, we have recovered some backups and replayed from another standby system, but i need to understand why i cannot reactivate this cluster on this state:

'2013-08-02 11:23:28 CEST LOG: consistent recovery state reached at 27A/2E3F42E8'

I am posting to bugs, too, as i start thinking this is one.

lg,k

pgsql-general by date:

From: Vik Fearing
Date: 02 August 2013, 11:51:11
Subject: Re: Add a NOT NULL column with default only during add

From: "Stephen Brearley"
Date: 02 August 2013, 12:41:10
Subject: Postgres 9.2.4 for Windows (Vista) Dell Vostro 400, re-installation failure PLEASE CAN SOMEONE HELP!! (nearly fixed)

Re: Recovery_target_time misinterpreted? - Mailing list pgsql-general

Previous

Next