Обсуждение: BUG #8043: 9.2.4 doesn't open WAL files from archive, only looks in pg_xlog
BUG #8043: 9.2.4 doesn't open WAL files from archive, only looks in pg_xlog
От
bohmer@visionlink.org
Дата:
The following bug has been logged on the website: Bug reference: 8043 Logged by: Jeff Bohmer Email address: bohmer@visionlink.org PostgreSQL version: 9.2.4 Operating system: CentOS 5.9 x86_64 kernel 2.6.18-348.3.1.el5 Description: = Hi pgsql-bugs, PG version: 9.2.4, from yum.postgresql.org OS: CentOS 5.9 x86_64 kernel 2.6.18-348.3.1.el5 Upgrading from 9.2.3 to 9.2.4 has broken archive recovery for me. Probably related to this 9.2.4 change: Ensure we do crash recovery before entering archive recovery, if the database was not stopped cleanly and a recovery.conf file is present (Heikki Linnakangas, Kyotaro Horiguchi, Mitsumasa Kondo) When starting the PostgreSQL 9.2.4 service on a base backup, I get this: 2013-04-05 12:49:04 MDT [10302]: [1-1] user=3D,db=3D LOG: database system = was interrupted; last known up at 2013-04-05 10:02:01 MDT 2013-04-05 12:49:04 MDT [10302]: [2-1] user=3D,db=3D LOG: starting archive recovery 2013-04-05 12:49:04 MDT [10302]: [3-1] user=3D,db=3D LOG: could not open f= ile "pg_xlog/000000010000002F0000002D" (log file 47, segment 45): No such file or directory 2013-04-05 12:49:04 MDT [10302]: [4-1] user=3D,db=3D LOG: invalid primary checkpoint record 2013-04-05 12:49:04 MDT [10302]: [5-1] user=3D,db=3D LOG: could not open f= ile "pg_xlog/000000010000002F0000002C" (log file 47, segment 44): No such file or directory 2013-04-05 12:49:04 MDT [10302]: [6-1] user=3D,db=3D LOG: invalid secondary checkpoint record 2013-04-05 12:49:04 MDT [10302]: [7-1] user=3D,db=3D PANIC: could not loca= te a valid checkpoint record 2013-04-05 12:49:04 MDT [10297]: [2-1] user=3D,db=3D LOG: startup process = (PID 10302) was terminated by signal 6: Aborted 2013-04-05 12:49:04 MDT [10297]: [3-1] user=3D,db=3D LOG: aborting startup= due to startup process failure The WAL file 000000010000002F0000002D does exist in my WAL archive, but not in pg_xlog. I exclude pg_xlog files when taking the base backup, per the instructions from <http://www.postgresql.org/docs/9.2/static/continuous-archiving.html>: You can, however, omit from the backup dump the files within the cluster's pg_xlog/ subdirectory. This slight adjustment is worthwhile because it reduces the risk of mistakes when restoring. I use a custom base backup script to call pg_start/stop_backup() and make the backup with rsync. The restore_command in recovery.conf is never called by PG 9.2.4 during startup. I confirmed this by adding a "touch /tmp/restore_command.`date +%H:%M:%S`" line at the beginning of the shell script I use for my restore_command. No such files are created when starting PG 9.2.4. After downgrading back to 9.2.3, archive recovery works using the very same base backup, recovery.conf file, and restore_command. The log indicates that PG 9.2.3 begins recovery by pulling WAL files from the archive instead of pg_xlog: 2013-04-05 13:01:14 MDT [16981]: [1-1] user=3D,db=3D LOG: database system = was interrupted; last known up at 2013-04-05 10:02:01 MDT 2013-04-05 13:01:14 MDT [16981]: [2-1] user=3D,db=3D LOG: starting archive recovery 2013-04-05 13:01:14 MDT [16981]: [3-1] user=3D,db=3D LOG: restored log file "000000010000002F0000002D" from archive 2013-04-05 13:01:14 MDT [16981]: [4-1] user=3D,db=3D LOG: consistent recov= ery state reached at 2F/2D000080 2013-04-05 13:01:14 MDT [16981]: [5-1] user=3D,db=3D LOG: redo starts at 2F/2D000080 2013-04-05 13:01:15 MDT [16981]: [6-1] user=3D,db=3D LOG: restored log file "000000010000002F0000002E" from archive 2013-04-05 13:01:15 MDT [16981]: [7-1] user=3D,db=3D LOG: restored log file "000000010000002F0000002F" from archive <snip> 2013-04-05 13:01:17 MDT [16981]: [25-1] user=3D,db=3D LOG: redo done at 2F/3F07B4D0 2013-04-05 13:01:17 MDT [16981]: [26-1] user=3D,db=3D LOG: last completed transaction was at log time 2013-04-05 12:53:01.069826-06 2013-04-05 13:01:17 MDT [16981]: [27-1] user=3D,db=3D LOG: restored log fi= le "000000010000002F0000003F" from archive 2013-04-05 13:01:17 MDT [16981]: [28-1] user=3D,db=3D LOG: selected new timeline ID: 2 2013-04-05 13:01:17 MDT [16981]: [29-1] user=3D,db=3D LOG: archive recovery complete 2013-04-05 13:01:17 MDT [16991]: [1-1] user=3D,db=3D LOG: checkpoint start= ing: end-of-recovery immediate wait 2013-04-05 13:01:17 MDT [16991]: [2-1] user=3D,db=3D LOG: checkpoint compl= ete: wrote 327 buffers (0.1%); 0 transaction log file(s) ad ded, 0 removed, 0 recycled; write=3D0.015 s, sync=3D0.000 s, total=3D0.035 = s; sync files=3D0, longest=3D0.000 s, average=3D0.000 s 2013-04-05 13:01:17 MDT [16978]: [2-1] user=3D,db=3D LOG: database system = is ready to accept connections So, the behavior has definitely changed between 9.2.3 and 9.2.4. Is this a bug in 9.2.4? Or, must I now include pg_xlog files when taking base backups with 9.2.4, contrary to the documentation? Or, is there a way to make PG 9.2.4 use restore_command for recovery, as 9.2.3 does? Thank you, - Jeff
On Fri, Apr 5, 2013 at 12:27 PM, <bohmer@visionlink.org> wrote: > The following bug has been logged on the website: > > Bug reference: 8043 > Logged by: Jeff Bohmer > Email address: bohmer@visionlink.org > PostgreSQL version: 9.2.4 > Operating system: CentOS 5.9 x86_64 kernel 2.6.18-348.3.1.el5 > Description: > > Hi pgsql-bugs, > > PG version: 9.2.4, from yum.postgresql.org > OS: CentOS 5.9 x86_64 kernel 2.6.18-348.3.1.el5 > > Upgrading from 9.2.3 to 9.2.4 has broken archive recovery for me. Probably > related to this 9.2.4 change: > > Ensure we do crash recovery before entering archive recovery, > if the database was not stopped cleanly and a recovery.conf > file is present (Heikki Linnakangas, Kyotaro Horiguchi, > Mitsumasa Kondo) > > When starting the PostgreSQL 9.2.4 service on a base backup, I get this: > > 2013-04-05 12:49:04 MDT [10302]: [1-1] user=,db= LOG: database system was > interrupted; last known up at 2013-04-05 10:02:01 MDT > 2013-04-05 12:49:04 MDT [10302]: [2-1] user=,db= LOG: starting archive > recovery > 2013-04-05 12:49:04 MDT [10302]: [3-1] user=,db= LOG: could not open file > "pg_xlog/000000010000002F0000002D" (log file 47, segment 45): No such file > or directory > ... > I use a custom base backup script to call pg_start/stop_backup() and make > the backup with rsync. > > The restore_command in recovery.conf is never called by PG 9.2.4 during > startup. I confirmed this by adding a "touch /tmp/restore_command.`date > +%H:%M:%S`" line at the beginning of the shell script I use for my > restore_command. No such files are created when starting PG 9.2.4. > > After downgrading back to 9.2.3, archive recovery works using the very same > base backup, recovery.conf file, and restore_command. The log indicates > that > PG 9.2.3 begins recovery by pulling WAL files from the archive instead of > pg_xlog: > I can reproduce the behavior you report only if I remove the "backup_label" file from the restored data directory before I begin recovery. Of course, doing that renders the backup invalid, as without it recovery is very likely to begin from the wrong WAL recovery location. I think it is appropriate that 9.2.4 refuses to cooperate in those circumstances, and it was a bug that 9.2.3 did allow it. Do you have a "backup_label" file? > Or, must I now include pg_xlog files when taking base backups with 9.2.4, > contrary to the documentation? > You do not need to include pg_xlog, but you do need to include backup_label. And you always did need to include it--if you were not including it in the past, then you were playing with fire and is only due to luck that your database survived. Cheers, Jeff
Re: BUG #8043: 9.2.4 doesn't open WAL files from archive, only looks in pg_xlog
От
Heikki Linnakangas
Дата:
On 06.04.2013 01:02, Jeff Janes wrote: > On Fri, Apr 5, 2013 at 12:27 PM,<bohmer@visionlink.org> wrote: >> I use a custom base backup script to call pg_start/stop_backup() and make >> the backup with rsync. >> >> The restore_command in recovery.conf is never called by PG 9.2.4 during >> startup. I confirmed this by adding a "touch /tmp/restore_command.`date >> +%H:%M:%S`" line at the beginning of the shell script I use for my >> restore_command. No such files are created when starting PG 9.2.4. >> >> After downgrading back to 9.2.3, archive recovery works using the very same >> base backup, recovery.conf file, and restore_command. The log indicates >> that >> PG 9.2.3 begins recovery by pulling WAL files from the archive instead of >> pg_xlog: > > I can reproduce the behavior you report only if I remove the "backup_label" > file from the restored data directory before I begin recovery. Of course, > doing that renders the backup invalid, as without it recovery is very > likely to begin from the wrong WAL recovery location. Yeah, if you use pg_start/stop_backup(), there definitely should be a backup_label present. But there is a point here, if you use an atomic filesystem snapshot instead of pg_start/stop_backup(), or just a plain copy of the data directory while the system is shut down. The problem in that case is that if pg_xlog is empty, we have no idea how far we need to recover until the system is consistent. Actually, if the system was shut down, then the system is consistent immediately and we could allow that, but the problem still remains for an online backup using an atomic filesystem snapshot. I don't think there's much we can do about that case. We could start up and recover all the WAL from the archive before we declare consistency, but that gets pretty complicated, and it would still not work if you tried to do that in a standby that uses streaming replication without a restore_command. So, I think what we need to do is to update the documentation to make it clear that you must not zap pg_xlog if you take a backup without pg_start/stop_backup(). The documentation that talks about filesystem snapshots and offline backups doesn't actually say that you can zap pg_xlog - that is only mentioned in the section on pg_start/stop_backup(). But perhaps that could be made more explicit. >> Or, must I now include pg_xlog files when taking base backups with 9.2.4, >> contrary to the documentation? > > You do not need to include pg_xlog, but you do need to include > backup_label. And you always did need to include it--if you were not > including it in the past, then you were playing with fire and is only due > to luck that your database survived. Incidentally, I bumped into another custom backup script just a few weeks back that also excluded backup_label. I don't know what the author was thinking when he wrote that, but it seems to be a surprisingly common mistake. Maybe it's the "label" in the filename that makes people think it's not important. Perhaps we should improve the documentation to make it more explicit that backup_label must be included in the backup. The docs already say that, though, so I suspect that people making this mistake have not read the docs very carefully anyway. Perhaps a comment in the beginning of backup_label would help: # NOTE: This file MUST be included in the backup. Otherwise, the backup # is inconsistent, and restoring it may result in a corrupt database. Jeff B., assuming that you excluded backup_label from the backup for some reason, do you have any thoughts on what would've helped you to avoid that mistake? Would a comment like above have helped - did you look inside backup_label at any point? - Heikki
On Sat, Apr 6, 2013 at 1:24 AM, Heikki Linnakangas <hlinnakangas@vmware.com> wrote:
Incidentally, I bumped into another custom backup script just a few weeks back that also excluded backup_label. I don't know what the author was thinking when he wrote that, but it seems to be a surprisingly common mistake. Maybe it's the "label" in the filename that makes people think it's not important.
I think part of it is the name "label', and part of it is that this file is similar to and hence easily confused with the .history files, which (as far as I know) truly are there only for human information and not for system operation.
Perhaps we should improve the documentation to make it more explicit that backup_label must be included in the backup. The docs already say that, though, so I suspect that people making this mistake have not read the docs very carefully anyway.
I don't think the docs are very clear on that. They say "This file will of course be archived as a part of your backup dump file", but "will be" does not imply "must be". Elsewhere it emphasizes that the label you gave to pg_start_backup is written into the file, but doesn't really say what the file itself is there for. To me it seems to imply that the file is there for your convenience, to hold that label, and not as a critical part of the system.
Patch attached, which I hope can be back-patched. I'll also add it to commitfest-Next.
Cheers,
Jeff
Вложения
Re: BUG #8043: 9.2.4 doesn't open WAL files from archive, only looks in pg_xlog
От
Jeff Bohmer
Дата:
On Apr 6, 2013, at 1:24 PM, Jeff Janes <jeff.janes@gmail.com> wrote: > On Sat, Apr 6, 2013 at 1:24 AM, Heikki Linnakangas > <hlinnakangas@vmware.com>wrote: > >> >> Incidentally, I bumped into another custom backup script just a few weeks >> back that also excluded backup_label. I don't know what the author was >> thinking when he wrote that, but it seems to be a surprisingly common >> mistake. Maybe it's the "label" in the filename that makes people think >> it's not important. > > > > I think part of it is the name "label', and part of it is that this file is > similar to and hence easily confused with the .history files, which (as far > as I know) truly are there only for human information and not for system > operation. While the backup_label file was included in all base backups by the custom backup script, it was not present in the clusterdirectory when starting PG 9.2.4. Because the data directory was synced from the base backup without backup_label.Sure enough, including backup_label in the data directory fixes this for me. I think these custom scripts were written around 8.1. That the base backups have worked all this time (each base backup istested) is probably because the backup script, immediately after calling pg_start_backup(), rsyncs pg_control before rsync'ingeverything else in the data directory. Although, it seems this quirk allows for problems if WAL files are generatedbetween the time pg_start_backup() is called and pg_control is rsync'd. >> Perhaps we should improve the documentation to make it more explicit that >> backup_label must be included in the backup. The docs already say that, >> though, so I suspect that people making this mistake have not read the docs >> very carefully anyway. >> > > > I don't think the docs are very clear on that. They say "This file will of > course be archived as a part of your backup dump file", but "will be" does > not imply "must be". Elsewhere it emphasizes that the label you gave to > pg_start_backup is written into the file, but doesn't really say what the > file itself is there for. To me it seems to imply that the file is there > for your convenience, to hold that label, and not as a critical part of the > system. > > Patch attached, which I hope can be back-patched. I'll also add it to > commitfest-Next. > > Cheers, > > Jeff > <backup_label_warning_v1.patch> I think this documentation update would be helpful. Thank you for your help, - Jeff -- Jeff Bohmer | Corporate Technology Manager | VisionLink, Inc. First National Center | 3101 Iris Avenue, Suite 240 | Boulder CO, 80301 Office 303.402.0170 x121 Other ways to stay in touch - Blog | Twitter | Facebook | LinkedIn | Web This message and any attachments may contain information that is privileged, confidential or exempt from disclosure under applicable law or agreement. If you have received this message in error, please reply and delete the message and any attachments without opening the attachment. Thank you.
Re: BUG #8043: 9.2.4 doesn't open WAL files from archive, only looks in pg_xlog
От
Jeff Bohmer
Дата:
On Apr 6, 2013, at 2:24 AM, Heikki Linnakangas <hlinnakangas@vmware.com> = wrote: > Incidentally, I bumped into another custom backup script just a few = weeks back that also excluded backup_label. I don't know what the author = was thinking when he wrote that, but it seems to be a surprisingly = common mistake. Maybe it's the "label" in the filename that makes people = think it's not important. Perhaps we should improve the documentation to = make it more explicit that backup_label must be included in the backup. = The docs already say that, though, so I suspect that people making this = mistake have not read the docs very carefully anyway. >=20 > Perhaps a comment in the beginning of backup_label would help: >=20 > # NOTE: This file MUST be included in the backup. Otherwise, the = backup > # is inconsistent, and restoring it may result in a corrupt database. >=20 > Jeff B., assuming that you excluded backup_label from the backup for = some reason, do you have any thoughts on what would've helped you to = avoid that mistake? Would a comment like above have helped - did you = look inside backup_label at any point? I think such a comment could be helpful. The base backups did contain = backup_label. That is how another script would determine what WAL files = to remove. It looked at the oldest base backup's backup_label file to = get the oldest WAL file to keep. My problem was that backup_label was excluded from the data directory = when it was sync'd from the base backup. (We keep base backups separate = from data directories, so they can be reused.) I guess it was excluded = because it was assumed to not be used by archive recovery. So, = clarifying backup_label's importance there seems helpful. Thank you for your help, - Jeff -- Jeff Bohmer | Corporate Technology Manager | VisionLink, Inc. First National Center | 3101 Iris Avenue, Suite 240 | Boulder CO, 80301 Office 303.402.0170 x121 Other ways to stay in touch - Blog | Twitter | Facebook | LinkedIn | Web This message and any attachments may contain information that is = privileged,=20 confidential or exempt from disclosure under applicable law or = agreement. If you=20 have received this message in error, please reply and delete the message = and=20 any attachments without opening the attachment. Thank you.
Re: [HACKERS] Re: BUG #8043: 9.2.4 doesn't open WAL files from archive, only looks in pg_xlog
От
Christoph Berg
Дата:
Re: Jeff Janes 2013-04-06 <CAMkU=1zvioQvMgbWssHv3DnXMNeEJmqtq_5hJqLGx8i4eGAQJg@mail.gmail.com> > I don't think the docs are very clear on that. They say "This file will of > course be archived as a part of your backup dump file", but "will be" does > not imply "must be". Elsewhere it emphasizes that the label you gave to > pg_start_backup is written into the file, but doesn't really say what the > file itself is there for. To me it seems to imply that the file is there > for your convenience, to hold that label, and not as a critical part of the > system. This was also my impression, tbh :-/. And the problem just popped up again independently on #postgresql. > Patch attached, which I hope can be back-patched. I'll also add it to > commitfest-Next. +1. It makes the documentation clearer on this. Christoph -- cb@df7cb.de | http://www.df7cb.de/
Re: BUG #8043: 9.2.4 doesn't open WAL files from archive, only looks in pg_xlog
От
Heikki Linnakangas
Дата:
On 08.04.2013 18:58, Jeff Bohmer wrote: > > On Apr 6, 2013, at 1:24 PM, Jeff Janes<jeff.janes@gmail.com> wrote: > >> On Sat, Apr 6, 2013 at 1:24 AM, Heikki Linnakangas >> <hlinnakangas@vmware.com>wrote: >> >>> Perhaps we should improve the documentation to make it more explicit that >>> backup_label must be included in the backup. The docs already say that, >>> though, so I suspect that people making this mistake have not read the docs >>> very carefully anyway. >> >> I don't think the docs are very clear on that. They say "This file will of >> course be archived as a part of your backup dump file", but "will be" does >> not imply "must be". Elsewhere it emphasizes that the label you gave to >> pg_start_backup is written into the file, but doesn't really say what the >> file itself is there for. To me it seems to imply that the file is there >> for your convenience, to hold that label, and not as a critical part of the >> system. >> >> Patch attached, which I hope can be back-patched. I'll also add it to >> commitfest-Next. > > I think this documentation update would be helpful. Committed that. - Heikki