Bug #50458 Backup logs show wrong stop time when restore is performed.
Submitted: 19 Jan 2010 21:36 Modified: 2 Mar 2010 2:18
Reporter: Hema Sridharan Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Backup Severity:S2 (Serious)
Version:5.6.0, 6.0.14 OS:Any
Assigned to: Rafal Somla CPU Architecture:Any

[19 Jan 2010 21:36] Hema Sridharan
Description:
Create database, tables and load some data in tables.
Execute backup and restore operations.
Check the backup history logs for start time and stop time of backup and restore.

You will notice that stop time is same for backup as well as restore. Therefore, start time for restore shows later time than stop time in backup logs.

How to repeat:
Create database db2;
create table db2.t1(id int);
Insert into db2.t1 values(1),(2),(3),(4);
Backup database db2 to 'db2.bak';
Drop database db2;
Restore from 'db2.bak';
Check the backup history logs for start and stop time.

The logs show the same stop time for backup as well as restore. See below for an example.

mysql> create database db;
Query OK, 1 row affected (0.00 sec)

mysql> use db;
Database changed
mysql> create table db.t1(id int);
Query OK, 0 rows affected (0.04 sec)

mysql> insert into db.t1 values(1),(2),(3),(4),(5);
Query OK, 5 rows affected (0.00 sec)
Records: 5  Duplicates: 0  Warnings: 0

mysql> backup database db to 'dba.bak';
+-----------+
| backup_id |
+-----------+
| 276       |
+-----------+
1 row in set (0.49 sec)

mysql> drop database db;
Query OK, 1 row affected (0.00 sec)

Perform restore after 1min

mysql> restore from 'dba.bak';
+-----------+
| backup_id |
+-----------+
| 277       |
+-----------+
1 row in set (0.06 sec)

mysql> select * from mysql.backup_history\G
*************************** 1. row ***************************
          backup_id: 276
         process_id: 0
   binlog_start_pos: 0
        binlog_file:
       backup_state: complete
          operation: backup
          error_num: 0
        num_objects: 2
        total_bytes: 1617
validity_point_time: 2010-01-19 21:22:39   
         start_time: 2010-01-19 21:22:39  
          stop_time: 2010-01-19 21:22:39  
host_or_server_name: localhost
           username: root
        backup_file: dba.bak
 ...
....
*************************** 2. row ***************************
          backup_id: 277
         process_id: 0
   binlog_start_pos: 0
        binlog_file:
       backup_state: complete
          operation: restore
          error_num: 0
        num_objects: 2
        total_bytes: 1617
validity_point_time: 2010-01-19 21:22:39 
         start_time: 2010-01-19 21:24:03
          stop_time: 2010-01-19 21:22:39 ==> Restore has same stop_time as backup
host_or_server_name: localhost
           username: root
        backup_file: dba.bak
        ..
..

The above table shows that stop_time for both backup and restore are the same
which is incorrect.
[19 Jan 2010 22:28] Sveta Smirnova
Thank you for the report.

Verified as described.
[21 Jan 2010 19:21] Bugs System
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/97771

2936 Rafal Somla	2010-01-21
      Bug#50458 - Backup logs show wrong stop time when restore is performed.
      
      Due to error in the program logic, RESTORE operation reported in backup
      logs stop time read from backup image, that is the saved time of when
      BACKUP operation has ended.
      
      This patch fixes the logic so that stop time of RESTORE operation is
      reported instead.
     @ mysql-test/suite/backup/t/backup_logs.test
        - Ensure that RESTORE operation runs at least 1 second, so that stop 
          time is bigger than start time.
        - Add check that stop time is bigger than start time.
     @ sql/backup/kernel.cc
        When reporting stop time to backup logs, take the time which is stored in 
        m_catalog only in case of BACKUP operation. For RESTORE report the actual
        time when the operation has ended.
[22 Jan 2010 10:13] Rafal Somla
Patch queued into mysql-6.0-backup tree.
revid:rafal.somla@sun.com-20100121192059-4bysvwlc3sltg9q9
[20 Feb 2010 9:17] Bugs System
Pushed into 6.0.14-alpha (revid:ingo.struewing@sun.com-20100218152520-s4v1ld76bif06eqn) (version source revid:ingo.struewing@sun.com-20100122221225-ccgkfpesvrttdlc1) (merge vers: 6.0.14-alpha) (pib:16)
[2 Mar 2010 2:18] Paul DuBois
Noted in 6.0.14 changelog.

The stop time for RESTORE operations was logged incorrectly.