I've got a daily process that restores a DB from one server to another. It restored the Database backup file of the DB and if it finds TLog backup files, it restores them too.
The process works for some time now with no issues. Today it failed The error message:
Message
Executed as user: AOI\sa_SqlAgentSrv_PRD. RegQueryValueEx() returned error 2, 'The system cannot find the file specified.' [SQLSTATE 01000] (Message 22001) IF EXISTS (select * from sysdatabases where name = 'SiteDbStandby') ALTER DATABASE SiteDbStandby SET SINGLE_USER WITH ROLLBACK IMMEDIATE
RESTORE DATABASE [SiteDbStandby] FROM DISK = '\\SqlBackup\Databases\SiteDb.bak' WITH NORECOVERY , REPLACE , MOVE 'SiteDb_data' to 'G:\MSSQL10.DB2\MSSQL\DATA\SiteDbStandby_SiteDb_data.mdf' , MOVE 'SiteDb_log' to 'J:\MSSQL10.DB2\MSSQL\DATA\SiteDbStandby_SiteDb_log.ndf' [SQLSTATE 01000] (Message 0) Processed 191216 pages for database 'SiteDbStandby', file 'SiteDb_data' on file 1. [SQLSTATE 01000] (Message 4035) Processed 4 pages for database 'SiteDbStandby', file 'SiteDb_log' on file 1. [SQLSTATE 01000] (Message 4035)
RESTORE DATABASE successfully processed 191220 pages in 20.366 seconds (73.352 MB/sec). [SQLSTATE 01000] (Message 3014)
RESTORE LOG SiteDbStandby FROM DISK = '\\SqlBackup\Logs\SiteDb_20120916_011017.BAK' WITH NORECOVERY
RESTORE LOG SiteDbStandby FROM DISK = '\\SqlBackup\Logs\SiteDb_20120916_021929.BAK' WITH NORECOVERY
RESTORE LOG SiteDbStandby FROM DISK = '\\SqlBackup\Logs\SiteDb_20120916_031349.BAK' WITH NORECOVERY
RESTORE LOG SiteDbStandby FROM DISK = '\\SqlBackup\Logs\SiteDb_20120915_231017.BAK' WITH NORECOVERY
RESTORE LOG SiteDbStandby FROM DISK = '\\SqlBackup\Logs\SiteDb_20120916_001017.BAK' WITH NORECOVERY [SQLSTATE 01000] (Message 0) The log in this backup set begins at LSN 42459000001303500001, which is too recent to apply to the database. An earlier log backup that includes LSN 42459000001302800001 can be restored. [SQLSTATE 42000] (Error 4305) RESTORE LOG is terminating abnormally. [SQLSTATE 42000] (Error 3013). The step failed.
You can see that it tries to restore the log file of 16.9 from 1AM, the log file of 16.9 from 2AM, the log file of 16.9 from 3AM, and then the log file of 15.9 from 23PM, and the log file of 16.9 from 12AM.
The restore sequence of the logs got messed up.
I've looked back in the job's histoy, we've got history of around 3 weeks of daily executions. In each one of the executions, the sequence is correct. For example:
Executed as user: AOI\sa_SqlAgentSrv_PRD. RegQueryValueEx() returned error 2, 'The system cannot find the file specified.' [SQLSTATE 01000] (Message 22001) IF EXISTS (select * from sysdatabases where name = 'SiteDbStandby') ALTER DATABASE SiteDbStandby SET SINGLE_USER WITH ROLLBACK IMMEDIATE
RESTORE DATABASE [SiteDbStandby] FROM DISK = '\\SqlBackup\Databases\SiteDb.bak' WITH NORECOVERY , REPLACE , MOVE 'SiteDb_data' to 'G:\MSSQL10.DB2\MSSQL\DATA\SiteDbStandby_SiteDb_data.mdf' , MOVE 'SiteDb_log' to 'J:\MSSQL10.DB2\MSSQL\DATA\SiteDbStandby_SiteDb_log.ndf' [SQLSTATE 01000] (Message 0) Processed 191032 pages for database 'SiteDbStandby', file 'SiteDb_data' on file 1. [SQLSTATE 01000] (Message 4035) Processed 6 pages for database 'SiteDbStandby', file 'SiteDb_log' on file 1. [SQLSTATE 01000] (Message 4035)
RESTORE DATABASE successfully processed 191038 pages in 21.703 seconds (68.768 MB/sec). [SQLSTATE 01000] (Message 3014)
RESTORE LOG SiteDbStandby FROM DISK = '\\SqlBackup\Logs\SiteDb_20120914_231026.BAK' WITH NORECOVERY
RESTORE LOG SiteDbStandby FROM DISK = '\\SqlBackup\Logs\SiteDb_20120915_001019.BAK' WITH NORECOVERY
RESTORE LOG SiteDbStandby FROM DISK = '\\SqlBackup\Logs\SiteDb_20120915_011032.BAK' WITH NORECOVERY
RESTORE LOG SiteDbStandby FROM DISK = '\\SqlBackup\Logs\SiteDb_20120915_021140.BAK' WITH NORECOVERY
RESTORE LOG SiteDbStandby FROM DISK = '\\SqlBackup\Logs\SiteDb_20120915_031053.BAK' WITH NORECOVERY [SQLSTATE 01000] (Message 0) Processed 0 pages for database 'SiteDbStandby', file 'SiteDb_data' on file 1. [SQLSTATE 01000] (Message 4035) Processed 7 pages for database 'SiteDbStandby', file 'SiteDb_log' on file 1. [SQLSTATE 01000] (Message 4035)
RESTORE LOG successfully processed 7 pages in 0.009 seconds (5.588 MB/sec). [SQLSTATE 01000] (Message 3014) Processed 0 pages for database 'SiteDbStandby', file 'SiteDb_data' on file 1. [SQLSTATE 01000] (Message 4035) Processed 0 pages for database 'SiteDbStandby', file 'SiteDb_log' on file 1. [SQLSTATE 01000] (Message 4035)
RESTORE LOG successfully processed 0 pages in 0.009 seconds (0.000 MB/sec). [SQLSTATE 01000] (Message 3014) Processed 0 pages for database 'SiteDbStandby', file 'SiteDb_data' on file 1. [SQLSTATE 01000] (Message 4035) Processed 1229 pages for database 'SiteDbStandby', file 'SiteDb_log' on file 1. [SQLSTATE 01000] (Message 4035)
RESTORE LOG successfully processed 1229 pages in 0.196 seconds (48.965 MB/sec). [SQLSTATE 01000] (Message 3014) Processed 0 pages for database 'SiteDbStandby', file 'SiteDb_data' on file 1. [SQLSTATE 01000] (Message 4035) Processed 3 pages for database 'SiteDbStandby', file 'SiteDb_log' on file 1. [SQLSTATE 01000] (Message 4035)
RESTORE LOG successfully processed 3 pages in 0.013 seconds (1.277 MB/sec). [SQLSTATE 01000] (Message 3014) Processed 0 pages for database 'SiteDbStandby', file 'SiteDb_data' on file 1. [SQLSTATE 01000] (Message 4035) Processed 0 pages for database 'SiteDbStandby', file 'SiteDb_log' on file 1. [SQLSTATE 01000] (Message 4035)
RESTORE LOG successfully processed 0 pages in 0.009 seconds (0.000 MB/sec). [SQLSTATE 01000] (Message 3014)
use master restore database SiteDbStandby with recovery [SQLSTATE 01000] (Message 0)
RESTORE DATABASE successfully processed 0 pages in 4.360 seconds (0.000 MB/sec). [SQLSTATE 01000] (Message 3014) use SiteDbStandby ALTER AUTHORIZATION ON DATABASE::SiteDbStandby TO sa ALTER DATABASE SiteDbStandby SET COMPATIBILITY_LEVEL = 100 [SQLSTATE 01000] (Message 0). The step succeeded.
So, the correct order is 11PM of the previous day, 12AM of the current day, 1AM, 2AM, and 3AM of the current day.
All the logs exist in their share folder directory. Everything looks normal.
Do you happen to think of an idea why did the job fail?
Thanks in advance,
Roni.
We added ORDER BY clause to the RESTORE LOG dynamic query.
This made sure the correct restore log order will be used.