MySQL Bugs: #43322: Finish time of BACKUP operation not stored in backup image

Bug #43322	Finish time of BACKUP operation not stored in backup image
Submitted:	3 Mar 2009 7:41	Modified:	6 Aug 2009 19:48
Reporter:	Rafal Somla	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Backup	Severity:	S3 (Non-critical)
Version:	6.0	OS:	Any
Assigned to:	Rafal Somla	CPU Architecture:	Any

Description:
The completion time of BACKUP statement (aka finis or stop time) which is reported in backup_history log, is not correctly stored in the resulting backup image.

How to repeat:
Run the following test case:

let $bdir=`select @@backupdir`;
BACKUP DATABASE test TO 'test.bkp';
query_vertical SELECT * FROM mysql.backup_history;
--exec $MYSQL_BACKUP --summary $bdir/test.bkp

and see the output of mysqlbackup utility:

Image path:          '<backupdir>/test.bkp'
Image size:          2166 bytes
Image compression:   none
Image version:       1
Creation time:       2009-03-03 07:29:27 UTC
Server version:      6.0.11 (6.0.11-alpha)
Server byte order:   little-endian
Server charset:      'utf8'

Summary:

Creation time:       2009-03-03 07:29:27 UTC
Validity time:       2009-03-03 07:29:27 UTC
Finish   time:       1900-01-00 00:00:00 UTC <-- This is wrong!
Binlog coordinates:  0.000001:107
Binlog group coords: [NULL]:0

Please specify whether this is a bug in the backup code, the stream code, or the mysqlbackup client. Can you please suggest areas where investigation can begin? Do you have any suggestions as to where the error occurs in the code?

I'm reasonably sure this is not mysqlbackup client problem but the finish time is not correctly stored in the image. A problem could be with the order in which finish time is stored in the Image_info object and the data is written to the image. The finish time is determined in Backup_restore_ctx::close() method but it is written to image in Backup_restore_ctx::do_backup() method (a call to write_summary()). So this must be the problem - finish time should be saved in Backup_info before a call to write_summary. Hmm, I think I know how to fix it :)

PROPOSED SOLUTION
=================

--- sql/backup/kernel.cc        2009-05-25 07:11:29 +0000
+++ sql/backup/kernel.cc        2009-06-19 09:31:32 +0000
@@ -1250,6 +1250,8 @@ int Backup_restore_ctx::do_backup()
   if (ret)
     DBUG_RETURN(fatal_error(ret));
 
+  info.save_end_time(my_time(0));
+
   DBUG_PRINT("backup",("Writing summary"));
 
   DEBUG_SYNC(m_thd, "before_backup_summary");

What remains to be done is to write a test case which checks that everything works as expected.

Setting to "verified" as I don't have time to work on this now.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/78701

2846 Rafal Somla	2009-07-15
      Bug #43322 - Finish time of BACKUP operation not stored in backup image
      
      Fixed by ensuring that:
      
      1) End time of backup operation is stored in Backup_info *before* backup image
         summary is written.
      
      2) The times stored in backup image's summary and logged in backup logs are the
         same.
     @ mysql-test/suite/backup/t/backup_logs.test
        Added new test for checking that times stored in backup logs and in 
        backup image's summary section are the same.
     @ sql/backup/image_info.h
        Add get_end_time() method. Move code common to get_*_time() to new
        helper function read_time() - a counterpart of save_time().
     @ sql/backup/kernel.cc
        - When end of backup/restore operation is reported in Backup_info::close() use 
          the end time saved in the Backup_info structure. If the end time was not saved 
          before, save and use the current time.
        - Save end time after backup of table data is complete and before the summary 
          section is written.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/79324

2846 Rafal Somla	2009-07-27
      Bug #43322 - Finish time of BACKUP operation not stored in backup image
      
      Before this patch, the finish time of BACKUP operation was reported in the
      backup logs, but was not stored in the summary section of the backup image.
      This was because the time was not yet stored in the Backup_info object at 
      the time when backup image summary section was written. This patch fixes 
      this by ensuring that:
      
      1) End time of backup operation is stored in Backup_info *before* backup image
         summary is written.
      
      2) The times stored in backup image's summary and logged in backup logs are the
         same.
     @ mysql-test/suite/backup/t/backup_logs.test
        Added new test case for checking that times stored in backup logs and in 
        backup image's summary section are the same.
     @ sql/backup/image_info.h
        Add get_end_time() method. Move code common to get_*_time() to new
        helper function read_time() - a counterpart of save_time().
     @ sql/backup/kernel.cc
        - When end of backup/restore operation is reported in Backup_info::close() use 
          the end time saved in the Backup_info structure. If the end time was not saved 
          before, save and use the current time.
        - Save end time after backup of table data is complete and before the summary 
          section is written.

Approved

Approved. No comments.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/79381

2850 Rafal Somla	2009-07-28
      Bug #43322 - Finish time of BACKUP operation not stored in backup image
      
      Before this patch, the finish time of BACKUP operation was reported in the
      backup logs, but was not stored in the summary section of the backup image.
      This was because the time was not yet stored in the Backup_info object at 
      the time when backup image summary section was written. This patch fixes 
      this by ensuring that:
      
      1) End time of backup operation is stored in Backup_info *before* backup image
         summary is written.
      
      2) The times stored in backup image's summary and logged in backup logs are the
         same.
     @ mysql-test/suite/backup/t/backup_logs.test
        Added new test case for checking that times stored in backup logs and in 
        backup image's summary section are the same.
     @ sql/backup/image_info.h
        Add get_end_time() method. Move code common to get_*_time() to new
        helper function read_time() - a counterpart of save_time().
     @ sql/backup/kernel.cc
        - When end of backup/restore operation is reported in Backup_info::close() use 
          the end time saved in the Backup_info structure. If the end time was not saved 
          before, save and use the current time.
        - Save end time after backup of table data is complete and before the summary 
          section is written.

Pushed to team tree on 2009-07-28 10:16:43.

Pushed into 5.4.4-alpha (revid:alik@sun.com-20090806082225-qssc912qdv1mm6xv) (version source revid:rafal.somla@sun.com-20090728062523-zx7atxgjfm6x1bj4) (merge vers: 5.4.4-alpha) (pib:11)

Not in any released version. No changelog entry needed.