Restore Log takes many hours to fail

reinisbreinisb Posts: 17
edited February 13, 2013 12:02AM in SQL Backup Previous Versions
Hi,

We have a daily log restore to a secondary database. For one reason or another, we have problems getting all the user connections to be automatically disconnected before the restore starts and so sometimes we get the restore failing with the error 1010 "could not get exclusive access to the database".

The weird thing is, the restore log attempts to start at 9.30pm, but it takes all the way until 4.15am before the job actually fails. It seems that redgate doesn't realize for 7 hours that it can't start the restore.

Why does it take so long for it to report a failure?

It's kind of a bummer because if it failed within 20mins of starting, I would still be awake to manually restart it!

Any thoughts? I'm actually using SQL Backup 6.5 (sorry i know this is the SQL 7 forum - couldn't see one for 6.5).

Thanks,

Reinis
· Share on Twitter

Comments

  • peteypetey Posts: 2,358 New member
    Is the secondary database read-only, or read-write?
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • reinisbreinisb Posts: 17
    Standy/Read-only because it's the log shipping target.

    Reinis
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    Could you please post the contents of the SQL Backup log file for the restore process that failed? The default folder where the logs are stored is C:\Documents and Settings\All Users\Application Data\Red Gate\SQL Backup\Log\<instance name> on Windows 2003 and older, and C:\ProgramData\Red Gate\SQL Backup\Log\<instance name> on Windows Vista and newer.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • reinisbreinisb Posts: 17
    Here is the log. The names have been changed to protect the innocent. javascript:emoticon(':roll:') Failed_LS is the target database for the restore, and server2 is the Windows Server 2003 the instance is on.

    I included only a partial list of the connections that were listed because I didn't want to go through changing all of them. There are a number that are shown as connected to the database we are trying to restore to but immediately before i start the restore I kill all the connections to that database. The connections listed for the restore DB are therefore created in the intervening 6 hours that the restore is failing - i checked the last batch time for all of them.

    If you can figure out why it seems the restore still does not work despite the disconnect_existing, and my kill spids routine that would be a bonus. I've also tried having a trigger on the database to disallow any connections for 5 mins around the time the restore starts and that didn't work either.

    Reinis
    SQL Backup log file 6.5.1.9

    -SQL "RESTORE LOG [Failed_LS] FROM DISK = '\\server2\Failed_LS_Share\LOG_Failed_*.sqb' WITH ERASEFILES = 5, DISCONNECT_EXISTING, FILEOPTIONS = 1, STANDBY = 'I:\Failed_LS\UNDO_Failed_LS.dat', MOVETO = 'J:\Failed_LS\Completed' "
    ERRORS AND WARNINGS


    2/10/2013 9:30:00 PM: Restoring Failed_LS (transaction logs) from:
    2/10/2013 9:30:00 PM: \\server2\Failed_LS_Share\LOG_Failed_20130209220000.sqb

    2/10/2013 9:30:04 PM: ALTER DATABASE [Failed_LS] SET ONLINE RESTORE LOG [Failed_LS] FROM VIRTUAL_DEVICE = 'SQLBACKUP_FF135A4B-697A-4263-B702-0A2FFFF8AEEA', VIRTUAL_DEVICE = 'SQLBACKUP_FF135A4B-697A-4263-B702-0A2FFFF8AEEA01', VIRTUAL_DEVICE = 'SQLBACKUP_FF135A4B-697A-4263-B702-0A2FFFF8AEEA02', VIRTUAL_DEVICE = 'SQLBACKUP_FF135A4B-697A-4263-B702-0A2FFFF8AEEA03', VIRTUAL_DEVICE = 'SQLBACKUP_FF135A4B-697A-4263-B702-0A2FFFF8AEEA04', VIRTUAL_DEVICE = 'SQLBACKUP_FF135A4B-697A-4263-B702-0A2FFFF8AEEA05', VIRTUAL_DEVICE = 'SQLBACKUP_FF135A4B-697A-4263-B702-0A2FFFF8AEEA06' WITH BUFFERCOUNT = 28, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY

    2/11/2013 4:19:40 AM: VDI error 1010: Failed to get the configuration from the server because the timeout interval has elapsed. Check that the SQL Server instance is running, that you have the SQL Server System Administrator server role; and that no other processes are blocking the backup or restore process; or try increasing the value of the VDITimeout registry setting in HKEY_LOCAL_MACHINE\SOFTWARE\Red Gate\SQL Backup\BackupSettingsGlobal\[InstanceName]
    2/11/2013 4:19:40 AM: Also check that the database is not currently in use.
    2/11/2013 4:19:40 AM:
    2/11/2013 4:19:40 AM: SPID Status Login HostName BlkBy DBName Command CPUTime DiskIO LastBatch ProgramName SPID_1 REQUESTID
    2/11/2013 4:19:40 AM:
    2/11/2013 4:19:40 AM: 1 BACKGROUND sa . . RESOURCE MONITOR 1257406 26548 01/25 14:46:54 1 0
    2/11/2013 4:19:40 AM: 2 SUSPENDED sa . . LOG WRITER 2825296 0 01/25 14:46:54 2 0
    2/11/2013 4:19:40 AM: 3 BACKGROUND sa . . master SIGNAL HANDLER 0 0 01/25 14:46:54 3 0
    2/11/2013 4:19:40 AM: 4 BACKGROUND sa . . LOCK MONITOR 31 0 01/25 14:46:54 4 0
    2/11/2013 4:19:40 AM: 5 BACKGROUND sa . . LAZY WRITER 1626859 0 01/25 14:46:54 5 0
    2/11/2013 4:19:40 AM: 6 sleeping sa . . master TASK MANAGER 0 0 01/25 14:46:54 6 0
    2/11/2013 4:19:40 AM: 7 BACKGROUND sa . . master TRACE QUEUE TASK 11765 0 01/25 14:46:54 7 0
    2/11/2013 4:19:40 AM: 8 sleeping sa . . UNKNOWN TOKEN 0 0 01/25 14:46:54 8 0
    2/11/2013 4:19:40 AM: 9 BACKGROUND sa . . master BRKR TASK 0 0 01/25 14:46:54 9 0
    2/11/2013 4:19:40 AM: 10 BACKGROUND sa . . master CHECKPOINT 2473062 97776 01/25 14:46:54 10 0
    2/11/2013 4:19:40 AM: 11 BACKGROUND sa . . master TASK MANAGER 125 38 01/25 14:46:54 11 0
    2/11/2013 4:19:40 AM: 12 BACKGROUND sa . . master BRKR EVENT HNDLR 15 39 01/25 14:46:54 12 0
    2/11/2013 4:19:40 AM: 13 BACKGROUND sa . . master BRKR TASK 0 0 01/25 14:46:54 13 0
    2/11/2013 4:19:40 AM: 14 sleeping sa . . master TASK MANAGER 0 3 01/25 14:46:54 14 0
    2/11/2013 4:19:40 AM: 15 sleeping sa . . master TASK MANAGER 0 0 01/25 14:46:54 15 0
    2/11/2013 4:19:40 AM: 16 sleeping sa . . master TASK MANAGER 0 114 01/25 14:46:54 16 0
    2/11/2013 4:19:40 AM: 17 sleeping sa . . master TASK MANAGER 0 0 01/25 14:46:54 17 0
    2/11/2013 4:19:40 AM: 18 sleeping sa . . master TASK MANAGER 0 0 01/25 14:46:54 18 0
    2/11/2013 4:19:40 AM: 19 sleeping sa . . master TASK MANAGER 0 29 01/25 14:46:54 19 0

    .....................................................

    2/11/2013 4:19:40 AM:
    2/11/2013 4:19:40 AM: SQL error 3013: RESTORE LOG is terminating abnormally.
    2/11/2013 4:19:40 AM: SQL error 3101: Exclusive access could not be obtained because the database is in use.
    · Share on Twitter
  • peteypetey Posts: 2,358 New member
    By default, SQL Backup would only wait 30 seconds for SQL Server to start the restore, before it aborts the process. In this case, it waited almost 7 hours. What is the VDITimeout value in the HKEY_LOCAL_MACHINE\SOFTWARE\Red Gate\SQL Backup\BackupSettingsGlobal\[InstanceName] registry node?
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
    · Share on Twitter
  • reinisbreinisb Posts: 17
    The value is 24576 which would be 6.8 hours (I assume that is in seconds) so it seems to make sense. I have no idea why that would be set to such a high value. I switched it to 30 so we'll see what happens with that.

    Thanks,

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