Log Shipping - two issues

BaldCoderBaldCoder Posts: 7
edited November 26, 2008 1:08PM in SQL Backup Previous Versions
I have Log Shipping set up for one of our databases and I have a couple of issues that continue to cause problems.

1. The Restore job often fails to pickup the backup files in the correct sequence if there are several files waiting. It reports failure with incorrect LSN. To date I have not found a way of making the restore process work flawlessly.

2. Occassionally the Backup reports a failure like below. It states that BACKUP LOG successfully processed pages, unfortunately the restore fails because the LOG BACKUP file is corrupt. This necessitates a reseed of the Log Shipping.

SQL Backup log file 5.2.0.2825
8/13/2008 5:45:01 AM: Backing up CUST_A_DATA (transaction log) to:
8/13/2008 5:45:01 AM: D:\CUST_A_DATA_Backup\LOG\LOG_CUST_A_DATA_20080813054501.sqb

8/13/2008 5:45:01 AM: BACKUP LOG [CUST_A_DATA] TO DISK = 'D:\CUST_A_DATA_Backup\LOG\<TYPE>_<DATABASE>_<DATETIME YYYYmmddhhnnss>.sqb' WITH NAME = '<AUTO>', DESCRIPTION = '<AUTO>', VERIFY, ERASEFILES = 30, MAILTO_ONERROR = 'dba@mycompany.com', COPYTO = '\\servername\Remote_Backups\CUST_A_DATA\LOGSHIPTO', COMPRESSION = 1

8/13/2008 5:45:02 AM: Thread 0 error:
Error 620: Error writing to backup file(s).
8/13/2008 5:45:02 AM: Warning 210: Thread 0 warning:
Warning 210: Error writing to backup file: D:\CUST_A_DATA_Backup\LOG\LOG_CUST_A_DATA_20080813054501.sqb
Warning: System error 87 (The parameter is incorrect) Processed 4513 pages for database 'CUST_A_DATA', file 'CUST_A_DATA_Log' on file 1.
BACKUP LOG successfully processed 4513 pages in 1.327 seconds (27.854 MB/sec).


Please can anyone cast any light on these two issues?

Many Thanks,
Baldcoder.
· Share on Twitter

