I recently was working on a customer system where a myriad of bad things had occurred simultaneously that left them in a scenario where their primary database server had corruption of an important database and their DR Log Shipped Secondary server couldn’t be rolled forward due to the Restore job failing with the following type of error:
RESTORE LOG AdventureWorks2014
FROM DISK = ‘D:\SQLBackups\Logs\AdventureWorks2014_LOG_202001021250.trn’
WITH FILE = 1,NORECOVERY, STATS = 10
14 percent processed.
31 percent processed.
49 percent processed.
66 percent processed.
Msg 3203, Level 16, State 1, Procedure s_res_translog_for_database, Line 70
Read on “D:\SQLBackups\Logs\AdventureWorks2014_LOG_202001021250.trn” failed: 38(Reached the end of the file.)
Msg 3013, Level 16, State 1, Procedure s_res_translog_for_database, Line 70
RESTORE LOG is terminating abnormally.
Further log restores on the log shipped secondary, even manually would also get this error:
Msg 4319, Level 16, State 3, Line 1
A previous restore operation was interrupted and did not complete processing on file ‘AdventureWorks2014log’. Either restore the backup set that was interrupted or restart the restore sequence.
Msg 3013, Level 16, State 1, Line 1
RESTORE LOG is terminating abnormally.
Since the log shipped database was multi-terabytes in size, reinitializing it from backup wasn’t an ideal situation, but what other options are there? The key lies in the original error message from log shipping, the file restore of the log reached the end of the file and wasn’t expecting it to be the end of the file. This means one of two things happened:
- Either the log backup file was in flight when the main server crashed and restarted and only a partial backup file was written and then copied over to the log shipped secondary and the restore job tried to restore this broken file (NOTE: This was a theory that I have proven to not be possible as the header would have prevented the restore)
- The backup had already completed and the copy file job was running when the server crashed and the file wasn’t fully copied over to the log shipped secondary and it tried to restore it when the restore job ran, generating the first exception
Comparing the file on the source server to the file on the log shipped secondary revealed that the sizes were in fact different, which means that scenario two from above is most likely what occurred. The backup file on the log shipped secondary was deleted and then the full file was manually copied over to the secondary server. However, when the Restore Job would run, it would still fail with error 4319. Manually applying the file with restore log would also result in:
Msg 4319, Level 16, State 3, Line 1
A previous restore operation was interrupted and did not complete processing on file ‘AdventureWorks2014log’. Either restore the backup set that was interrupted or restart the restore sequence.
Msg 3013, Level 16, State 1, Line 1
RESTORE LOG is terminating abnormally.
It seems totally broken, and then I tried the same file but specifying CONTINUE_AFTER_ERROR since at this point there wasn’t really much risk of doing more harm. I was maybe 50/50 that this might work, but if it didn’t we were going to have to reinitialize from a full backup either way, so it was worth trying as it stood.
RESTORE LOG AdventureWorks2014
FROM DISK = ‘D:\SQLBackups\Logs\AdventureWorks2014_LOG_202001021250.trn’
WITH FILE = 1,NORECOVERY, STATS = 10, CONTINUE_AFTER_ERROR;
The file restored and then the Log Shipping Restore Job immediately resumed normal restore operations of the subsequent files without errors. Since the file was not damaged, this worked and allowed the restore log operation to complete and clear the previous end of file encountered error bit successfully so further restore operations could be applied without errors.
One thought on “Fixing A previous restore operation was interrupted and did not complete processing”
This is another reason to be very careful when using SqlLogShip.exe. Log shipping can be handled in other ways – part of a job might include robocopy for example, which leaves file modified timestamps at 1980-01-01 until the transfer is complete. Checking for that magic number date before attempting to restore the file gives you a better chance of success.
Also, who wants to deal with one or more SQL Agent jobs for every single log shipped database? Several databases can be restored concurrently in a loop using SMO in parallel runspaces.