This post is more than 5 years old
2 Intern
•
143 Posts
0
4514
SQL VSS freeze failures
Hello,
I have deployed AppSync 1.5 fresh and am trying to get AppSync to properly snap my SQL 2008 R2 database server. I have installed the new AppSync 1.5 patch released a few weeks ago to support SQL servers running on VMware on virtual disks (VMDKs). In my case, the SQL 2008 R2 VM is running on Windows 2008 R2, on a VM, with databases and logs on the E: drive. I ran through the usual VSS troubleshooting steps, but I cannot figure out why the VSS freeze operations keep timing out. Below is a copy of the AppSync log. Most of the errors seem to be near the end of the freeze cycle. Anyone have any ideas? I am trying to prove AppSync with SQL and so far my experience hasn't been too good. Any help would be appreciated.
2013-10-31 10:14:38.425 INFO [1396] [] [sql2008a] [] SQL: Agent receieved freeze command
2013-10-31 10:14:38.425 INFO [1396] [] [sql2008a] [] SQL: Creating thread for database SQL2008A.ViewEvent
2013-10-31 10:14:38.425 INFO [1396] [] [sql2008a] [] TIME=1383232478425 THREAD=1396 ID=SQL_000004 STEP= PHASE=Create local copy PIT=f5428bb4-6524-4656-836a-bb5d139a05b2 EVENTMSG=Not in catalog ARGS= SQL2008A_ViewEvent,FULL,
2013-10-31 10:14:38.425 INFO [1396] [] [sql2008a] [] SQL: Creating thread for database SQL2008A.ViewComposer
2013-10-31 10:14:38.425 INFO [1396] [] [sql2008a] [] TIME=1383232478425 THREAD=1396 ID=SQL_000004 STEP= PHASE=Create local copy PIT=f5428bb4-6524-4656-836a-bb5d139a05b2 EVENTMSG=Not in catalog ARGS= SQL2008A_ViewComposer,FULL,
2013-10-31 10:14:38.426 INFO [1396] [] [sql2008a] [] SQL: Creating thread for database SQL2008A.lab511vc01_RSA
2013-10-31 10:14:38.426 INFO [1396] [] [sql2008a] [] TIME=1383232478426 THREAD=1396 ID=SQL_000004 STEP= PHASE=Create local copy PIT=f5428bb4-6524-4656-836a-bb5d139a05b2 EVENTMSG=Not in catalog ARGS= SQL2008A_lab511vc01_RSA,FULL,
2013-10-31 10:14:38.426 INFO [1396] [] [sql2008a] [] SQL: Creating thread for database SQL2008A.lab511vc01_vcdb
2013-10-31 10:14:38.426 INFO [1396] [] [sql2008a] [] TIME=1383232478426 THREAD=1396 ID=SQL_000004 STEP= PHASE=Create local copy PIT=f5428bb4-6524-4656-836a-bb5d139a05b2 EVENTMSG=Not in catalog ARGS= SQL2008A_lab511vc01_vcdb,FULL,
2013-10-31 10:14:38.426 INFO [1396] [] [sql2008a] [] SQL: Creating thread for database SQL2008A.lab511vc01_vum
2013-10-31 10:14:38.426 INFO [1396] [] [sql2008a] [] TIME=1383232478426 THREAD=1396 ID=SQL_000004 STEP= PHASE=Create local copy PIT=f5428bb4-6524-4656-836a-bb5d139a05b2 EVENTMSG=Not in catalog ARGS= SQL2008A_lab511vc01_vum,FULL,
2013-10-31 10:14:38.426 INFO [1396] [] [sql2008a] [] SQL: Waiting at most 300 seconds for threads to complete
2013-10-31 10:14:38.546 DEBUG [2232] [] [sql2008a] [] SQL: Setting logging alias thread id to: 1396
2013-10-31 10:14:38.546 INFO [2232] [] [sql2008a] [] SQL: Starting replication of SQL2008A.ViewEvent.
2013-10-31 10:14:38.546 INFO [2232] [] [sql2008a] [] SQL: Using temp dir: C:\Windows\TEMP\
2013-10-31 10:14:38.546 INFO [2232] [] [sql2008a] [] SQL: Metadata file path:"C:\Windows\TEMP\APPSYNC_VDI_SQL2008A_ViewEvent20131031151438.bin"
2013-10-31 10:14:38.546 INFO [2232] [] [sql2008a] [] SQL: Connecting to master database of instance SQL2008A for backing up ViewEvent
2013-10-31 10:14:38.546 INFO [2232] [] [sql2008a] [] SQL: Connecting to database SQL2008A.master
2013-10-31 10:14:38.546 INFO [2232] [] [sql2008a] [] SQL: impersonating enlab\sql
2013-10-31 10:14:38.546 DEBUG [2936] [] [sql2008a] [] SQL: Setting logging alias thread id to: 1396
2013-10-31 10:14:38.547 INFO [2936] [] [sql2008a] [] SQL: Starting replication of SQL2008A.ViewComposer.
2013-10-31 10:14:38.547 INFO [2936] [] [sql2008a] [] SQL: Using temp dir: C:\Windows\TEMP\
2013-10-31 10:14:38.547 INFO [2936] [] [sql2008a] [] SQL: Metadata file path:"C:\Windows\TEMP\APPSYNC_VDI_SQL2008A_ViewComposer20131031151438.bin"
2013-10-31 10:14:38.547 INFO [2936] [] [sql2008a] [] SQL: Connecting to master database of instance SQL2008A for backing up ViewComposer
2013-10-31 10:14:38.547 INFO [2936] [] [sql2008a] [] SQL: Connecting to database SQL2008A.master
2013-10-31 10:14:38.547 INFO [2936] [] [sql2008a] [] SQL: impersonating enlab\sql
2013-10-31 10:14:38.547 DEBUG [1192] [] [sql2008a] [] SQL: Setting logging alias thread id to: 1396
2013-10-31 10:14:38.547 INFO [1192] [] [sql2008a] [] SQL: Starting replication of SQL2008A.lab511vc01_RSA.
2013-10-31 10:14:38.547 INFO [1192] [] [sql2008a] [] SQL: Using temp dir: C:\Windows\TEMP\
2013-10-31 10:14:38.547 INFO [1192] [] [sql2008a] [] SQL: Metadata file path:"C:\Windows\TEMP\APPSYNC_VDI_SQL2008A_lab511vc01_RSA20131031151438.bin"
2013-10-31 10:14:38.547 INFO [1192] [] [sql2008a] [] SQL: Connecting to master database of instance SQL2008A for backing up lab511vc01_RSA
2013-10-31 10:14:38.547 INFO [1192] [] [sql2008a] [] SQL: Connecting to database SQL2008A.master
2013-10-31 10:14:38.547 INFO [1192] [] [sql2008a] [] SQL: impersonating enlab\sql
2013-10-31 10:14:38.548 DEBUG [1260] [] [sql2008a] [] SQL: Setting logging alias thread id to: 1396
2013-10-31 10:14:38.548 INFO [1260] [] [sql2008a] [] SQL: Starting replication of SQL2008A.lab511vc01_vcdb.
2013-10-31 10:14:38.548 INFO [1260] [] [sql2008a] [] SQL: Using temp dir: C:\Windows\TEMP\
2013-10-31 10:14:38.548 INFO [1260] [] [sql2008a] [] SQL: Metadata file path:"C:\Windows\TEMP\APPSYNC_VDI_SQL2008A_lab511vc01_vcdb20131031151438.bin"
2013-10-31 10:14:38.548 INFO [1260] [] [sql2008a] [] SQL: Connecting to master database of instance SQL2008A for backing up lab511vc01_vcdb
2013-10-31 10:14:38.548 INFO [1260] [] [sql2008a] [] SQL: Connecting to database SQL2008A.master
2013-10-31 10:14:38.548 INFO [1260] [] [sql2008a] [] SQL: impersonating enlab\sql
2013-10-31 10:14:38.601 DEBUG [2100] [] [sql2008a] [] SQL: Setting logging alias thread id to: 1396
2013-10-31 10:14:38.601 INFO [2100] [] [sql2008a] [] SQL: Starting replication of SQL2008A.lab511vc01_vum.
2013-10-31 10:14:38.602 INFO [2100] [] [sql2008a] [] SQL: Using temp dir: C:\Windows\TEMP\
2013-10-31 10:14:38.602 INFO [2100] [] [sql2008a] [] SQL: Metadata file path:"C:\Windows\TEMP\APPSYNC_VDI_SQL2008A_lab511vc01_vum20131031151438.bin"
2013-10-31 10:14:38.602 INFO [2100] [] [sql2008a] [] SQL: Connecting to master database of instance SQL2008A for backing up lab511vc01_vum
2013-10-31 10:14:38.602 INFO [2100] [] [sql2008a] [] SQL: Connecting to database SQL2008A.master
2013-10-31 10:14:38.602 INFO [2100] [] [sql2008a] [] SQL: impersonating enlab\sql
2013-10-31 10:14:38.876 INFO [1192] [] [sql2008a] [] SQL: Allocating environment handle
2013-10-31 10:14:38.876 INFO [1192] [] [sql2008a] [] SQL: Setting environment handle's attributes
2013-10-31 10:14:38.876 INFO [1192] [] [sql2008a] [] SQL: Allocating first connection handle
2013-10-31 10:14:38.876 DEBUG [1192] [] [sql2008a] [] Successfully set connection timeout.
2013-10-31 10:14:38.876 INFO [1192] [] [sql2008a] [] SQL: Connecting to the driver
2013-10-31 10:14:38.879 INFO [1260] [] [sql2008a] [] SQL: Allocating environment handle
2013-10-31 10:14:38.879 INFO [1260] [] [sql2008a] [] SQL: Setting environment handle's attributes
2013-10-31 10:14:38.879 INFO [1260] [] [sql2008a] [] SQL: Allocating first connection handle
2013-10-31 10:14:38.879 DEBUG [1260] [] [sql2008a] [] Successfully set connection timeout.
2013-10-31 10:14:38.879 INFO [1260] [] [sql2008a] [] SQL: Connecting to the driver
2013-10-31 10:14:38.880 INFO [2936] [] [sql2008a] [] SQL: Allocating environment handle
2013-10-31 10:14:38.880 INFO [2936] [] [sql2008a] [] SQL: Setting environment handle's attributes
2013-10-31 10:14:38.880 INFO [2936] [] [sql2008a] [] SQL: Allocating first connection handle
2013-10-31 10:14:38.880 DEBUG [2936] [] [sql2008a] [] Successfully set connection timeout.
2013-10-31 10:14:38.880 INFO [2936] [] [sql2008a] [] SQL: Connecting to the driver
2013-10-31 10:14:38.880 INFO [2100] [] [sql2008a] [] SQL: Allocating environment handle
2013-10-31 10:14:38.880 INFO [2100] [] [sql2008a] [] SQL: Setting environment handle's attributes
2013-10-31 10:14:38.880 INFO [2100] [] [sql2008a] [] SQL: Allocating first connection handle
2013-10-31 10:14:38.880 DEBUG [2100] [] [sql2008a] [] Successfully set connection timeout.
2013-10-31 10:14:38.881 INFO [2100] [] [sql2008a] [] SQL: Connecting to the driver
2013-10-31 10:14:41.756 INFO [2232] [] [sql2008a] [] SQL: Allocating environment handle
2013-10-31 10:14:41.756 INFO [2232] [] [sql2008a] [] SQL: Setting environment handle's attributes
2013-10-31 10:14:41.756 INFO [2232] [] [sql2008a] [] SQL: Allocating first connection handle
2013-10-31 10:14:41.756 DEBUG [2232] [] [sql2008a] [] Successfully set connection timeout.
2013-10-31 10:14:41.756 INFO [2232] [] [sql2008a] [] SQL: Connecting to the driver
2013-10-31 10:14:57.843 INFO [1192] [] [sql2008a] [] SQL: Connected successfully to database SQL2008A.master
2013-10-31 10:14:57.850 INFO [1192] [] [sql2008a] [] SQL: vdiExecutePrepare: Creating backup/recovery command.
2013-10-31 10:14:57.850 INFO [1192] [] [sql2008a] [] SQL: VDI command is: BACKUP DATABASE "lab511vc01_RSA" TO VIRTUAL_DEVICE='EMCAPM_BACKUP_FILE_lab511vc01_RSA20131031151457' WITH SNAPSHOT
2013-10-31 10:14:57.889 INFO [1192] [] [sql2008a] [] SQL: starting asynchronized execution of VDI command
2013-10-31 10:14:57.889 INFO [1192] [] [sql2008a] [] SQL: query: "BACKUP DATABASE "lab511vc01_RSA" TO VIRTUAL_DEVICE='EMCAPM_BACKUP_FILE_lab511vc01_RSA20131031151457' WITH SNAPSHOT", is executed on database SQL2008A.master asynchronously
2013-10-31 10:15:06.733 INFO [2936] [] [sql2008a] [] SQL: Connected successfully to database SQL2008A.master
2013-10-31 10:15:06.733 INFO [2936] [] [sql2008a] [] SQL: vdiExecutePrepare: Creating backup/recovery command.
2013-10-31 10:15:06.733 INFO [2936] [] [sql2008a] [] SQL: VDI command is: BACKUP DATABASE "ViewComposer" TO VIRTUAL_DEVICE='EMCAPM_BACKUP_FILE_ViewComposer2013103115156' WITH SNAPSHOT
2013-10-31 10:15:06.734 INFO [2936] [] [sql2008a] [] SQL: starting asynchronized execution of VDI command
2013-10-31 10:15:06.734 INFO [2936] [] [sql2008a] [] SQL: query: "BACKUP DATABASE "ViewComposer" TO VIRTUAL_DEVICE='EMCAPM_BACKUP_FILE_ViewComposer2013103115156' WITH SNAPSHOT", is executed on database SQL2008A.master asynchronously
2013-10-31 10:15:07.113 INFO [2100] [] [sql2008a] [] SQL: Connected successfully to database SQL2008A.master
2013-10-31 10:15:07.113 INFO [2100] [] [sql2008a] [] SQL: vdiExecutePrepare: Creating backup/recovery command.
2013-10-31 10:15:07.113 INFO [2100] [] [sql2008a] [] SQL: VDI command is: BACKUP DATABASE "lab511vc01_vum" TO VIRTUAL_DEVICE='EMCAPM_BACKUP_FILE_lab511vc01_vum2013103115157' WITH SNAPSHOT
2013-10-31 10:15:07.114 INFO [2100] [] [sql2008a] [] SQL: starting asynchronized execution of VDI command
2013-10-31 10:15:07.114 INFO [2100] [] [sql2008a] [] SQL: query: "BACKUP DATABASE "lab511vc01_vum" TO VIRTUAL_DEVICE='EMCAPM_BACKUP_FILE_lab511vc01_vum2013103115157' WITH SNAPSHOT", is executed on database SQL2008A.master asynchronously
2013-10-31 10:15:09.394 INFO [2976] [] [sql2008a] [] poll something ready
2013-10-31 10:15:09.394 INFO [2976] [] [sql2008a] [] UTIL_socketTLS: SSL_ERROR_SYSCALL - will retry
2013-10-31 10:15:09.394 INFO [2976] [] [sql2008a] [] UTIL_socketTLS: SSL_ERROR_SYSCALL - will retry
2013-10-31 10:15:09.394 INFO [2976] [] [sql2008a] [] UTIL_socketTLS: SSL_ERROR_SYSCALL - will retry
2013-10-31 10:15:09.394 INFO [2976] [] [sql2008a] [] UTIL_socketTLS: SSL_ERROR_SYSCALL - will retry
2013-10-31 10:15:09.394 INFO [2976] [] [sql2008a] [] UTIL_socketTLS: SSL_ERROR_SYSCALL - will retry
2013-10-31 10:15:09.394 INFO [2976] [] [sql2008a] [] UTIL_socketTLS: SSL_ERROR_SYSCALL - will retry
2013-10-31 10:15:09.394 INFO [2976] [] [sql2008a] [] UTIL_socketTLS: SSL_ERROR_SYSCALL - will retry
2013-10-31 10:15:09.395 INFO [2976] [] [sql2008a] [] UTIL_socketTLS: SSL_ERROR_SYSCALL - will retry
2013-10-31 10:15:09.395 INFO [2976] [] [sql2008a] [] UTIL_socketTLS: SSL_ERROR_SYSCALL - will retry
2013-10-31 10:15:09.395 INFO [2976] [] [sql2008a] [] UTIL_socketTLS: SSL_ERROR_SYSCALL - will retry
2013-10-31 10:15:09.395 INFO [2976] [] [sql2008a] [] UTIL_socketTLS: SSL_ERROR_SYSCALL - will retry
2013-10-31 10:15:09.395 INFO [2976] [] [sql2008a] [] UTIL_socketTLS: Read returned zero 10 times - Socket (0000000000000310) possibly closed by peer
2013-10-31 10:15:09.395 INFO [2976] [] [sql2008a] [] Failed to read length header
2013-10-31 10:15:09.395 INFO [2976] [] [sql2008a] [] error reading connection in messageDispatch
2013-10-31 10:15:09.395 INFO [2976] [] [sql2008a] [] session finished, deleting
2013-10-31 10:15:09.395 INFO [2976] [] [sql2008a] [] freeing m_addrInfo
2013-10-31 10:15:09.395 INFO [2976] [] [sql2008a] [] closesocket(0000000000000310) ret=0
2013-10-31 10:15:09.395 INFO [2976] [] [sql2008a] [] closed socket(0000000000000310)
2013-10-31 10:15:09.419 INFO [1260] [] [sql2008a] [] SQL: Connected successfully to database SQL2008A.master
2013-10-31 10:15:09.419 INFO [1260] [] [sql2008a] [] SQL: vdiExecutePrepare: Creating backup/recovery command.
2013-10-31 10:15:09.419 INFO [1260] [] [sql2008a] [] SQL: VDI command is: BACKUP DATABASE "lab511vc01_vcdb" TO VIRTUAL_DEVICE='EMCAPM_BACKUP_FILE_lab511vc01_vcdb2013103115159' WITH SNAPSHOT
2013-10-31 10:15:09.420 INFO [1260] [] [sql2008a] [] SQL: starting asynchronized execution of VDI command
2013-10-31 10:15:09.420 INFO [1260] [] [sql2008a] [] SQL: query: "BACKUP DATABASE "lab511vc01_vcdb" TO VIRTUAL_DEVICE='EMCAPM_BACKUP_FILE_lab511vc01_vcdb2013103115159' WITH SNAPSHOT", is executed on database SQL2008A.master asynchronously
2013-10-31 10:15:13.998 INFO [2232] [] [sql2008a] [] SQL: Connected successfully to database SQL2008A.master
2013-10-31 10:15:13.998 INFO [2232] [] [sql2008a] [] SQL: vdiExecutePrepare: Creating backup/recovery command.
2013-10-31 10:15:13.998 INFO [2232] [] [sql2008a] [] SQL: VDI command is: BACKUP DATABASE "ViewEvent" TO VIRTUAL_DEVICE='EMCAPM_BACKUP_FILE_ViewEvent20131031151513' WITH SNAPSHOT
2013-10-31 10:15:13.999 INFO [2232] [] [sql2008a] [] SQL: starting asynchronized execution of VDI command
2013-10-31 10:15:13.999 INFO [2232] [] [sql2008a] [] SQL: query: "BACKUP DATABASE "ViewEvent" TO VIRTUAL_DEVICE='EMCAPM_BACKUP_FILE_ViewEvent20131031151513' WITH SNAPSHOT", is executed on database SQL2008A.master asynchronously
2013-10-31 10:15:25.375 INFO [2100] [] [sql2008a] [] SQL: vdiExecute metadata file path: C:\Windows\TEMP\APPSYNC_VDI_SQL2008A_lab511vc01_vum20131031151438.bin
2013-10-31 10:15:25.385 INFO [2100] [] [sql2008a] [] SQL: Starting VDC command execution
2013-10-31 10:15:26.529 INFO [1192] [] [sql2008a] [] SQL: vdiExecute metadata file path: C:\Windows\TEMP\APPSYNC_VDI_SQL2008A_lab511vc01_RSA20131031151438.bin
2013-10-31 10:15:26.529 INFO [1192] [] [sql2008a] [] SQL: Starting VDC command execution
2013-10-31 10:15:28.180 INFO [2936] [] [sql2008a] [] SQL: vdiExecute metadata file path: C:\Windows\TEMP\APPSYNC_VDI_SQL2008A_ViewComposer20131031151438.bin
2013-10-31 10:15:28.180 INFO [2936] [] [sql2008a] [] SQL: Starting VDC command execution
2013-10-31 10:15:28.646 INFO [1260] [] [sql2008a] [] SQL: vdiExecute metadata file path: C:\Windows\TEMP\APPSYNC_VDI_SQL2008A_lab511vc01_vcdb20131031151438.bin
2013-10-31 10:15:28.646 INFO [1260] [] [sql2008a] [] SQL: Starting VDC command execution
2013-10-31 10:15:36.477 INFO [2232] [] [sql2008a] [] SQL: vdiExecute metadata file path: C:\Windows\TEMP\APPSYNC_VDI_SQL2008A_ViewEvent20131031151438.bin
2013-10-31 10:15:36.477 INFO [2232] [] [sql2008a] [] SQL: Starting VDC command execution
2013-10-31 10:15:38.745 INFO [2936] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:15:39.123 INFO [2936] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:15:39.312 INFO [1260] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:15:39.691 INFO [1260] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:15:41.396 INFO [2100] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:15:41.774 INFO [2100] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:15:43.101 INFO [1192] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:15:43.479 INFO [1192] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:15:47.653 INFO [2232] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:15:48.048 INFO [2232] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:16:09.971 INFO [2100] [] [sql2008a] [] SQL: Virtual Device Command - SQL Server is prepared to freeze the database now
2013-10-31 10:16:09.971 INFO [2100] [] [sql2008a] [] SQL: done with VDI execution
2013-10-31 10:16:09.971 INFO [2100] [] [sql2008a] [] SQL: freezing database
2013-10-31 10:16:09.971 INFO [2100] [] [sql2008a] [] SQL: freezing SQL2008A.lab511vc01_vum
2013-10-31 10:16:09.971 INFO [2100] [] [sql2008a] [] SQL: Starting VDC command execution
2013-10-31 10:16:11.483 INFO [1192] [] [sql2008a] [] SQL: Virtual Device Command - SQL Server is prepared to freeze the database now
2013-10-31 10:16:11.483 INFO [1192] [] [sql2008a] [] SQL: done with VDI execution
2013-10-31 10:16:11.483 INFO [1192] [] [sql2008a] [] SQL: freezing database
2013-10-31 10:16:11.483 INFO [1192] [] [sql2008a] [] SQL: freezing SQL2008A.lab511vc01_RSA
2013-10-31 10:16:11.483 INFO [1192] [] [sql2008a] [] SQL: Starting VDC command execution
2013-10-31 10:16:13.188 INFO [2936] [] [sql2008a] [] SQL: Virtual Device Command - SQL Server is prepared to freeze the database now
2013-10-31 10:16:13.188 INFO [2936] [] [sql2008a] [] SQL: done with VDI execution
2013-10-31 10:16:13.188 INFO [2936] [] [sql2008a] [] SQL: freezing database
2013-10-31 10:16:13.188 INFO [2936] [] [sql2008a] [] SQL: freezing SQL2008A.ViewComposer
2013-10-31 10:16:13.188 INFO [2936] [] [sql2008a] [] SQL: Starting VDC command execution
2013-10-31 10:16:15.083 INFO [2100] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:16:15.654 INFO [2100] [] [sql2008a] [] SQL: performed VDC_Flush
2013-10-31 10:16:15.654 INFO [2100] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:16:16.244 INFO [2100] [] [sql2008a] [] SQL: ready to take snapshot.
2013-10-31 10:16:16.244 INFO [2100] [] [sql2008a] [] SQL: Saving freeze result 0, for database SQL2008A.lab511vc01_vum id dff4e9a0-46ff-4bd8-956e-26ae921701e6
2013-10-31 10:16:16.244 ERROR [2100] [] [sql2008a] [] Unable to get the value for query key CC_AGENT_THREAD_WAIT_TIME. Error: The system cannot find the file specified.
2013-10-31 10:16:16.244 INFO [2100] [] [sql2008a] [] SQL: Waiting 300 seconds for thaw message to arrive for database SQL2008A.lab511vc01_vum id dff4e9a0-46ff-4bd8-956e-26ae921701e6
2013-10-31 10:16:16.817 INFO [1192] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:16:17.256 INFO [1192] [] [sql2008a] [] SQL: performed VDC_Flush
2013-10-31 10:16:17.256 INFO [1192] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:16:17.635 INFO [1192] [] [sql2008a] [] SQL: ready to take snapshot.
2013-10-31 10:16:17.635 INFO [1192] [] [sql2008a] [] SQL: Saving freeze result 0, for database SQL2008A.lab511vc01_RSA id 26fa538e-7d97-4d2b-944b-2f1b1dbc030f
2013-10-31 10:16:17.635 ERROR [1192] [] [sql2008a] [] Unable to get the value for query key CC_AGENT_THREAD_WAIT_TIME. Error: The system cannot find the file specified.
2013-10-31 10:16:17.635 INFO [1192] [] [sql2008a] [] SQL: Waiting 300 seconds for thaw message to arrive for database SQL2008A.lab511vc01_RSA id 26fa538e-7d97-4d2b-944b-2f1b1dbc030f
2013-10-31 10:16:18.013 INFO [2232] [] [sql2008a] [] SQL: Virtual Device Command - SQL Server is prepared to freeze the database now
2013-10-31 10:16:18.013 INFO [2232] [] [sql2008a] [] SQL: done with VDI execution
2013-10-31 10:16:18.013 INFO [2232] [] [sql2008a] [] SQL: freezing database
2013-10-31 10:16:18.013 INFO [2232] [] [sql2008a] [] SQL: freezing SQL2008A.ViewEvent
2013-10-31 10:16:18.013 INFO [2232] [] [sql2008a] [] SQL: Starting VDC command execution
2013-10-31 10:16:18.966 INFO [2936] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:16:19.344 INFO [2936] [] [sql2008a] [] SQL: performed VDC_Flush
2013-10-31 10:16:19.344 INFO [2936] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:16:19.723 INFO [2936] [] [sql2008a] [] SQL: ready to take snapshot.
2013-10-31 10:16:19.723 INFO [2936] [] [sql2008a] [] SQL: Saving freeze result 0, for database SQL2008A.ViewComposer id e965d593-641e-4dad-a192-8083b36bebb7
2013-10-31 10:16:19.723 ERROR [2936] [] [sql2008a] [] Unable to get the value for query key CC_AGENT_THREAD_WAIT_TIME. Error: The system cannot find the file specified.
2013-10-31 10:16:19.723 INFO [2936] [] [sql2008a] [] SQL: Waiting 300 seconds for thaw message to arrive for database SQL2008A.ViewComposer id e965d593-641e-4dad-a192-8083b36bebb7
2013-10-31 10:16:22.757 INFO [2232] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:16:23.135 INFO [2232] [] [sql2008a] [] SQL: performed VDC_Flush
2013-10-31 10:16:23.135 INFO [2232] [] [sql2008a] [] SQL: completeCommand
2013-10-31 10:16:23.701 INFO [2232] [] [sql2008a] [] SQL: ready to take snapshot.
2013-10-31 10:16:23.701 INFO [2232] [] [sql2008a] [] SQL: Saving freeze result 0, for database SQL2008A.ViewEvent id 3f08d792-dff5-4c54-bb45-113389b1a83e
2013-10-31 10:16:23.701 ERROR [2232] [] [sql2008a] [] Unable to get the value for query key CC_AGENT_THREAD_WAIT_TIME. Error: The system cannot find the file specified.
2013-10-31 10:16:23.701 INFO [2232] [] [sql2008a] [] SQL: Waiting 300 seconds for thaw message to arrive for database SQL2008A.ViewEvent id 3f08d792-dff5-4c54-bb45-113389b1a83e
2013-10-31 10:20:39.781 INFO [1260] [] [sql2008a] [] SQL: The BACKUP command for database SQL2008A.lab511vc01_vcdb failed because SQL Server failed to respond in a timely manner.
2013-10-31 10:20:39.781 INFO [1260] [] [sql2008a] [] TIME=1383232839781 THREAD=1260 ID=SQL_000018 STEP= PHASE=Create local copy PIT=f5428bb4-6524-4656-836a-bb5d139a05b2 EVENTMSG=Not in catalog ARGS= BACKUP,SQL2008A.lab511vc01_vcdb,
2013-10-31 10:20:41.305 INFO [1260] [] [sql2008a] [] SQL: Checking if BACKUP command is still executing. Wait for it to complete or cancel it.
2013-10-31 10:20:41.305 INFO [1260] [] [sql2008a] [] SQL: Timeout for BACKUP is set for 300 seconds
2013-10-31 10:20:41.305 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:20:52.739 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:04.150 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:15.560 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:16.320 INFO [2100] [] [sql2008a] [] SQL: Time 300 seconds expired waiting for thaw request to arrive
2013-10-31 10:21:16.320 INFO [2100] [] [sql2008a] [] TIME=1383232876320 THREAD=2100 ID=SQL_000011 STEP= PHASE=Create local copy PIT=f5428bb4-6524-4656-836a-bb5d139a05b2 EVENTMSG=Not in catalog ARGS=
2013-10-31 10:21:16.320 INFO [2100] [] [sql2008a] [] SQL: Backup of SQL Server database SQL2008A.lab511vc01_vum failed because of an error creating the replica.
2013-10-31 10:21:16.320 INFO [2100] [] [sql2008a] [] SQL: aborting the VDI snapshot for lab511vc01_vum.
2013-10-31 10:21:17.273 INFO [2100] [] [sql2008a] [] SQL: Timeout for BACKUP is set for 300 seconds
2013-10-31 10:21:17.273 INFO [2100] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:17.655 INFO [1192] [] [sql2008a] [] SQL: Time 300 seconds expired waiting for thaw request to arrive
2013-10-31 10:21:17.656 INFO [1192] [] [sql2008a] [] TIME=1383232877656 THREAD=1192 ID=SQL_000011 STEP= PHASE=Create local copy PIT=f5428bb4-6524-4656-836a-bb5d139a05b2 EVENTMSG=Not in catalog ARGS=
2013-10-31 10:21:17.656 INFO [1192] [] [sql2008a] [] SQL: Backup of SQL Server database SQL2008A.lab511vc01_RSA failed because of an error creating the replica.
2013-10-31 10:21:17.656 INFO [1192] [] [sql2008a] [] SQL: aborting the VDI snapshot for lab511vc01_RSA.
2013-10-31 10:21:18.986 INFO [1192] [] [sql2008a] [] SQL: Timeout for BACKUP is set for 300 seconds
2013-10-31 10:21:18.986 INFO [1192] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:19.752 INFO [2936] [] [sql2008a] [] SQL: Time 300 seconds expired waiting for thaw request to arrive
2013-10-31 10:21:19.752 INFO [2936] [] [sql2008a] [] TIME=1383232879752 THREAD=2936 ID=SQL_000011 STEP= PHASE=Create local copy PIT=f5428bb4-6524-4656-836a-bb5d139a05b2 EVENTMSG=Not in catalog ARGS=
2013-10-31 10:21:19.752 INFO [2936] [] [sql2008a] [] SQL: Backup of SQL Server database SQL2008A.ViewComposer failed because of an error creating the replica.
2013-10-31 10:21:19.752 INFO [2936] [] [sql2008a] [] SQL: aborting the VDI snapshot for ViewComposer.
2013-10-31 10:21:21.842 INFO [2936] [] [sql2008a] [] SQL: Timeout for BACKUP is set for 300 seconds
2013-10-31 10:21:21.842 INFO [2936] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:23.780 INFO [2232] [] [sql2008a] [] SQL: Time 300 seconds expired waiting for thaw request to arrive
2013-10-31 10:21:23.780 INFO [2232] [] [sql2008a] [] TIME=1383232883780 THREAD=2232 ID=SQL_000011 STEP= PHASE=Create local copy PIT=f5428bb4-6524-4656-836a-bb5d139a05b2 EVENTMSG=Not in catalog ARGS=
2013-10-31 10:21:23.780 INFO [2232] [] [sql2008a] [] SQL: Backup of SQL Server database SQL2008A.ViewEvent failed because of an error creating the replica.
2013-10-31 10:21:23.780 INFO [2232] [] [sql2008a] [] SQL: aborting the VDI snapshot for ViewEvent.
2013-10-31 10:21:25.114 INFO [2232] [] [sql2008a] [] SQL: Timeout for BACKUP is set for 300 seconds
2013-10-31 10:21:25.114 INFO [2232] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:27.016 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:28.725 INFO [2100] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:30.454 INFO [1192] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:33.307 INFO [2936] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:36.540 INFO [2232] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:38.441 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:40.156 INFO [2100] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:41.864 INFO [1192] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:44.708 INFO [2936] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:47.938 INFO [2232] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:48.890 INFO [2936] [] [sql2008a] [] SQL: Last native error: error number 3271, SQLState 42000, sql native info message [Microsoft][ODBC SQL Server Driver][SQL Server]A nonrecoverable I/O error occurred on file "EMCAPM_BACKUP_FILE_ViewComposer2013103115156:" 995(The I/O operation has been aborted because of either a thread exit or an application request.).
2013-10-31 10:21:48.890 INFO [2936] [] [sql2008a] [] SQL: processSQLMessages: Message = Msg 3271, SevLevel 16, State 1, SQLState 42000, sql native info [Microsoft][ODBC SQL Server Driver][SQL Server]A nonrecoverable I/O error occurred on file "EMCAPM_BACKUP_FILE_ViewComposer2013103115156:" 995(The I/O operation has been aborted because of either a thread exit or an application request.).
2013-10-31 10:21:48.890 INFO [2936] [] [sql2008a] [] SQL: [Microsoft][ODBC SQL Server Driver][SQL Server]A nonrecoverable I/O error occurred on file "EMCAPM_BACKUP_FILE_ViewComposer2013103115156:" 995(The I/O operation has been aborted because of either a thread exit or an application request.).
2013-10-31 10:21:48.890 INFO [2936] [] [sql2008a] [] SQL: Last native error: error number 3013, SQLState 42000, sql native info message [Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP DATABASE is terminating abnormally.
2013-10-31 10:21:48.890 INFO [2936] [] [sql2008a] [] SQL: processSQLMessages: Message = Msg 3013, SevLevel 16, State 1, SQLState 42000, sql native info [Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP DATABASE is terminating abnormally.
2013-10-31 10:21:48.890 INFO [2936] [] [sql2008a] [] SQL: The BACKUP command failed with: [Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP DATABASE is terminating abnormally.
2013-10-31 10:21:49.082 INFO [2936] [] [sql2008a] [] SQL: Disconnecting from database SQL2008A.master
2013-10-31 10:21:49.082 INFO [2936] [] [sql2008a] [] SQL: Released SQL Server connection handle for SQL2008A.master.
2013-10-31 10:21:49.082 INFO [2936] [] [sql2008a] [] SQL: Released SQL Server environment handle for SQL2008A.master.
2013-10-31 10:21:49.082 DEBUG [2936] [] [sql2008a] [] SQL: Ending user impersonation for this connection.
2013-10-31 10:21:49.082 DEBUG [2936] [] [sql2008a] [] SQL: closing impersonation handle.
2013-10-31 10:21:49.276 INFO [2100] [] [sql2008a] [] SQL: Last native error: error number 3271, SQLState 42000, sql native info message [Microsoft][ODBC SQL Server Driver][SQL Server]A nonrecoverable I/O error occurred on file "EMCAPM_BACKUP_FILE_lab511vc01_vum2013103115157:" 995(The I/O operation has been aborted because of either a thread exit or an application request.).
2013-10-31 10:21:49.276 INFO [2100] [] [sql2008a] [] SQL: processSQLMessages: Message = Msg 3271, SevLevel 16, State 1, SQLState 42000, sql native info [Microsoft][ODBC SQL Server Driver][SQL Server]A nonrecoverable I/O error occurred on file "EMCAPM_BACKUP_FILE_lab511vc01_vum2013103115157:" 995(The I/O operation has been aborted because of either a thread exit or an application request.).
2013-10-31 10:21:49.276 INFO [2100] [] [sql2008a] [] SQL: [Microsoft][ODBC SQL Server Driver][SQL Server]A nonrecoverable I/O error occurred on file "EMCAPM_BACKUP_FILE_lab511vc01_vum2013103115157:" 995(The I/O operation has been aborted because of either a thread exit or an application request.).
2013-10-31 10:21:49.276 INFO [2100] [] [sql2008a] [] SQL: Last native error: error number 3013, SQLState 42000, sql native info message [Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP DATABASE is terminating abnormally.
2013-10-31 10:21:49.276 INFO [2100] [] [sql2008a] [] SQL: processSQLMessages: Message = Msg 3013, SevLevel 16, State 1, SQLState 42000, sql native info [Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP DATABASE is terminating abnormally.
2013-10-31 10:21:49.276 INFO [2100] [] [sql2008a] [] SQL: The BACKUP command failed with: [Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP DATABASE is terminating abnormally.
2013-10-31 10:21:49.276 INFO [2100] [] [sql2008a] [] SQL: Disconnecting from database SQL2008A.master
2013-10-31 10:21:49.276 INFO [2100] [] [sql2008a] [] SQL: Released SQL Server connection handle for SQL2008A.master.
2013-10-31 10:21:49.276 INFO [2100] [] [sql2008a] [] SQL: Released SQL Server environment handle for SQL2008A.master.
2013-10-31 10:21:49.277 DEBUG [2100] [] [sql2008a] [] SQL: Ending user impersonation for this connection.
2013-10-31 10:21:49.277 DEBUG [2100] [] [sql2008a] [] SQL: closing impersonation handle.
2013-10-31 10:21:49.849 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:21:50.233 INFO [2232] [] [sql2008a] [] SQL: Last native error: error number 3271, SQLState 42000, sql native info message [Microsoft][ODBC SQL Server Driver][SQL Server]A nonrecoverable I/O error occurred on file "EMCAPM_BACKUP_FILE_ViewEvent20131031151513:" 995(The I/O operation has been aborted because of either a thread exit or an application request.).
2013-10-31 10:21:50.233 INFO [2232] [] [sql2008a] [] SQL: processSQLMessages: Message = Msg 3271, SevLevel 16, State 1, SQLState 42000, sql native info [Microsoft][ODBC SQL Server Driver][SQL Server]A nonrecoverable I/O error occurred on file "EMCAPM_BACKUP_FILE_ViewEvent20131031151513:" 995(The I/O operation has been aborted because of either a thread exit or an application request.).
2013-10-31 10:21:50.234 INFO [2232] [] [sql2008a] [] SQL: [Microsoft][ODBC SQL Server Driver][SQL Server]A nonrecoverable I/O error occurred on file "EMCAPM_BACKUP_FILE_ViewEvent20131031151513:" 995(The I/O operation has been aborted because of either a thread exit or an application request.).
2013-10-31 10:21:50.234 INFO [2232] [] [sql2008a] [] SQL: Last native error: error number 3013, SQLState 42000, sql native info message [Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP DATABASE is terminating abnormally.
2013-10-31 10:21:50.234 INFO [2232] [] [sql2008a] [] SQL: processSQLMessages: Message = Msg 3013, SevLevel 16, State 1, SQLState 42000, sql native info [Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP DATABASE is terminating abnormally.
2013-10-31 10:21:50.234 INFO [2232] [] [sql2008a] [] SQL: The BACKUP command failed with: [Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP DATABASE is terminating abnormally.
2013-10-31 10:21:50.234 INFO [2232] [] [sql2008a] [] SQL: Disconnecting from database SQL2008A.master
2013-10-31 10:21:50.234 INFO [2232] [] [sql2008a] [] SQL: Released SQL Server connection handle for SQL2008A.master.
2013-10-31 10:21:50.234 INFO [2232] [] [sql2008a] [] SQL: Released SQL Server environment handle for SQL2008A.master.
2013-10-31 10:21:50.234 DEBUG [2232] [] [sql2008a] [] SQL: Ending user impersonation for this connection.
2013-10-31 10:21:50.234 DEBUG [2232] [] [sql2008a] [] SQL: closing impersonation handle.
2013-10-31 10:21:50.998 INFO [1192] [] [sql2008a] [] SQL: Last native error: error number 3271, SQLState 42000, sql native info message [Microsoft][ODBC SQL Server Driver][SQL Server]A nonrecoverable I/O error occurred on file "EMCAPM_BACKUP_FILE_lab511vc01_RSA20131031151457:" 995(The I/O operation has been aborted because of either a thread exit or an application request.).
2013-10-31 10:21:50.998 INFO [1192] [] [sql2008a] [] SQL: processSQLMessages: Message = Msg 3271, SevLevel 16, State 1, SQLState 42000, sql native info [Microsoft][ODBC SQL Server Driver][SQL Server]A nonrecoverable I/O error occurred on file "EMCAPM_BACKUP_FILE_lab511vc01_RSA20131031151457:" 995(The I/O operation has been aborted because of either a thread exit or an application request.).
2013-10-31 10:21:50.998 INFO [1192] [] [sql2008a] [] SQL: [Microsoft][ODBC SQL Server Driver][SQL Server]A nonrecoverable I/O error occurred on file "EMCAPM_BACKUP_FILE_lab511vc01_RSA20131031151457:" 995(The I/O operation has been aborted because of either a thread exit or an application request.).
2013-10-31 10:21:50.998 INFO [1192] [] [sql2008a] [] SQL: Last native error: error number 3013, SQLState 42000, sql native info message [Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP DATABASE is terminating abnormally.
2013-10-31 10:21:50.998 INFO [1192] [] [sql2008a] [] SQL: processSQLMessages: Message = Msg 3013, SevLevel 16, State 1, SQLState 42000, sql native info [Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP DATABASE is terminating abnormally.
2013-10-31 10:21:50.998 INFO [1192] [] [sql2008a] [] SQL: The BACKUP command failed with: [Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP DATABASE is terminating abnormally.
2013-10-31 10:21:50.999 INFO [1192] [] [sql2008a] [] SQL: Disconnecting from database SQL2008A.master
2013-10-31 10:21:50.999 INFO [1192] [] [sql2008a] [] SQL: Released SQL Server connection handle for SQL2008A.master.
2013-10-31 10:21:50.999 INFO [1192] [] [sql2008a] [] SQL: Released SQL Server environment handle for SQL2008A.master.
2013-10-31 10:21:50.999 DEBUG [1192] [] [sql2008a] [] SQL: Ending user impersonation for this connection.
2013-10-31 10:21:50.999 DEBUG [1192] [] [sql2008a] [] SQL: closing impersonation handle.
2013-10-31 10:22:01.314 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:22:12.743 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:22:23.855 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:22:35.196 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:22:46.664 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:22:57.996 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:23:09.534 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:23:20.890 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:23:32.250 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:23:43.675 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:23:55.062 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:24:06.415 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:24:17.753 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:24:29.097 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:24:40.440 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:24:51.791 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:25:03.127 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:25:14.484 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:25:25.823 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:25:37.164 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:25:48.500 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:25:59.839 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:26:11.181 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:26:22.539 INFO [1260] [] [sql2008a] [] SQL: The BACKUP command for database SQL2008A.lab511vc01_vcdb failed because SQL Server failed to respond in a timely manner.
2013-10-31 10:26:22.539 INFO [1260] [] [sql2008a] [] TIME=1383233182539 THREAD=1260 ID=SQL_000018 STEP= PHASE=Create local copy PIT=f5428bb4-6524-4656-836a-bb5d139a05b2 EVENTMSG=Not in catalog ARGS= BACKUP,SQL2008A.lab511vc01_vcdb,
2013-10-31 10:26:22.539 INFO [1260] [] [sql2008a] [] SQL: Waiting for the SQL BACKUP command to complete
2013-10-31 10:26:30.671 ERROR [1260] [] [sql2008a] [] SQL: Error in the BACKUP command.
2013-10-31 10:26:30.671 ERROR [1260] [] [sql2008a] [] SQL: SQL Server Error in backup or restore operation for database SQL2008A.lab511vc01_vcdb. Details: .
2013-10-31 10:26:30.671 INFO [1260] [] [sql2008a] [] TIME=1383233190671 THREAD=1260 ID=SQL_000060 STEP= PHASE=Create local copy PIT=f5428bb4-6524-4656-836a-bb5d139a05b2 EVENTMSG=Not in catalog ARGS= SQL2008A.lab511vc01_vcdb,,
2013-10-31 10:26:30.671 INFO [1260] [] [sql2008a] [] SQL: Disconnecting from SQL database SQL2008A.lab511vc01_vcdb because of an error in pre freeze.
2013-10-31 10:26:30.671 INFO [1260] [] [sql2008a] [] SQL: Disconnecting from database SQL2008A.master
2013-10-31 10:26:30.672 INFO [1260] [] [sql2008a] [] SQL: Released SQL Server connection handle for SQL2008A.master.
2013-10-31 10:26:30.672 INFO [1260] [] [sql2008a] [] SQL: Released SQL Server environment handle for SQL2008A.master.
2013-10-31 10:26:30.672 DEBUG [1260] [] [sql2008a] [] SQL: Ending user impersonation for this connection.
2013-10-31 10:26:30.672 DEBUG [1260] [] [sql2008a] [] SQL: closing impersonation handle.
2013-10-31 10:26:30.672 INFO [1260] [] [sql2008a] [] SQL: Saving freeze result -1, for database SQL2008A.lab511vc01_vcdb id 9df9b32d-1af2-4657-bc18-23d6360c5f8c
2013-10-31 10:26:30.673 INFO [1396] [] [sql2008a] [] SQL: Gathering freeze response for 5 databases
2013-10-31 10:26:30.673 INFO [1396] [] [sql2008a] [] SQL: Finished wait for threads to freeze.
2013-10-31 10:26:30.673 INFO [1396] [] [sql2008a] [] SQL: Freeze result: 0 for database id 26fa538e-7d97-4d2b-944b-2f1b1dbc030f
2013-10-31 10:26:30.673 INFO [1396] [] [sql2008a] [] SQL: Freeze result: 0 for database id 3f08d792-dff5-4c54-bb45-113389b1a83e
2013-10-31 10:26:30.673 INFO [1396] [] [sql2008a] [] SQL: Freeze result: -1 for database id 9df9b32d-1af2-4657-bc18-23d6360c5f8c
2013-10-31 10:26:30.708 INFO [1396] [] [sql2008a] [] VssAgent::RunApplicationCommand - in catch block. command FreezeVSS failed
2013-10-31 10:26:30.708 INFO [1396] [] [sql2008a] [] OUT VssAgent::RunApplicationCommand
2013-10-31 10:26:30.708 INFO [1396] [] [sql2008a] [] VssAgent::FreezeVSS - Error returned from application agent during freeze
2013-10-31 10:26:30.708 INFO [1396] [] [sql2008a] [] IN AW_VssCmnReqInterface::AbortBackup
2013-10-31 10:26:30.708 INFO [1396] [] [sql2008a] [] The VSS backup component interface is invalid. Unable to abort backup.
2013-10-31 10:26:30.708 INFO [1396] [] [sql2008a] [] AW_VssAgent::run Freeze VSS Failed
FoolInTheRain
123 Posts
0
October 31st, 2013 12:00
Hi Bill,
while doing some reasearch on your issue, I came across the following that I'd like you to review and see if it will make a difference in your env:
http://blogs.msdn.com/b/dipanb/archive/2010/06/09/sql-server-query-performance-when-running-query-from-a-windows-2008-server.aspx
My thought here is to make sure SQL performance isn't affecting you.
I will also ask that you check to make sure you have all the required VSS hot fixes installed. (as well as all required sw/fixes! :-) )
Since you said you installed the 1.5 patch (CF08 or CF10?)...I assume you are talking about AppSync Server patch. Did you also install the required host plugin patch (CF02 or CF03) that was included?
If that helps...great!!
if not...a new set of logs and EMCReports should be collected and included when you open an SR with support.
(of course, if others have anything additional to add, I'd be glad to hear if their suggestions help!)
Jay
boyler05
2 Intern
2 Intern
•
143 Posts
0
October 31st, 2013 13:00
Thank you, Jay! You got me pointed in the right direction. It turns out there were 76 "important" Windows Updates since Win2008 R2 SP1, so I installed those updates and now AppSync works properly with the VSS freeze operation and everything that follows. I would suspect one of those updates fixed VSS. I am not sure which one. I guess the rule of thumb is to always install post-SP1 hotfixes to Windows 2008 R2 SP1.
I did not install any STORport driver updates or hotfixes, because I am not using iSCSI or Fibre Channel. I am just using VMware VMDKs (virtual disks). My next test will be an actual restore..!