9.1 doesn't start when died mid-backup

Поиск
Список
Период
Сортировка
От hubert depesz lubaczewski
Тема 9.1 doesn't start when died mid-backup
Дата
Msg-id 20110413074924.GA11318@depesz.com
обсуждение исходный текст
Ответы Re: 9.1 doesn't start when died mid-backup  (Heikki Linnakangas <heikki.linnakangas@enterprisedb.com>)
Список pgsql-bugs
hi
got new 9.1, straight from git.
compiled, installed.
did initdb, and then set config values using this script:
perl -pi -e '
  s/\A \s* (?: [#] \s* )? listen_addresses \s* = \s*.*/listen_addresses = \047*\047/x;
  s/\A \s* (?: [#] \s* )? log_destination \s* = \s*.*/log_destination = \047stderr\047/x;
  s/\A \s* (?: [#] \s* )? logging_collector \s* = \s*.*/logging_collector = on/x;
  s/\A \s* (?: [#] \s* )? log_min_duration_statement \s* = \s*.*/log_min_duration_statement = 0/x;
  s/\A \s* (?: [#] \s* )? log_line_prefix \s* = \s*.*/log_line_prefix = \047\%m \%u\@\%d \%p \%r \047/x;
  s/\A \s* (?: [#] \s* )? log_temp_files \s* = \s*.*/log_temp_files = 0/x;
  s/\A \s* (?: [#] \s* )? (log_checkpoints|log_connections|log_disconnections|log_lock_waits) \s* = \s*.*/$1 = on/x;
  s/\A \s* (?: [#] \s* )? wal_level \s* = \s*.*/wal_level = hot_standby/x;
  s/\A \s* (?: [#] \s* )? archive_mode \s* = \s*.*/archive_mode = on/x;
  s/\A \s* (?: [#] \s* )? archive_command \s* = \s*.*/archive_command = \047\/bin\/true\047/x;
' data/postgresql.conf

afterwards I did start pg.

then, i connected with psql, and issued:
$ select pg_start_backup('xx');
 pg_start_backup
-----------------
 0/2000020
(1 row)

$ create database pgdba;
CREATE DATABASE

$ create user postgres with superuser;
CREATE ROLE

$ create user depesz with superuser;
CREATE ROLE

$ create database depesz with owner depesz;
CREATE DATABASE

Afterwards, I exited psql, and simulated power-failure, with:

=$ killall -9 postgres; killall -9 postmaster
postmaster: no process found

All pg processes were killed.

When I then tried to start Pg, I got:
=$ pg_ctl start
pg_ctl: another server might be running; trying to start server anyway
server starting

but it didn't start.

log looks like this:
=$ cat postgresql-2011-04-13_093859.log
2011-04-13 09:38:59.807 CEST @ 3446  LOG:  database system was interrupted; last known up at 2011-04-13 09:38:43 CEST
2011-04-13 09:38:59.807 CEST @ 3446  LOG:  database system was not properly shut down; automatic recovery in progress
2011-04-13 09:38:59.852 CEST @ 3446  LOG:  redo starts at 0/2000020
2011-04-13 09:39:00.304 CEST @ 3446  LOG:  record with zero length at 0/20018E8
2011-04-13 09:39:00.304 CEST @ 3446  LOG:  redo done at 0/2001898
2011-04-13 09:39:00.304 CEST @ 3446  LOG:  last completed transaction was at log time 2011-04-13 09:38:43.563356+02
2011-04-13 09:39:00.304 CEST @ 3446  FATAL:  WAL ends before end of online backup
2011-04-13 09:39:00.304 CEST @ 3446  HINT:  Online backup started with pg_start_backup() must be ended with
pg_stop_backup(),and all WAL up to that point must be available at recovery. 
2011-04-13 09:39:00.304 CEST @ 3444  LOG:  startup process (PID 3446) exited with exit code 1
2011-04-13 09:39:00.304 CEST @ 3444  LOG:  aborting startup due to startup process failure

interestingl7y backup_label got renamed to backup_label.old, and
contains:
START WAL LOCATION: 0/2000020 (file 000000010000000000000002)
CHECKPOINT LOCATION: 0/2000058
START TIME: 2011-04-13 09:38:19 CEST
LABEL: xx

Given the file was renamed, I retried:

=$ pg_ctl start
server starting

but again - it didn't work.

Log looks like this:

2011-04-13 09:44:06.844 CEST @ 3783  LOG:  database system was interrupted while in recovery at 2011-04-13 09:38:59
CEST
2011-04-13 09:44:06.844 CEST @ 3783  HINT:  This probably means that some data is corrupted and you will have to use
thelast backup for recovery. 
2011-04-13 09:44:06.845 CEST @ 3783  LOG:  database system was not properly shut down; automatic recovery in progress
2011-04-13 09:44:06.877 CEST @ 3783  LOG:  redo starts at 0/2000020
2011-04-13 09:44:07.316 CEST @ 3783  LOG:  record with zero length at 0/20018E8
2011-04-13 09:44:07.316 CEST @ 3783  LOG:  redo done at 0/2001898
2011-04-13 09:44:07.316 CEST @ 3783  LOG:  last completed transaction was at log time 2011-04-13 09:38:43.563356+02
2011-04-13 09:44:07.316 CEST @ 3783  FATAL:  WAL ends before end of online backup
2011-04-13 09:44:07.316 CEST @ 3783  HINT:  Online backup started with pg_start_backup() must be ended with
pg_stop_backup(),and all WAL up to that point must be available at recovery. 
2011-04-13 09:44:07.316 CEST @ 3776  LOG:  startup process (PID 3783) exited with exit code 1
2011-04-13 09:44:07.316 CEST @ 3776  LOG:  aborting startup due to startup process failure


So, it looks to me that by killing postgres mid-backup I made it end up in some state that doesn't let it start again.

I *think* it might be related to this:
http://archives.postgresql.org/pgsql-hackers/2011-03/msg01490.php and more
specifically, with this:
http://archives.postgresql.org/pgsql-hackers/2011-03/msg01627.php

Best regards,

depesz

--
The best thing about modern society is how easy it is to avoid contact with it.
                                                             http://depesz.com/

В списке pgsql-bugs по дате отправления:

Предыдущее
От: "John Dickson"
Дата:
Сообщение: BUG #5975: Incorrect result from mod function with cast
Следующее
От: "Donald Fraser"
Дата:
Сообщение: Re: [JDBC] [ADMIN] Missing documentation for error code: 80S01