RESTORE...LATEST_ALL fails

meastland · April 20, 2011 10:16AM

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.

petey · April 21, 2011 3:40AM

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.

meastland · April 21, 2011 4:20PM

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

petey · April 21, 2011 9:56PM

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.

meastland · April 22, 2011 9:56AM

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

meastland · April 26, 2011 10:04AM

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

petey · April 26, 2011 11:55AM

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.

meastland · April 26, 2011 12:35PM

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

petey · April 26, 2011 12:55PM

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.

meastland · April 26, 2011 2:21PM

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

meastland · April 26, 2011 2:30PM

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

meastland · April 28, 2011 11:08AM

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

petey · April 29, 2011 5:56AM

It's a possibility. Let's see how it holds out over the next week or so.

meastland · May 3, 2011 9:57AM

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

meastland · May 6, 2011 9:44AM

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

petey · May 9, 2011 6:05AM

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.

meastland · May 9, 2011 10:03AM

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

petey · May 9, 2011 10:31PM

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.

RESTORE...LATEST_ALL fails

Comments

Product Learning

Community Forums

Events & Friends

Simple Talk