Comments

  • peteypetey Posts: 2,358 New member
    The error during your backup is a known issue, and was fixed in version 5.3. I would suggest updating to that version. That error is also a cause of the LSN sorting issue.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • DonFergusonDonFerguson Posts: 202 Silver 5
    I had the same problem and am using 5.3.0.178. The problem started when the restore job got hung up. After restarting the SQL Agent I started getting the out of sequence problem with multiple log files in the same source folder. The only way I was able to resolve it was by taking the sql agent restore command into a query window and by changing the filename_*.sqb values to match the correct next file name that needed to be restored. Doing that a few times resolved the issue, but it was tedious.

    Clearly this bug isn't completely fixed.
    · Share on Twitter
  • Matthew FlattMatthew Flatt Posts: 255 Bronze 5
    Hi DonMan,

    The issue which was fixed in SQL Backup 5.3 was the following :

    Warning: System error 87 (The parameter is incorrect)

    Are you encountering this in your backups using the 5.3 Server Components? If so could you please paste the log file.

    If it was just your LSNs being out of sync for the restore, were there any messages regarding reading the Header/LSN information and this failing?

    Thanks,
    Matthew Flatt
    Redgate Foundry
    · Share on Twitter
  • DonFergusonDonFerguson Posts: 202 Silver 5
    Here is one of many:

    SQL Backup log file 5.3.0.178

    -SQL "RESTORE LOG [MyDB] FROM DISK = '\\MyHost\LogShare\MySrcHost\MyInstance\MyDB\LOG_MyDB_*.sqb' WITH MAILTO_ONERROR = 'i.s.dba@mydomain.com;i.s.backupadmins@mydomain.com', ERASEFILES = 72h, FILEOPTIONS = 1, STANDBY = 'E:\LogShare\MySrcHost\MyInstance\MyDB\UNDO_MyDB.dat', MOVETO = 'E:\LogShipping\MySrcHost\MyInstance\MyDB' "
    ERRORS AND WARNINGS


    11/12/2008 11:28:00 AM: Warning 170: Log files are not in sequence: 'LOG_MyDB_20081111204500.sqb' and 'LOG_MyDB_20081111203500.sqb'
    11/12/2008 11:28:00 AM: Warning 170: Log files are not in sequence: 'LOG_MyDB_20081111205500.sqb' and 'LOG_MyDB_20081111211500.sqb'
    11/12/2008 11:28:00 AM: Warning 170: Log files are not in sequence: '' and 'LOG_MyDB_20081111210500.sqb'
    11/12/2008 11:28:00 AM: Warning 170: Log files are not in sequence: 'LOG_MyDB_20081111212500.sqb' and 'LOG_MyDB_20081111220500.sqb'
    11/12/2008 11:28:00 AM: Warning 170: Log files are not in sequence: 'LOG_MyDB_20081111222500.sqb' and 'LOG_MyDB_20081111213500.sqb'
    11/12/2008 11:28:00 AM: Warning 170: Log files are not in sequence: 'LOG_MyDB_20081111234500.sqb' and 'LOG_MyDB_20081112005500.sqb'
    11/12/2008 11:28:00 AM: Warning 170: Log files are not in sequence: '' and 'LOG_MyDB_20081112002500.sqb'
    11/12/2008 11:28:00 AM: Warning 170: Log files are not in sequence: 'LOG_MyDB_20081112003500.sqb' and 'LOG_MyDB_20081112011500.sqb'
    11/12/2008 11:28:00 AM: Warning 170: Log files are not in sequence: '' and 'LOG_MyDB_20081112010500.sqb'
    11/12/2008 11:28:00 AM: Warning 170: Log files are not in sequence: 'LOG_MyDB_20081112012500.sqb' and 'LOG_MyDB_20081112032500.sqb'
    11/12/2008 11:28:00 AM: Warning 170: Log files are not in sequence: 'LOG_MyDB_20081112022500.sqb' and 'LOG_MyDB_20081112013500.sqb'
    11/12/2008 11:28:00 AM: Restoring MyDB (transaction logs) on MyInstance instance from:
    11/12/2008 11:28:00 AM: \\MyHost\LogShare\MySrcHost\MyInstance\MyDB\LOG_MyDB_20081111204500.sqb

    11/12/2008 11:28:00 AM: RESTORE LOG [MyDB] FROM VIRTUAL_DEVICE = 'SQLBACKUP_AFACABD5-CFE0-4FAC-AECD-9894AB1137B8' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , STANDBY = 'E:\LogShare\MySrcHost\MyInstance\MyDB\UNDO_MyDB.dat'

    11/12/2008 11:28:00 AM: SQL Server error

    SQL error 3013: SQL error 3013: RESTORE LOG is terminating abnormally.
    SQL error 4305: SQL error 4305: The log in this backup set begins at LSN 48598000000181700001, which is too recent to apply to the database. An earlier log backup that includes LSN 48598000000178100001 can be restored.
    11/12/2008 11:28:01 AM: Mail sent successfully to: dba@mydomain.com;backupadmins@mydomain.com


    Please note that all the files were there but since the restore order was incorrect, it threw an error.
    · Share on Twitter
  • Matthew FlattMatthew Flatt Posts: 255 Bronze 5
    Do you have the SQL Backup log files for the backup jobs on each of these files?

    It looks like the LSN information isn't being written at the time of backup, the log files for the backup job should hold more information.
    Matthew Flatt
    Redgate Foundry
    · Share on Twitter
  • DonFergusonDonFerguson Posts: 202 Silver 5
    The log files of the backups don't seem very helpful. The LSN information is in the sample I posted. Most of the time when there are multiple files in a * wildcard restore. they are indeed restored in the correct order. But sometimes they are not. That makes me wonder how the order to restore them in is sorted. Are they sorted by filename, modify date, create date, or something else at restore time?

    I would hope filename, but if that is the case, then I can't explain why sometimes they are restored in the wrong order. Perhaps they are sorted by the date created. If that is the case, I could imagine how the sequence could get messed up if a the copy order is out of sequence.

    Does version 5.4 resolve the issue?
    · Share on Twitter
  • Matthew FlattMatthew Flatt Posts: 255 Bronze 5
    If SQL Backup is asked to restore multiple files using a wildcard it uses the LSN information from the backup file header to put the backup files in the correct order for restoration.

    If the LSN information can not be read, the files can not be put into the correct order and so the restore process fails.

    Are no error messages recorded in the backup log files pertaining to writing LSN information?

    What are the results of the following when run against the backup files which aren't being ordered correctly?
    EXECUTE MASTER..sqlbackup N'-SQL "RESTORE HEADERONLY FROM DISK = ''C:\Backups\LOG_Northwind.sqb''"'

