VDI error 1010

Proto

I'm getting this error when running my transaction log backup on sunday nights. I get the error, it retries and then goes through fine. The transaction log backup is scheduled to run every night at midnight, and it runs without error on every other night but sunday. I have a full backup that runs early sunday morning that also runs fine.

The odd thing is that there is literally nothing else running on the server at this time. No other jobs, nothing else that would use memory or CPU.

Running SQL Server 2005, SQL Backup 6.2.0.134

Here is the log:

---

SQL Backup log file 6.2.0.134

-SQL "BACKUP LOG [BNCSD] TO DISK = 'F:\Backup\<AUTO>.sqb' WITH MAILTO = '****', DISKRETRYINTERVAL = 30, DISKRETRYCOUNT = 10, COMPRESSION = 4, THREADCOUNT = 3 "

---

ERRORS AND WARNINGS

---

6/14/2010: Backing up BNCSD (transaction log) to:
6/14/2010: F:\Backup\LOG_(local)_BNCSD_20100614_000000.sqb

6/14/2010: BACKUP LOG [BNCSD] TO VIRTUAL_DEVICE = 'SQLBACKUP_86FCCBBA-3476-4CF6-8036-C9B78704D2D1', VIRTUAL_DEVICE = 'SQLBACKUP_86FCCBBA-3476-4CF6-8036-C9B78704D2D101', VIRTUAL_DEVICE = 'SQLBACKUP_86FCCBBA-3476-4CF6-8036-C9B78704D2D102' WITH BUFFERCOUNT
= 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 1048576, NAME = N'Database (BNCSD), 6/14/2010', DESCRIPTION = N'Backup on 6/14/2010 Server: BOOKNETDB Database: BNCSD', FORMAT

6/14/2010 12:00:30 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]
6/14/2010 12:01:56 AM: SQL error 3013: BACKUP LOG is terminating abnormally.
6/14/2010 12:01:56 AM: SQL error 3201: Cannot open backup device 'SQLBACKUP_86FCCBBA-3476-4CF6-8036-C9B78704D2D1'. Operating system error 0x80070002(The system cannot find the file specified.).
6/14/2010 12:01:56 AM:
6/14/2010 12:01:57 AM: Memory profile
6/14/2010 12:01:57 AM: Type Maximum Minimum Average Blk count Total
6/14/2010 12:01:57 AM:

---

---

---

---

---

---

6/14/2010 12:01:57 AM: Commit 212598784 4096 57008 239016 13625872384
6/14/2010 12:01:57 AM: Reserve 7079919616 4096 118760 236325 28066074624
6/14/2010 12:01:57 AM: Free 6841860882432 4096 29278933142 299 8754401009664
6/14/2010 12:01:57 AM: Private 7079919616 4096 87451 474396 41486532608
6/14/2010 12:01:57 AM: Mapped 4194304 4096 364455 93 33894400
6/14/2010 12:01:57 AM: Image 33259520 4096 201314 852 171520000
6/14/2010 12:01:57 AM:

---

PROCESSES COMPLETED SUCCESSFULLY

---

6/14/2010 12:01:57 AM: Warning 300: Backup failed. Retry attempt: 1
6/14/2010 12:02:00 AM: BACKUP LOG [BNCSD] TO VIRTUAL_DEVICE = 'SQLBACKUP_C78A2A4C-0058-42C4-95C5-42DDCFBB69DC', VIRTUAL_DEVICE = 'SQLBACKUP_C78A2A4C-0058-42C4-95C5-42DDCFBB69DC01', VIRTUAL_DEVICE = 'SQLBACKUP_C78A2A4C-0058-42C4-95C5-42DDCFBB69DC02' WITH
BUFFERCOUNT = 18, BLOCKSIZE = 65536, MAXTRANSFERSIZE = 524288, NAME = N'Database (BNCSD), 6/14/2010', DESCRIPTION = N'Backup on 6/14/2010 Server: BOOKNETDB Database: BNCSD', FORMAT

6/14/2010 12:02:28 AM: Backup data size : 1.097 GB
6/14/2010 12:02:28 AM: Compressed data size: 96.232 MB
6/14/2010 12:02:28 AM: Compression rate : 91.43%

6/14/2010 12:02:28 AM: Processed 27944 pages for database 'BNCSD', file 'BNCSD_1_log' on file 1.
6/14/2010 12:02:28 AM: Processed 114856 pages for database 'BNCSD', file 'BNCSD_2_log' on file 1.
6/14/2010 12:02:28 AM: BACKUP LOG successfully processed 142800 pages in 28.275 seconds (41.372 MB/sec).
6/14/2010 12:02:29 AM: Mail sent successfully to: *****

---

Looking at other posts I came across this one that is similar.

http://www.red-gate.com/messageboard/vi ... 3442#33442

And when I look at the log file I do see that MAXTRANSFERSIZE drops from 1048576 to 524288 between retries.

The question is: Why is this happening at all? And why only on the one day of the week?

petey

Your transaction log backup started at midnight:

6/14/2010: Backing up BNCSD (transaction log) to:

SQL Backup sent some backup configuration details to SQL Server, and waits for 30 seconds for SQL Server to acknowledge receipt of the configuration data. However, SQL Server did not respond within the 30 seconds, and SQL Backup aborted the backup:

6/14/2010 12:00:30 AM: VDI error 1010: Failed to get the configuration from the server because the timeout interval has elapsed.

At 12:01:56, 86 seconds after SQL Backup aborted the backup, SQL Server tried to contact SQL Backup to acknowledge that the configuration data was fine. By that time, SQL Backup had already aborted the backup, and could no longer communicate with SQL Server. As a result, SQL Server also aborted the backup task.

6/14/2010 12:01:56 AM: SQL error 3013: BACKUP LOG is terminating abnormally.

In short, something was preventing SQL Server from communicating with SQL Backup between 12:00:00 and 12:00:30. Usual cases involve a server that is under a heavy load, and also when another process is blocking the backup e.g. index rebuilds, another backup of the same database running at that time etc.

Is it possible that your full backup was still running during that time?

Thanks.

Proto

Nope. The full backup runs nearly a day before (3AM Sunday morning) and was complete a long time before the transaction log backup ran.

Like I said, the confusing part is that there is nothing else going on at this time. Looking at our monitoring software (SQL Sentry) there is nothing that jumps out. CPU usage is ~3%. No other queries running. No deadlocks or blocking.

petey

If you encounter this warning consistently, perhaps you could schedule a SQL Server Agent job to run at 12:00:15, to get a log of the active processes at that time e.g.

SELECT * INTO AdventureWorks..processdump FROM master..sysprocesses

to confirm that nothing is blocking the backup process at that time.

Thanks.