Log Ship CopyTo function failed silently

shu lee · April 2, 2013 12:19AM

I am trying to use SQL backup 6.4.0.56 to setup log shipping between 2 servers. The source server is running Windows 2008 R2 and SQL server 2005. The destination server is running Windows 2003 and SQL server 2005.

Using the SQL Backup GUI I setup the "Backup location" to a local folder on the source server and the "Network copy location" to a share on the destination server. I clicked on the 'Test' button under 'Network copy location' and the GUI displayed the "Server has the correct permissions" text. The destination share has all permissions available to 'Everyone'.

From the SQL Backup GUI on the source server, I goto the jobs tab and I right click on the log shipping job and 'start' it. The GUI reports a successful run and I verify 1) the tran log was created on the local folder, 2) the tran log WAS NOT copied to the destination folder.

Viewing the history of the backup log ship job from SSMS indicates the log ship backup job completed successfully. Looking at the SQL Backup log, it also indicates the job completed successfully.

Here's the backup tsql generated by the SQL Backup GUI -

EXECUTE master..sqlbackup '-SQL "BACKUP LOG [TestLogShip] TO DISK = ''E:\sqlserver2005\Backups\LogsForLogShip\<TYPE>_<DATABASE>_<DATETIME YYYYmmddhhnnss>.sqb'' WITH ERASEFILES = 14, ERASEFILES_REMOTE = 14, FILEOPTIONS = 4, DISKRETRYINTERVAL = 30, DISKRETRYCOUNT = 10, COPYTO = ''\\192.168.100.215\LogsForLogShipSlave'', THREADCOUNT = 7"', @errorcode OUT, @sqlerrorcode OUT;

I also ran this with SSMS and got no errors.

Any ideas why the tran log was not copied to the destination share?

Thanks,

-Shu

petey · April 3, 2013 12:28AM

Could you please run the following in SSMS:

EXEC master..sqbdata 'SELECT a.name, b.copystart, b.copyend, b.message 
FROM backupfiles_copylist a 
INNER JOIN backupfiles_copylist_log b ON a.ID = b.copylist_id 
INNER JOIN backuphistory c ON a.backup_id = c.id 
WHERE c.dbname = 'TestLogShip''
AND b.message IS NOT NULL 
ORDER BY a.ID DESC, b.attempt DESC'

and see if it provides any useful information?

shu lee · April 3, 2013 10:32PM

Thanks Peter.

Here are the top 3 records returned from that query:

name copystart copyend message
E:\sqlserver2005\Backups\LogsForLogShip\LOG_TestLogShip_20130402111500.sqb 2013-04-03 10:54:53.000 2013-04-03 10:54:53.000
E:\sqlserver2005\Backups\LogsForLogShip\LOG_TestLogShip_20130402110000.sqb 2013-04-03 10:54:53.000 2013-04-03 10:54:53.000
E:\sqlserver2005\Backups\LogsForLogShip\LOG_TestLogShip_20130402101500.sqb 2013-04-03 09:57:34.000 2013-04-03 09:57:34.000

The message column is empty.

Ok. This might sound odd, but it appears to me the file copying occurs almost 24 hour later. Looking at the 1st record above, note from the 1st filename that the log-create datetime is 2013-04-02-11:15:00. Then note that file's copyStart time is 2013-04-03 10:54:53. Does that sound right?

Thanks,

-Shu

petey · April 3, 2013 10:38PM

Could you please post the results of running the following:

EXEC master..sqbdata 'SELECT a.name, b.attempt, b.copystart, b.copyend, b.message 
FROM backupfiles_copylist a 
INNER JOIN backupfiles_copylist_log b ON a.ID = b.copylist_id 
INNER JOIN backuphistory c ON a.backup_id = c.id 
WHERE a.name = ''E:\sqlserver2005\Backups\LogsForLogShip\LOG_TestLogShip_20130402111500.sqb''
ORDER BY b.attempt DESC'

I would like to see how many attempts had been made to copy that file, and from when the attempts started.

Thanks.

shu lee · April 3, 2013 10:45PM

Thanks Peter.

Here's the result of your query:

E:\sqlserver2005\Backups\LogsForLogShip\LOG_TestLogShip_20130402111500.sqb 1 2013-04-03 10:54:53.000 2013-04-03 10:54:53.000

Seems like a normal 1 attempt.

How much of the file copying depends on msdb? Either before or after the copy?

