RESTORE...LATEST_ALL fails

meastlandmeastland Posts: 47
We have a process to periodically restore production databases to a development server using the RESTORE...LATEST_ALL command with SQL Backup Pro. This process has been in place and running fine for nearly a month. However, the last two consecutive jobs have ended with the following error for the same database restore:

Thread 0 error:
Process terminated unexpectedly. Error code: -2139684861 (The api was waiting and the timeout interval had elapsed.)


The full backup is restored successfully, but the error is generated before the most recent differential restore is attempted. I am also using the LOG_ONERRORONLY parameter, but no log is being generated in the SQL Backup log folder on the destination server.

The restoring server is currently running version 6.4.0.56 with the 6.4.0.1014 patch applied.

I can't reproduce the error at will, so I would appreciate any feedback or suggestions.

Thanks in advance.

Comments

  • peteypetey Posts: 2,358 New member
    Could you please post the contents of the log 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.

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • Peter,

    As I stated in the original post, no log file was created, even though the LOG_ONERRORONLY parameter was used in the SQL Backup command.

    One thing I can tell you is that I needed to reboot the restoring server yesterday afternoon for another reason, and the restore process completed successfully this morning after failing for two consecutive days. I know that doesn't give you any diagnostic information, but I figured it was worth mentioning.

    Thanks,

    -Mike
  • peteypetey Posts: 2,358 New member
    Sorry, missed the part about the LOG_ONERRORONLY. Can you run your jobs without that parameter, so that if it fails again, we at least have a log to examine?

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • Peter,

    I will remove the LOG_ONERRORONLY parameter from the restore job on the destination server. If / when the job fails again, I'll update this thread.

    Thanks again for your time.

    Regards,

    -Mike Eastland
  • Peter,

    The restore process failed again this morning with the same error for the same database. Unfortunately, the log file that was generated doesn't seem to contain much additional information. Here is the contents of the log file in its entirety:

    SQL Backup log file 6.4.0.1014

    -SQL "RESTORE DATABASE [Resales4] FROM DISK = '\\uhlig.com\prod\SQLBackups\*Resales4*.sqb' LATEST_ALL WITH DISCONNECT_EXISTING, DISKRETRYCOUNT = 10, DISKRETRYINTERVAL = 30, MAILTO_ONERRORONLY = '****', PASSWORD = 'XXXXXXXXXX', RECOVERY, REPLACE "


    ERRORS AND WARNINGS


    4/26/2011 7:01:38 AM: Restoring Resales4 (database) from:
    4/26/2011 7:01:38 AM: \\uhlig.com\prod\SQLBackups\FULL_Resales4_20110426_020158_01.sqb
    4/26/2011 7:01:38 AM: \\uhlig.com\prod\SQLBackups\FULL_Resales4_20110426_020158_02.sqb

    4/26/2011 7:01:39 AM: ALTER DATABASE [Resales4] SET ONLINE RESTORE DATABASE [Resales4] FROM VIRTUAL_DEVICE = 'SQLBACKUP_CD6523F1-6602-4913-B5F8-47A982752801', VIRTUAL_DEVICE = 'SQLBACKUP_CD6523F1-6602-4913-B5F8-47A98275280101' WITH BUFFERCOUNT = 12, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576 , NORECOVERY, REPLACE

    4/26/2011 7:15:17 AM: Thread 0 error:
    Process terminated unexpectedly. Error code: -2139684861 (The api was waiting and the timeout interval had elapsed.)
    4/26/2011 7:15:17 AM:
    4/26/2011 7:15:19 AM: Processed 2838336 pages for database 'Resales4', file 'Resales4_Data' on file 1.
    4/26/2011 7:15:19 AM: Processed 1 pages for database 'Resales4', file 'Resales4_Log' on file 1.
    4/26/2011 7:15:19 AM: RESTORE DATABASE successfully processed 2838337 pages in 817.590 seconds (28.439 MB/sec).
    4/26/2011 7:15:20 AM: Mail sent successfully to: ****

    I'm not sure if this is relevant or not, but I did notice one other symptom of this problem when the process failed this morning. When I query msdb.dbo.backupmediafamily for the physical device name, the entry for the database where the restore failed shows the sqlBackup VIRTUAL_DEVICE name, while the entries for the databases where the restore succeeds show the actual physical path to the *.sqb files used for the restore process. So it would appear that the process is timing out before that update to the msdb backup tables can occur.

    Database Restore Type Physical File Name Restore Date Recovery State
    Utility Transaction Log \\uhlig.com\prod\SQLBackups\LOG_Utility_20110426_070538.sqb 4/26/11 7:21 Recovery
    Utility Transaction Log \\uhlig.com\prod\SQLBackups\LOG_Utility_20110426_065035.sqb 4/26/11 7:21 NoRecovery
    Utility Transaction Log \\uhlig.com\prod\SQLBackups\LOG_Utility_20110426_063534.sqb 4/26/11 7:20 NoRecovery
    Utility Transaction Log \\uhlig.com\prod\SQLBackups\LOG_Utility_20110426_062035.sqb 4/26/11 7:20 NoRecovery
    Utility Differential \\uhlig.com\prod\SQLBackups\DIFF_Utility_20110426_060905.sqb 4/26/11 7:20 NoRecovery
    Utility Full \\uhlig.com\prod\SQLBackups\FULL_Utility_20110426_023019.sqb 4/26/11 7:16 NoRecovery
    Resales4 Full SQLBACKUP_CD6523F1-6602-4913-B5F8-47A982752801 4/26/11 7:01 NoRecovery
    Resales4 Full SQLBACKUP_CD6523F1-6602-4913-B5F8-47A98275280101 4/26/11 7:01 NoRecovery


    Anyway, please let me know if you have any suggestions for next steps in the troubleshooting process.

    Thanks,

    -Mike
  • peteypetey Posts: 2,358 New member
    It's a strange situation indeed. The restore process itself seems to have completed, as SQL Server is reporting the restore statistics, and has even created entries in the backup/restore history tables for that restore. However, during the passing of the uncompressed data from SQL Backup to SQL Server, there was an error, but it didn't seem to have affected the restore.

    SQL Backup uses the SQL Server VDI library to perform backups and restores. Could you please check if any errors were logged by the VDI component? If you are using SQL Server 2000, the errors were logged in a file named vdi.log, in the instance's log directory. If you are using SQL Server 2005 or newer, errors are logged in the Windows Event log. The Source component is identified as SQLVDI. It might also be worth checking the SQL Server log to see if any errors were logged.

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • Peter,

    Thanks for the suggestions. I see the following SQLVDI errors in the Application Log which seem to correspond with the time that the restore failed:

    Log Name: Application
    Source: SQLVDI
    Date: 4/26/2011 7:15:19 AM
    Event ID: 1
    Task Category: None
    Level: Error
    Keywords: Classic
    User: N/A
    Computer: SQLDEV.uhlig.com
    Description:
    SQLVDI: Loc=CVDS::Close. Desc=Open devices!. ErrorCode=(0). Process=2008. Thread=2196. Client. Instance=. VD=Global\SQLBACKUP_CD6523F1-6602-4913-B5F8-47A982752801_SQLVDIMemoryName_0.

    Log Name: Application
    Source: SQLVDI
    Date: 4/26/2011 7:15:19 AM
    Event ID: 1
    Task Category: None
    Level: Error
    Keywords: Classic
    User: N/A
    Computer: SQLDEV.uhlig.com
    Description:
    SQLVDI: Loc=SignalAbort. Desc=Client initiates abort. ErrorCode=(0). Process=2008. Thread=2196. Client. Instance=. VD=Global\SQLBACKUP_CD6523F1-6602-4913-B5F8-47A982752801_SQLVDIMemoryName_0.


    Looking at the SQL Server error log, I also see that a process was killed by the local host around the same time. While I can't say for sure that the killed process is related to the sqlBackup error, there isn't much else going on with the server at the time of the failed restore.

    Date 4/26/2011 7:15:20 AM
    Log SQL Server (Current - 4/26/2011 12:29:00 AM)

    Source spid62

    Message
    Process ID 93 was killed by hostname SQLDEV, host process ID 2208.


    Does this information get us any closer to a possible root cause?

    Thanks,

    -Mike
  • peteypetey Posts: 2,358 New member
    I'm afraid it doesn't get us any closer to the possible root cause, but it does confirm that there is something wrong going on in the VDI interaction.

    If you are running a 64-bit system, perhaps it's worth checking if the 32-bit and 64-bit VDI libraries are consistent.

    In the registry, look for the key {40700425-0080-11d2-851f-00c04fc21759} in HKEY_CLASSES_ROOT. In the subkey InprocServer32, look for the copy of sqlvdi.dll that is used. Check the version number of this file. If you are running a 64-bit system, you should find another entry in HKEY_CLASSES_ROOT\Wow6432Node\CLSID. Again, check the version number of this file. What are the versions of both those files?

    If both files are consistent, I guess we'll need to wait for another failure, and compare the situation surrounding both failures.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • Peter,

    I checked both files, per your instructions. Here is the information I collected:

    HKCR\CLSID\{40700425-0080-11d2-851f-00c04fc21759}\InprocServer32
    C:\Program Files\Microsoft SQL Server\80\COM\sqlvdi.dll
    Version: 8.05.2312
    Size: 157KB

    HKCR\Wow6432Node\CLSID\{40700425-0080-11d2-851f-00c04fc21759}\InprocServer32
    C:\Program Files (x86)\Microsoft SQL Server\80\COM\sqlvdi.dll
    Version: 8.05.2312
    Size: 120KB


    From what I can tell, both files are the same version, but have a considerable difference in size. I'm not sure if that means anything or not. Please let me know if there is any additional information I can collect to help troubleshoot.

    Thanks again for your time.

    -Mike
  • Peter,

    For the purpose of comparison, I checked the version of these files on another host to which I frequently restore this database. The versions of both sqlvdi.dll files match the server on which the error is being generated, but I don't seem to get the error on the second server. Also, the version of SQLBackup is consistent across both servers.

    I was hoping to find something different on the server that isn't generating any errors, but that is unfortunately not the case.

    -Mike
  • Peter,

    I made one change to the backup process for this particular database last night. Instead of striping the backup across multiple files, I went back to writing it to a single file. Subsequently, the restore process completed successfully this morning. Is it possible that trying to restore from multiple backup files is causing this problem?

    Thanks,

    -Mike
  • peteypetey Posts: 2,358 New member
    It's a possibility. Let's see how it holds out over the next week or so.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • Peter,

    The process has executed successfully the past four consecutive days since the switch was made back to using a single backup file. I'll watch it for the rest of the week, but it appears this change has resolved my particular issue.

    That being said, have there been any other reports of customers having issues with striping backupsets across multiple files? At my previous employer, I did this frequently with the larger databases I managed using native SQL Server backups and it seemed to work fine.

    Thanks again for your time.

    -Mike Eastland
  • Peter,

    The process has not failed since the switch was made back to writing the full backupset to a single file. This is not a problem for me currently, but I think other customers with larger databases could see significant performance gains in their backup jobs by striping large database backups across multiple files.

    I'm not sure how you want to leave this. I'm fine with considering the issue closed from my end, but I would also be happy to provide any additional information that might help troubleshoot the underlying issue.

    Thanks,

    -Mike
  • peteypetey Posts: 2,358 New member
    This is the first time I've come across an error of this nature i.e. SQL Server completes the restore, but reports an API timeout error to the VDI components, thus causing SQL Backup to think that an error occurred during the restore process.

    Would you be willing to switch back to backing up to 2 files, to try reproducing the error again?

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
  • Peter,

    I would not be opposed to trying to recreate the error. However, I want to be sure that something is different, such as a higher debug setting etc, in order to provide you with additional troubleshooting information. It seems that just flipping back to the multiple files for the sake of having the process generate another error doesn't really get us closer to the root cause.

    Thanks,

    -Mike
  • peteypetey Posts: 2,358 New member
    We have only had one good trace to work on, and that had one process killing another process. Could be coincidental, or could have been the cause of that error then. If you can reproduce the error and there are no spids being killed this time round, we then at least eliminate the possibility that someone or some process was killing your restore jobs prematurely, and confirm that the issue has to do with SQL Backup having to restore from more than one file.

    Thanks.
    Peter Yeoh
    SQL Backup Consultant Developer
    Associate, Yohz Software
    Beyond compression - SQL Backup goodies under the hood, updated for version 8
Sign In or Register to comment.