Log Ship CopyTo function failed silently

• 
  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?

  petey April 03, 2013 00:28

  - 0 +
• 
  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

  shu lee April 03, 2013 22:32

  - 0 +
• 
  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.

  petey April 03, 2013 22:38

  - 0 +
• 
  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

  shu lee April 03, 2013 22:45

  - 0 +
• 
  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 >= ''2013-04-02 11:15:00'' 
    AND b.copyend <= ''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.

  petey April 03, 2013 22:54

  - 0 +
• 
  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

  shu lee April 03, 2013 23:05

  - 0 +
• 
  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 >= ''2013-04-02 11:15:00'' 
    AND b.copyend <= ''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?

  petey April 03, 2013 23:25

  - 0 +
• 
  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

  shu lee April 03, 2013 23:44

  - 0 +
• 
  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?

  petey April 03, 2013 23:53

  - 0 +
• 
  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

  shu lee April 04, 2013 00:08

  - 0 +
• 
  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)?

  petey April 04, 2013 02:08

  - 0 +
• 
  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.

  shu lee April 04, 2013 21:50

  - 0 +
• 
  If you run this query now:
  

  EXEC master..sqbdata 'SELECT COUNT(*) FROM backupfiles_copylist WHERE status = ''P'''
  

  
  what is the result?

  petey April 05, 2013 01:01

  - 0 +
• 
  2392

  shu lee April 05, 2013 01:29

  - 0 +
• 
  What does the status = 'p' means?

  shu lee April 05, 2013 19:36

  - 0 +
• 
  '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?

  petey April 07, 2013 04:36

  - 0 +

Add comment

Please sign in to leave a comment.