-Shu

petey · April 3, 2013 10:54PM

Could you please run the following?

EXEC master..sqbdata 'SELECT a.name, b.attempt, b.copystart, b.copyend, b.message 
FROM backupfiles_copylist a 
INNER JOIN backupfiles_copylist_log b ON a.ID = b.copylist_id 
WHERE b.copystart &gt;= ''2013-04-02 11:15:00'' 
  AND b.copyend &lt;= ''2013-04-03 10:54:00'' 
ORDER BY a.name, b.attempt'

Were there a lot of copying activity going on during the specified interval?

How much of the file copying depends on msdb? Either before or after the copy?

None. Once the backup completes, the file name is placed in the backupfiles_copylist table, and is queued for copying.

shu lee · April 3, 2013 11:05PM

There should be no other activities between these 2 servers at the time of the log copying. I should add that for a sanity check, at one point I added a 2nd step to the log shipping job that calls robocopy to copy the logs and that copies the logs to the secondary server without issues. One issue with robocopy is I haven't figured out how to only copy the logs that are new.

I ask about the msdb because my last DBA neglected to setup a job to clean up msdb and as a result the msdb has entries going back to 2011. Because of that, it could take a long time to delete entries out of msdb.

-Shu

petey · April 3, 2013 11:25PM

What I meant was if you ran the following script:

EXEC master..sqbdata 'SELECT a.name, b.attempt, b.copystart, b.copyend, b.message 
FROM backupfiles_copylist a 
INNER JOIN backupfiles_copylist_log b ON a.ID = b.copylist_id 
WHERE b.copystart &gt;= ''2013-04-02 11:15:00'' 
  AND b.copyend &lt;= ''2013-04-03 10:54:00'' 
ORDER BY a.name, b.attempt'

are there a lot of entries returned?

I ask about the msdb because my last DBA neglected to setup a job to clean up msdb and as a result the msdb has entries going back to 2011. Because of that, it could take a long time to delete entries out of msdb.

The copying task is independent of the msdb deletion task. Is SQL Backup set up to delete old entries from msdb now?

shu lee · April 3, 2013 11:44PM

Oops. My bad. I totally missed your query at the top of the last post. I ran the query just now and there are over 6000 records returned. Most of the records are copying tran logs of the 'real' databases to a network drive. The only traffic between the 2 servers are the copying of the TestLogShip tran logs.

SQL Backup is not currently setup to delete the old entries from msdb.

-Shu

petey · April 3, 2013 11:53PM

SQL Backup gives priority to older files when copying files. Were the files that were being copied over during that interval older than the transaction log backup file for TestLogShip created on 2 April 2013 11:15 AM?

shu lee · April 4, 2013 12:08AM

Possibly. The other tran logs are taken every 30 minutes and there should be about 40 of them every 30 minutes. These tran logs are compressed so they aren't that big that they take that long to copy. The 1 tran log for TestLogShip are taken every 15 minutes.

-Shu

petey · April 4, 2013 2:08AM

Looking at the results of the last query you ran, were the files that were being copied during that interval all older than the backup file you created and expected to be copied at that time (E:\sqlserver2005\Backups\LogsForLogShip\LOG_TestLogShip_20130402111500.sqb)?

shu lee · April 4, 2013 9:50PM

No, not all files are older than the expected log ship backup file. But I did notice that all my other files exhibit the same delay behavior, meaning the other tran logs are also getting copied almost a day later. I am also seeing some 'COPYTO error:' messages with some of the records returned from this query.

petey · April 5, 2013 1:01AM

If you run this query now:

EXEC master..sqbdata 'SELECT COUNT&#40;*&#41; FROM backupfiles_copylist WHERE status = ''P'''

what is the result?

shu lee · April 5, 2013 1:29AM

2392

shu lee · April 5, 2013 7:36PM

What does the status = 'p' means?

petey · April 7, 2013 4:36AM

'P' means pending. It looks like at any one point, there are 2300+ files waiting to be copied, and is probably increasing over time as more files get queued, and SQL Backup isn't copying them over fast enough. Since SQL Backup will copy older files first, this explains why the new backup files are only getting copied almost 24 hours later.

If you look at the files that have already been copied (with a status of 'S'), how long does it take on average to copy a single file?

Log Ship CopyTo function failed silently

Comments

Product Learning

Community Forums

Events & Friends

Simple Talk