Thread

1. Error restoring from a base backup taken from standby

   Heikki Linnakangas <hlinnakangas@vmware.com> — 2012-12-17T17:39:29Z

   (This is different from the other issue related to timeline switches I 
   just posted about. There's no timeline switch involved in this one.)
   
   If you do "pg_basebackup -x" against a standby server, in some 
   circumstances the backup fails to restore with error like this:
   
   C 2012-12-17 19:09:44.042 EET 7832 LOG:  database system was not 
   properly shut down; automatic recovery in progress
   C 2012-12-17 19:09:44.091 EET 7832 LOG:  record with zero length at 
   0/1764F48
   C 2012-12-17 19:09:44.091 EET 7832 LOG:  redo is not required
   C 2012-12-17 19:09:44.091 EET 7832 FATAL:  WAL ends before end of online 
   backup
   C 2012-12-17 19:09:44.091 EET 7832 HINT:  All WAL generated while online 
   backup was taken must be available at recovery.
   C 2012-12-17 19:09:44.092 EET 7831 LOG:  startup process (PID 7832) 
   exited with exit code 1
   C 2012-12-17 19:09:44.092 EET 7831 LOG:  aborting startup due to startup 
   process failure
   
   I spotted this bug while reading the code, and it took me quite a while 
   to actually construct a test case to reproduce the bug, so let me begin 
   by discussing the code where the bug is. You get the above error, "WAL 
   ends before end of online backup", when you reach the end of WAL before 
   reaching the backupEndPoint stored in the control file, which originally 
   comes from the backup_label file. backupEndPoint is only used in a base 
   backup taken from a standby, in a base backup taken from the master, the 
   end-of-backup WAL record is used instead to mark the end of backup. In 
   the xlog redo loop, after replaying each record, we check if we've just 
   reached backupEndPoint, and clear it from the control file if we have. 
   Now the problem is, if there are no WAL records after the checkpoint 
   redo point, we never even enter the redo loop, so backupEndPoint is not 
   cleared even though it's reached immediately after reading the initial 
   checkpoint record.
   
   To deal with the similar situation wrt. reaching consistency for hot 
   standby purposes, we call CheckRecoveryConsistency() before the redo 
   loop. The straightforward fix is to copy-paste the check for 
   backupEndPoint to just before the redo loop, next to the 
   CheckRecoveryConsistency() call. Even better, I think we should move the 
   backupEndPoint check into CheckRecoveryConsistency(). It's already 
   responsible for keeping track of whether minRecoveryPoint has been 
   reached, so it seems like a good idea to do this check there as well.
   
   Attached is a patch for that (for 9.2), as well as a script I used to 
   reproduce the bug. The script is a bit messy, and requires tweaking the 
   paths at the top. Anyone spot a problem with this?
   
   - Heikki
   

2. Re: Error restoring from a base backup taken from standby

   Simon Riggs <simon@2ndquadrant.com> — 2012-12-17T22:35:43Z

   On 17 December 2012 17:39, Heikki Linnakangas <hlinnakangas@vmware.com> wrote:
   > (This is different from the other issue related to timeline switches I just
   > posted about. There's no timeline switch involved in this one.)
   >
   > If you do "pg_basebackup -x" against a standby server, in some circumstances
   > the backup fails to restore with error like this:
   >
   > C 2012-12-17 19:09:44.042 EET 7832 LOG:  database system was not properly
   > shut down; automatic recovery in progress
   > C 2012-12-17 19:09:44.091 EET 7832 LOG:  record with zero length at
   > 0/1764F48
   > C 2012-12-17 19:09:44.091 EET 7832 LOG:  redo is not required
   > C 2012-12-17 19:09:44.091 EET 7832 FATAL:  WAL ends before end of online
   > backup
   > C 2012-12-17 19:09:44.091 EET 7832 HINT:  All WAL generated while online
   > backup was taken must be available at recovery.
   > C 2012-12-17 19:09:44.092 EET 7831 LOG:  startup process (PID 7832) exited
   > with exit code 1
   > C 2012-12-17 19:09:44.092 EET 7831 LOG:  aborting startup due to startup
   > process failure
   >
   > I spotted this bug while reading the code, and it took me quite a while to
   > actually construct a test case to reproduce the bug, so let me begin by
   > discussing the code where the bug is. You get the above error, "WAL ends
   > before end of online backup", when you reach the end of WAL before reaching
   > the backupEndPoint stored in the control file, which originally comes from
   > the backup_label file. backupEndPoint is only used in a base backup taken
   > from a standby, in a base backup taken from the master, the end-of-backup
   > WAL record is used instead to mark the end of backup. In the xlog redo loop,
   > after replaying each record, we check if we've just reached backupEndPoint,
   > and clear it from the control file if we have. Now the problem is, if there
   > are no WAL records after the checkpoint redo point, we never even enter the
   > redo loop, so backupEndPoint is not cleared even though it's reached
   > immediately after reading the initial checkpoint record.
   >
   > To deal with the similar situation wrt. reaching consistency for hot standby
   > purposes, we call CheckRecoveryConsistency() before the redo loop. The
   > straightforward fix is to copy-paste the check for backupEndPoint to just
   > before the redo loop, next to the CheckRecoveryConsistency() call. Even
   > better, I think we should move the backupEndPoint check into
   > CheckRecoveryConsistency(). It's already responsible for keeping track of
   > whether minRecoveryPoint has been reached, so it seems like a good idea to
   > do this check there as well.
   >
   > Attached is a patch for that (for 9.2), as well as a script I used to
   > reproduce the bug. The script is a bit messy, and requires tweaking the
   > paths at the top. Anyone spot a problem with this?
   
   Yep. The problem is one of design, not merely a coding error.
   
   The design assumes that the master is up, connected and doing work.
   Which is perfectly reasonable, since this is the reason we are doing a
   backup from the standby. But obviously not always true, so what we're
   saying is that the selection of backupEndPoint is incorrect in the
   first place. Putting code in to cope with that poor choice at recovery
   seems wrong - we should record the correct location.
   
   Comments in do_pg_start_backup() say this
   
    * We return the current minimum recovery point as the backup end
    * location. Note that it can be greater than the exact backup end
    * location if the minimum recovery point is updated after the backup of
    * pg_control. This is harmless for current uses.
   
   Which would stay wrong if we apply the proposed patch.
   
   I think we should record the most recently received LSN, which I
   notice is not the misnamed receivedUpto in xlog.c
   Misnamed because it refers to what has been received and written
   rather than what has been received.
   
   So I suggest using latestWalEnd if streaming or similar for file access.
   
   In passing, I see another problem as well. We assume that the backup
   is still valid if we promote the standby to a master during the
   backup, but that isn't documented and so isn't full analysed to see
   that is true. I haven't tried to construct a failure case out of that,
   as yet.
   
   -- 
    Simon Riggs                   http://www.2ndQuadrant.com/
    PostgreSQL Development, 24x7 Support, Training & Services
   
   
   

3. Re: Error restoring from a base backup taken from standby

   Heikki Linnakangas <hlinnakangas@vmware.com> — 2012-12-18T09:18:50Z

   On 18.12.2012 00:35, Simon Riggs wrote:
   > On 17 December 2012 17:39, Heikki Linnakangas<hlinnakangas@vmware.com>  wrote:
   >> (This is different from the other issue related to timeline switches I just
   >> posted about. There's no timeline switch involved in this one.)
   >>
   >> If you do "pg_basebackup -x" against a standby server, in some circumstances
   >> the backup fails to restore with error like this:
   >>
   >> C 2012-12-17 19:09:44.042 EET 7832 LOG:  database system was not properly
   >> shut down; automatic recovery in progress
   >> C 2012-12-17 19:09:44.091 EET 7832 LOG:  record with zero length at
   >> 0/1764F48
   >> C 2012-12-17 19:09:44.091 EET 7832 LOG:  redo is not required
   >> C 2012-12-17 19:09:44.091 EET 7832 FATAL:  WAL ends before end of online
   >> backup
   >> C 2012-12-17 19:09:44.091 EET 7832 HINT:  All WAL generated while online
   >> backup was taken must be available at recovery.
   >> C 2012-12-17 19:09:44.092 EET 7831 LOG:  startup process (PID 7832) exited
   >> with exit code 1
   >> C 2012-12-17 19:09:44.092 EET 7831 LOG:  aborting startup due to startup
   >> process failure
   >>
   >> I spotted this bug while reading the code, and it took me quite a while to
   >> actually construct a test case to reproduce the bug, so let me begin by
   >> discussing the code where the bug is. You get the above error, "WAL ends
   >> before end of online backup", when you reach the end of WAL before reaching
   >> the backupEndPoint stored in the control file, which originally comes from
   >> the backup_label file. backupEndPoint is only used in a base backup taken
   >> from a standby, in a base backup taken from the master, the end-of-backup
   >> WAL record is used instead to mark the end of backup. In the xlog redo loop,
   >> after replaying each record, we check if we've just reached backupEndPoint,
   >> and clear it from the control file if we have. Now the problem is, if there
   >> are no WAL records after the checkpoint redo point, we never even enter the
   >> redo loop, so backupEndPoint is not cleared even though it's reached
   >> immediately after reading the initial checkpoint record.
   >>
   >> To deal with the similar situation wrt. reaching consistency for hot standby
   >> purposes, we call CheckRecoveryConsistency() before the redo loop. The
   >> straightforward fix is to copy-paste the check for backupEndPoint to just
   >> before the redo loop, next to the CheckRecoveryConsistency() call. Even
   >> better, I think we should move the backupEndPoint check into
   >> CheckRecoveryConsistency(). It's already responsible for keeping track of
   >> whether minRecoveryPoint has been reached, so it seems like a good idea to
   >> do this check there as well.
   >>
   >> Attached is a patch for that (for 9.2), as well as a script I used to
   >> reproduce the bug. The script is a bit messy, and requires tweaking the
   >> paths at the top. Anyone spot a problem with this?
   >
   > Yep. The problem is one of design, not merely a coding error.
   >
   > The design assumes that the master is up, connected and doing work.
   > Which is perfectly reasonable, since this is the reason we are doing a
   > backup from the standby. But obviously not always true, so what we're
   > saying is that the selection of backupEndPoint is incorrect in the
   > first place. Putting code in to cope with that poor choice at recovery
   > seems wrong - we should record the correct location.
   
   Hmm, pg_controlinfo says:
   
   pg_control version number:            922
   Catalog version number:               201204301
   Database system identifier:           5823207860608399803
   Database cluster state:               in crash recovery
   pg_control last modified:             ti 18. joulukuuta 2012 11.00.58
   Latest checkpoint location:           0/1764EE8
   Prior checkpoint location:            0/1764EE8
   Latest checkpoint's REDO location:    0/1764EE8
   Latest checkpoint's TimeLineID:       1
   ...
   Minimum recovery ending location:     0/1764F48
   Backup start location:                0/1764EE8
   Backup end location:                  0/1764F48
   ...
   
   That seems correct to me. The backup is considered valid after reaching 
   0/1764F48, which is where the checkpoint record ends. minRecoveryPoint 
   is set to the same. What do you think it should be set to?
   
   > In passing, I see another problem as well. We assume that the backup
   > is still valid if we promote the standby to a master during the
   > backup, but that isn't documented and so isn't full analysed to see
   > that is true.
   
   No, that is taken care of in do_pg_stop_backup:
   
   > 	/*
   > 	 * Parse the BACKUP FROM line. If we are taking an online backup from the
   > 	 * standby, we confirm that the standby has not been promoted during the
   > 	 * backup.
   > 	 */
   > 	ptr = strstr(remaining, "BACKUP FROM:");
   > 	if (!ptr || sscanf(ptr, "BACKUP FROM: %19s\n", backupfrom) != 1)
   > 		ereport(ERROR,
   > 				(errcode(ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE),
   > 				 errmsg("invalid data in file \"%s\"", BACKUP_LABEL_FILE)));
   > 	if (strcmp(backupfrom, "standby") == 0 && !backup_started_in_recovery)
   > 		ereport(ERROR,
   > 				(errcode(ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE),
   > 				 errmsg("the standby was promoted during online backup"),
   > 				 errhint("This means that the backup being taken is corrupt "
   > 						 "and should not be used. "
   > 						 "Try taking another online backup.")));
   
   - Heikki
   
   
   

4. Re: Error restoring from a base backup taken from standby

   Simon Riggs <simon@2ndquadrant.com> — 2012-12-18T09:30:50Z

   On 18 December 2012 09:18, Heikki Linnakangas <hlinnakangas@vmware.com> wrote:
   
   > That seems correct to me. The backup is considered valid after reaching
   > 0/1764F48, which is where the checkpoint record ends. minRecoveryPoint is
   > set to the same. What do you think it should be set to?
   
   I already said?
   
   -- 
    Simon Riggs                   http://www.2ndQuadrant.com/
    PostgreSQL Development, 24x7 Support, Training & Services
   
   
   

5. Re: Error restoring from a base backup taken from standby

   Heikki Linnakangas <hlinnakangas@vmware.com> — 2012-12-18T09:35:47Z

   On 18.12.2012 11:30, Simon Riggs wrote:
   > On 18 December 2012 09:18, Heikki Linnakangas<hlinnakangas@vmware.com>  wrote:
   >
   >> That seems correct to me. The backup is considered valid after reaching
   >> 0/1764F48, which is where the checkpoint record ends. minRecoveryPoint is
   >> set to the same. What do you think it should be set to?
   >
   > I already said?
   
   In this situation, there are no more WAL records in the standby the 
   backup was taken from, after the checkpoint record. Using receivedUpto 
   would yield the same value, and you'd still have the same problem.
   
   - Heikki
   
   
   

6. Re: Error restoring from a base backup taken from standby

   Fujii Masao <masao.fujii@gmail.com> — 2012-12-18T18:06:53Z

   On Tue, Dec 18, 2012 at 2:39 AM, Heikki Linnakangas
   <hlinnakangas@vmware.com> wrote:
   > (This is different from the other issue related to timeline switches I just
   > posted about. There's no timeline switch involved in this one.)
   >
   > If you do "pg_basebackup -x" against a standby server, in some circumstances
   > the backup fails to restore with error like this:
   >
   > C 2012-12-17 19:09:44.042 EET 7832 LOG:  database system was not properly
   > shut down; automatic recovery in progress
   > C 2012-12-17 19:09:44.091 EET 7832 LOG:  record with zero length at
   > 0/1764F48
   > C 2012-12-17 19:09:44.091 EET 7832 LOG:  redo is not required
   > C 2012-12-17 19:09:44.091 EET 7832 FATAL:  WAL ends before end of online
   > backup
   > C 2012-12-17 19:09:44.091 EET 7832 HINT:  All WAL generated while online
   > backup was taken must be available at recovery.
   > C 2012-12-17 19:09:44.092 EET 7831 LOG:  startup process (PID 7832) exited
   > with exit code 1
   > C 2012-12-17 19:09:44.092 EET 7831 LOG:  aborting startup due to startup
   > process failure
   >
   > I spotted this bug while reading the code, and it took me quite a while to
   > actually construct a test case to reproduce the bug, so let me begin by
   > discussing the code where the bug is. You get the above error, "WAL ends
   > before end of online backup", when you reach the end of WAL before reaching
   > the backupEndPoint stored in the control file, which originally comes from
   > the backup_label file. backupEndPoint is only used in a base backup taken
   > from a standby, in a base backup taken from the master, the end-of-backup
   > WAL record is used instead to mark the end of backup. In the xlog redo loop,
   > after replaying each record, we check if we've just reached backupEndPoint,
   > and clear it from the control file if we have. Now the problem is, if there
   > are no WAL records after the checkpoint redo point, we never even enter the
   > redo loop, so backupEndPoint is not cleared even though it's reached
   > immediately after reading the initial checkpoint record.
   
   Good catch!
   
   > To deal with the similar situation wrt. reaching consistency for hot standby
   > purposes, we call CheckRecoveryConsistency() before the redo loop. The
   > straightforward fix is to copy-paste the check for backupEndPoint to just
   > before the redo loop, next to the CheckRecoveryConsistency() call. Even
   > better, I think we should move the backupEndPoint check into
   > CheckRecoveryConsistency(). It's already responsible for keeping track of
   > whether minRecoveryPoint has been reached, so it seems like a good idea to
   > do this check there as well.
   >
   > Attached is a patch for that (for 9.2), as well as a script I used to
   > reproduce the bug.
   
   The patch looks good to me.
   
   Regards,
   
   -- 
   Fujii Masao