none
Transaction Log Shipping Fails, randomly

    Question

  • I have set up log shipping from a primary database on one server running SQL 2005, to a secondary server running the same.  The servers are physically identical, running the same Windows Server 2003 and MS SQL 2005.

    It seems to all work fine, for a few hours.  Then it will fail, but not consistently.  Sometimes it will run for 5 hours, sometimes 8 hours, sometimes 15 hours, but will never last more than 24 hours.

    There are no issues with the backup job, no issues with the copy job.  The restore job is what starts out fine, then randomly will throw the error "the log file is too recent to be restored", and it skips the file.  Then the very next time the jobs run, it dies saying "Could not find a log backup file that could be applied to the secondary database".  More info on that message says the log files are no longer in sequence.

    First I assumed there was some other backup job running on the primary database that was creating backup files, thus throwing the transaction logs out of sequence.  But I have made sure that none of my Maintenance Plans and Symantec Backupexec are not touching the primary database, nor the secondary database.  What verifies this is that it seems to fail at random times, not linked to any other backup plans I have scheduled.

    Any suggestions where  I can start troubleshooting this?  I can post up log files and whatnot if that will help.  Just let me know what you need.  Thanks so much in advance!

     

    Monday, April 19, 2010 9:43 PM

Answers

  • Hi,


    In this case, I think the transaction log backup that the restore job used doesn’t match the LSN chain of the secondary server. The transaction log backup gets restored successfully only when there is no LSN chain breakage. To troubleshoot the issue, try the following steps:
    1. Find all the transaction log backups that are created after the last successful restore job in the backup folder from the primary server.
    2. Restore the transaction log backups into the secondary database order by the date manually.
    3. Manually execute the backup, copy and restore job.
    4. If it sill fails, try to recreate the log shipping.

    If there are any more problems, please let me know.
    Thanks.


    ***Xiao Min Tan***Microsoft Online Community***
    Monday, April 26, 2010 4:14 AM

