Log Shipping - two issues

BaldCoder

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: \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: \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.

petey

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.

DonFerguson

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.

Matthew Flatt

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,

DonFerguson

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.

Matthew Flatt

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.

DonFerguson

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?

Matthew Flatt

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''"'

DonFerguson

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

Matthew Flatt

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.

DonFerguson

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.