EXECUTE MASTER..sqlbackup N'-SQL "RESTORE SQBHEADERONLY FROM DISK = ''C:\Backups\LOG_Northwind.sqb''"'
    Matthew Flatt
    Redgate Foundry
    · Share on Twitter
  • DonFergusonDonFerguson Posts: 202 Silver 5
    There were no errors in the backup logs.

    I did examine RESTORE HEADERONLY and RESTORE SQBHEADERONLY options against more recent files where the sequence was out of order and I did find something interesting.

    It turns out that the file that was out of sequence had a matching First LSN: 48619000000934800001 and Last LSN: 48619000000934800001.

    :idea: I believe the problem is that the order is sorted by the Last LSN and not the first LSN. If that is indeed the case, I would consider this a bug.

    I did upgrade to version 5.4 this weekend. Is there any chance that was fixed in 5.4?

    Here is the header information from the backup files along with new restore logs showing the error:

    SQL Backup v5.4.0.55
    Reading file header of "N:\Backups\Log\MyVHost\MyInstance\MyDB\LOG_MyDB_20081121040500.sqb"

    Backup name : Database (MyDB), 11/21/2008 4:05:00 AM
    Description : Backup on 11/21/2008 4:05:00 AM Server: MyPHost\MyInstance Database: MyDB
    Backup type : 2 (Transaction log)
    User name : MyDomain\MyAccount
    Backup start : 11/21/2008 4:10:28 AM
    Backup finish: 11/21/2008 4:10:28 AM

    Server name : MyVHost\MyInstance
    Database name : MyDB
    Database version : 611
    Creation date : 10/24/2008 12:25:03 PM
    Size : 320.000 KB
    Sort order : 52
    Code page : 0
    Machine name : MyVHost
    Collation : SQL_Latin1_General_CP1_CI_AS

    First LSN : 48619000000930600001
    Last LSN : 48619000000934800001
    Checkpoint LSN : 48619000000904800219
    Database backup LSN : 48619000000904800219
    Differential base LSN : NULL

    SQL Backup process ended.

    SQL Backup v5.4.0.55
    Reading file header of "N:\Backups\Log\MyVHost\MyInstance\MyDB\LOG_MyDB_20081121041500.sqb"

    Backup name : Database (MyDB), 11/21/2008 4:15:00 AM
    Description : Backup on 11/21/2008 4:15:00 AM Server: MyPHost\MyInstance Database: MyDB
    Backup type : 2 (Transaction log)
    User name : MyDomain\MyAccount
    Backup start : 11/21/2008 4:17:27 AM
    Backup finish: 11/21/2008 4:17:27 AM

    Server name : MyVHost\MyInstance
    Database name : MyDB
    Database version : 611
    Creation date : 10/24/2008 12:25:03 PM
    Size : 192.000 KB
    Sort order : 52
    Code page : 0
    Machine name : MyVHost
    Collation : SQL_Latin1_General_CP1_CI_AS

    First LSN : 48619000000934800001
    Last LSN : 48619000000934800001
    Checkpoint LSN : 48619000000904800219
    Database backup LSN : 48619000000904800219
    Differential base LSN : NULL

    SQL Backup process ended.

    SQL Backup v5.4.0.55
    Reading file header of "N:\Backups\Log\MyVHost\MyInstance\MyDB\LOG_MyDB_20081121042500.sqb"

    Backup name : Database (MyDB), 11/21/2008 4:25:00 AM
    Description : Backup on 11/21/2008 4:25:00 AM Server: MyPHost\MyInstance Database: MyDB
    Backup type : 2 (Transaction log)
    User name : MyDomain\MyAccount
    Backup start : 11/21/2008 4:25:44 AM
    Backup finish: 11/21/2008 4:25:44 AM

    Server name : MyVHost\MyInstance
    Database name : MyDB
    Database version : 611
    Creation date : 10/24/2008 12:25:03 PM
    Size : 320.000 KB
    Sort order : 52
    Code page : 0
    Machine name : MyVHost
    Collation : SQL_Latin1_General_CP1_CI_AS

    First LSN : 48619000000934800001
    Last LSN : 48619000000936600001
    Checkpoint LSN : 48619000000904800219
    Database backup LSN : 48619000000904800219
    Differential base LSN : NULL

    SQL Backup process ended.


    SQL Backup log file 5.3.0.178

    -SQL "RESTORE LOG [MyDB] FROM DISK = '\\MyRemoteHost\LogShare\MyVHost\MyInstance\MyDB\LOG_MyDB_*.sqb' WITH MAILTO_ONERROR = 'dba@MyDomain.com;backupadmins@MyDomain.com', ERASEFILES = 72h, FILEOPTIONS = 1, STANDBY = 'E:\LogShare\MyVHost\MyInstance\MyDB\UNDO_MyDB.dat', MOVETO = 'E:\LogShipping\MyVHost\MyInstance\MyDB' "
    ERRORS AND WARNINGS


    11/21/2008 4:18:05 AM: Warning 170: Log files are not in sequence: 'LOG_MyDB_20081121041500.sqb' and 'LOG_MyDB_20081121040500.sqb'
    11/21/2008 4:18:05 AM: Restoring MyDB (transaction logs) on MyInstance instance from:
    11/21/2008 4:18:05 AM: \\MyRemoteHost\LogShare\MyVHost\MyInstance\MyDB\LOG_MyDB_20081121041500.sqb

    11/21/2008 4:18:05 AM: RESTORE LOG [MyDB] FROM VIRTUAL_DEVICE = 'SQLBACKUP_D44E7CCF-B9DC-4E33-9B20-B310DF5C39B4' WITH BUFFERCOUNT = 6, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , STANDBY = 'E:\LogShare\MyVHost\MyInstance\MyDB\UNDO_MyDB.dat'

    11/21/2008 4:18:05 AM: SQL Server error

    SQL error 3013: SQL error 3013: RESTORE LOG is terminating abnormally.
    SQL error 4305: SQL error 4305: The log in this backup set begins at LSN 48619000000934800001, which is too recent to apply to the database. An earlier log backup that includes LSN 48619000000930600001 can be restored.
    11/21/2008 4:18:06 AM: Mail sent successfully to: dba@MyDomain.com;backupadmins@MyDomain.com
    · Share on Twitter
  • Matthew FlattMatthew Flatt Posts: 255 Bronze 5
    Thank you for the info.

    There is no fix for this in SQL Backup 5.4.

    Unfortunately it doesn't matter if we were to sort the files by the first or last LSN, in this scenario an error would be thrown either way.

    I have raised a bug/feature request for this so if two files are found with the same Last LSN, the first LSNs are also checked.

    To workaround this at the moment you would have to restore each file individually.

    Thank you for bringing this to our attention.
    Matthew Flatt
    Redgate Foundry
    · Share on Twitter
  • DonFergusonDonFerguson Posts: 202 Silver 5
    Yes,

    Sorting by first and last lsn or by filename would resolve the issue. Until then, I will need to continue to run the manual work around when this becomes an issue. Fortunately it doesn't happen too often.

    Two things need to occur for this to happen:

    1. Multiple files need to get bunched up together between restores.
    2. At least one of the files doesn't have any transactional activity in it, causing the First and Last LSNs to match.

    I suppose I could create a job that writes a dummy transaction in the databases between transaction log backups to prevent scenario 2 from occurring, but hopefully this will get fixed soon.

    Thanks.
    · Share on Twitter
Sign In or Register to comment.