All replies

  • Here is my latest round of log files from the restore job when it failed last night.  I set the entire thing up from scratch yesterday afternoon.  As the logs reveal, it worked fine every hour until 19:10.

     

    Here it is the last time it ran successfully, 18:10

    04/19/2010 18:10:00,LSRestore_SERVER4_CopyCurrent,Unknown,0,SERVER5,LSRestore_SERVER4_CopyCurrent,(Job outcome),,The job succeeded.  The Job was invoked by Schedule 78 (DefaultRestoreJobSchedule).  The last step to run was step 1 (Log shipping restore log job step.).,00:00:01,0,0,,,,0
    04/19/2010 18:10:00,LSRestore_SERVER4_CopyCurrent,Unknown,1,SERVER5,LSRestore_SERVER4_CopyCurrent,Log shipping restore log job step.,,Executed as user: WORLDHEALTHCLUB\SVC-sqlserver. The step succeeded.,00:00:01,0,0,,,,0
    04/19/2010 18:10:00,LSRestore_SERVER4_CopyCurrent,Unknown,1,SERVER5,LSRestore_SERVER4_CopyCurrent,Log shipping restore log job step.,,
    2010-04-19 18:10:00.95    The restore operation was successful. Secondary Database: 'CopyCurrent'<c/> Number of log backup files restored: 1<nl/>
    2010-04-19 18:10:00.95    Deleting old log backup files. Primary Database: 'CopyCurrent'<nl/>
    2010-04-19 18:10:00.95    The restore operation was successful. Secondary ID: 'dc1dc0ae-b256-40b0-a0ea-665b5d626ecf'<nl/>
    2010-04-19 18:10:00.95    ----- END OF TRANSACTION LOG RESTORE     -----<nl/><nl/>Exit Status: 0 (Success),00:00:00,0,0,,,,0

    04/19/2010 18:10:00,LSRestore_SERVER4_CopyCurrent,Unknown,1,SERVER5,LSRestore_SERVER4_CopyCurrent,Log shipping restore log job step.,,
    2010-04-19 18:10:00.87    Restored log backup file. Secondary DB: 'CopyCurrent'<c/> File: '\\server5\e$\sqllogshipping\copycurrent-ls\CopyCurrent_20100420000000.trn',00:00:00,0,0,,,,0

    04/19/2010 18:10:00,LSRestore_SERVER4_CopyCurrent,Unknown,1,SERVER5,LSRestore_SERVER4_CopyCurrent,Log shipping restore log job step.,,
    2010-04-19 18:10:00.37    Starting transaction log restore. Secondary ID: 'dc1dc0ae-b256-40b0-a0ea-665b5d626ecf'<nl/>
    2010-04-19 18:10:00.37    Retrieving restore settings. Secondary ID: 'dc1dc0ae-b256-40b0-a0ea-665b5d626ecf'<nl/>
    2010-04-19 18:10:00.37    Retrieved common restore settings. Primary Server: 'SERVER4'<c/> Primary Database: 'CopyCurrent'<c/> Backup Destination Directory: '\\server5\e$\sqllogshipping\copycurrent-ls'<c/> File Retention Period: 480 minute(s)<nl/>

    2010-04-19 18:10:00.37    Retrieved database restore settings. Secondary Database: 'CopyCurrent'<c/> Restore Delay: 5<c/> Restore All: True<c/> Restore Mode: Standby<c/> Disconnect Users: True<c/> Last Restored File: \\server5\e$\sqllogshipping\copycurrent-ls\CopyCurrent_20100419230007.trn<c/> Block Size: Not Specified<c/> Buffer Count: Not Specified<c/> Max Transfer Size: Not Specified<nl/>

    2010-04-19 18:10:00.41    Disconnecting users. Secondary DB: 'CopyCurrent',00:00:00,0,0,,,,0
    04/19/2010 18:10:00,LSRestore_SERVER4_CopyCurrent,Unknown,1,SERVER5,LSRestore_SERVER4_CopyCurrent,Log shipping restore log job step.,,Microsoft (R) SQL Server Log Shipping Agent<nl/>[Assembly Version = 9.0.242.0<c/> File Version = 9.00.4035.00]<nl/>c Microsoft Corp. All rights reserved.<nl/><nl/>
    2010-04-19 18:10:00.31    ----- START OF TRANSACTION LOG RESTORE   -----,00:00:00,0,0,,,,0

    =======================================================================

     

    And now the very next time the job runs, an hour later, it fails saying the log file is too recent to apply

     

    04/19/2010 19:10:00,LSRestore_SERVER4_CopyCurrent,Error,0,SERVER5,LSRestore_SERVER4_CopyCurrent,(Job outcome),,The job failed.  The Job was invoked by Schedule 78 (DefaultRestoreJobSchedule).  The last step to run was step 1 (Log shipping restore log job step.).,00:00:01,0,0,,,,0

    04/19/2010 19:10:00,LSRestore_SERVER4_CopyCurrent,Error,1,SERVER5,LSRestore_SERVER4_CopyCurrent,Log shipping restore log job step.,,Executed as user: WORLDHEALTHCLUB\SVC-sqlserver. The step failed.,00:00:01,0,0,,,,0

    04/19/2010 19:10:00,LSRestore_SERVER4_CopyCurrent,Unknown,1,SERVER5,LSRestore_SERVER4_CopyCurrent,Log shipping restore log job step.,,
    2010-04-19 19:10:01.36    *** Error: Could not find a log backup file that could be applied to secondary database 'CopyCurrent'.(Microsoft.SqlServer.Management.LogShipping) ***<nl/>
    2010-04-19 19:10:01.36    Deleting old log backup files. Primary Database: 'CopyCurrent'<nl/>
    2010-04-19 19:10:01.36    The restore operation completed with errors. Secondary ID: 'dc1dc0ae-b256-40b0-a0ea-665b5d626ecf'<nl/>
    2010-04-19 19:10:01.36    ----- END OF TRANSACTION LOG RESTORE     -----<nl/><nl/>Exit Status: 1 (Error),00:00:01,0,0,,,,0

    04/19/2010 19:10:00,LSRestore_SERVER4_CopyCurrent,Unknown,1,SERVER5,LSRestore_SERVER4_CopyCurrent,Log shipping restore log job step.,,
    2010-04-19 19:10:01.34    Skipped log backup file. Secondary DB: 'CopyCurrent'<c/> File: '\\server5\e$\sqllogshipping\copycurrent-ls\CopyCurrent_20100419230007.trn',00:00:01,0,0,,,,0

    04/19/2010 19:10:00,LSRestore_SERVER4_CopyCurrent,Unknown,1,SERVER5,LSRestore_SERVER4_CopyCurrent,Log shipping restore log job step.,,
    2010-04-19 19:10:01.23    *** Error: The file '\\server5\e$\sqllogshipping\copycurrent-ls\CopyCurrent_20100420010000.trn' is too recent to apply to the secondary database 'CopyCurrent'.(Microsoft.SqlServer.Management.LogShipping) ***<nl/>
    2010-04-19 19:10:01.23    *** Error: The log in this backup set begins at LSN 388579000000005500001<c/> which is too recent to apply to the database. An earlier log backup that includes LSN 388579000000001600001 can be restored.<nl/>RESTORE LOG is terminating abnormally.(.Net SqlClient Data Provider) ***<nl/>
    2010-04-19 19:10:01.30    Searching for an older log backup file. Secondary Database: 'CopyCurrent'<nl/>
    2010-04-19 19:10:01.33    Skipped log backup file. Secondary DB: 'CopyCurrent'<c/> File: '\\server5\e$\sqllogshipping\copycurrent-ls\CopyCurrent_20100420000000.trn',00:00:01,0,0,,,,0

    04/19/2010 19:10:00,LSRestore_SERVER4_CopyCurrent,Unknown,1,SERVER5,LSRestore_SERVER4_CopyCurrent,Log shipping restore log job step.,,
    2010-04-19 19:10:01.03    Disconnecting users. Secondary DB: 'CopyCurrent',00:00:01,0,0,,,,0

    04/19/2010 19:10:00,LSRestore_SERVER4_CopyCurrent,Unknown,1,SERVER5,LSRestore_SERVER4_CopyCurrent,Log shipping restore log job step.,,Specified,00:00:01,0,0,,,,0

    04/19/2010 19:10:00,LSRestore_SERVER4_CopyCurrent,Unknown,1,SERVER5,LSRestore_SERVER4_CopyCurrent,Log shipping restore log job step.,,Microsoft (R) SQL Server Log Shipping Agent<nl/>[Assembly Version = 9.0.242.0<c/> File Version = 9.00.4035.00]<nl/>c Microsoft Corp. All rights reserved.<nl/><nl/>
    2010-04-19 19:10:00.92    ----- START OF TRANSACTION LOG RESTORE   -----<nl/>
    2010-04-19 19:10:00.98    Starting transaction log restore. Secondary ID: 'dc1dc0ae-b256-40b0-a0ea-665b5d626ecf'<nl/>
    2010-04-19 19:10:00.98    Retrieving restore settings. Secondary ID: 'dc1dc0ae-b256-40b0-a0ea-665b5d626ecf'<nl/>
    2010-04-19 19:10:00.98    Retrieved common restore settings. Primary Server: 'SERVER4'<c/> Primary Database: 'CopyCurrent'<c/> Backup Destination Directory: '\\server5\e$\sqllogshipping\copycurrent-ls'<c/> File Retention Period: 480 minute(s)<nl/>
    2010-04-19 19:10:00.98    Retrieved database restore settings. Secondary Database: 'CopyCurrent'<c/> Restore Delay: 5<c/> Restore All: True<c/> Restore Mode: Standby<c/> Disconnect Users: True<c/> Last Restored File: \\server5\e$\sqllogshipping\copycurrent-ls\CopyCurrent_20100420000000.trn<c/> Block Size: Not Specified<c/> Buffer Count: Not Specified<c/> Max Transfer Size: Not,00:00:01,0,0,,,,0

     

     

    Tuesday, April 20, 2010 2:42 PM
  • Hi,


    Based on the log above, the copy job failed and then the restore job completed with "Could not find a log backup file that could be applied to secondary database." It leads that log shipping is out of synchronization beyond the restore threshold. In this case, examine the job history for the copy job to look for the cause.

    To work around the issue, you could manually execute the backup, copy and restore job to synchronize the log shipping.  Then, to confirm the file restored successfully, run the following query:
    select * from msdb..log_shipping_monitor_history_detail order by log_time desc


    If there are any more problems, please let me know.
    Thanks.


    ***Xiao Min Tan***Microsoft Online Community***
    Wednesday, April 21, 2010 7:31 AM
  • The copy job seems fine.  When I view the job history, it has completed successfully each time it runs.

    I can see the backed up log files in the source directory.  I can see that they have copied from the primary server to the secondary server and are sitting in the correct directory.  I can also manually restore the trn files without issue.  It's just the restore job that seems to fail...

    Thursday, April 22, 2010 8:20 PM
  • Hi,


    In this case, I think the transaction log backup that the restore job used doesn’t match the LSN chain of the secondary server. The transaction log backup gets restored successfully only when there is no LSN chain breakage. To troubleshoot the issue, try the following steps:
    1. Find all the transaction log backups that are created after the last successful restore job in the backup folder from the primary server.
    2. Restore the transaction log backups into the secondary database order by the date manually.
    3. Manually execute the backup, copy and restore job.
    4. If it sill fails, try to recreate the log shipping.

    If there are any more problems, please let me know.
    Thanks.


    ***Xiao Min Tan***Microsoft Online Community***
    Monday, April 26, 2010 4:14 AM
  • I have no issues sequentially restoring each transaction log manually.

     

    thus far I've narrowed it down to something specific with the source database I'm working with.  Because I've set up transaction log shipping with a different source database, but using the exact same job settings, and it is working flawlessly.

    Wednesday, May 05, 2010 9:48 PM
  • What did you do to correct the problem. I am having the same problem.
    Wednesday, January 26, 2011 5:26 PM
  • How did you fix this problem. I am having exact same problem and cannot figure out why this is happening for last 1 week. Thanks Sonali

    RPSAdmin

    Friday, December 07, 2012 8:51 PM