Backup Exec 12.5 hangs during verification phase

Hello all,

I'm trying to track down why Backup Exec appears to hang during the verification phase.

This is what I have so far.

The backup phase of the backup completes without issue. When we start the verify phase, Backup Exec appears to get a few files in (normally under 2Gb out of 80Gb) and will hang. The files it appears to hang on do change, but are never in use, never locked and always on a network share.

We are backing up to an Iomega Rev 120Gb USB drive on a SBS 2003 box.
Backup Exec Media Sever and Administration Console : 12.5 Rev 2213
SP2 and the following hotfixes
324947
317436
325647
319242
324012
326004
323894
324011
327135
328459
329045
328462

I have enabled debugging as per this post : http://seer.entsupport.symantec.com/docs/254212.htm

At the end of this post are the logs from the end of the backup phase and beginning of the verification phase.

Can anyone help me troubleshoot this issue please. I have tried the Symantec forums (https://www-secure.symantec.com/connect/forums/verification-seems-hang-how-troubleshoot) but the response times there are awful and the problem is starting to drag on.

Many thanks in advance.

Log extracts follow (actual logs are too large to post here). These logs were taken from a Friday night backup which appeared to have completed backing up a few hours into the job and then it spent the entire weekend verifying the backup. When I came in on Monday morning, the backup was still verfiying and had got as far as 1.8Gb out of about 80. If anything is missing, please let me know and I will post it. When I came in on Monday morning the entire system running Backup Exec was slow and unresponsive (but not actually hung). Cancelling the job allowed the system to come back up to speed after a little while.



From <name>-SBS1-bengine01.log

[2804] 08/21/09 23:14:35 Informational : VERIFY - Using Encryption for SET.
[2804] 08/21/09 23:14:35 TF_OpenTape()
[2804] 08/21/09 23:14:35 TF_GetChannel( ) allocated channel 02E3F3B0
[2804] 08/21/09 23:14:35 Allocated 10 buffers, size 32768 bytes, total used: 328480
[2804] 08/21/09 23:14:35 HARDWARE COMPRESSION ===> Compression is NOT configurable.
[2804] 08/21/09 23:14:35 HARDWARE ENCRYPTION ===> Encryption is NOT supported.
[2804] 08/21/09 23:14:35 GET_DRV_INF: bsize = 1024
[2804] 08/21/09 23:14:35 GET_DRV_INF: preferredBlockSize = 1024
[2804] 08/21/09 23:14:35 TF_OpenSet( )
[2804] 08/21/09 23:14:35 Requested Set: ID = 3b15a8a6 Seq = 1 Set = 1
[2804] 08/21/09 23:14:35 Current VCB: ID = 3b15a8a6  Seq = 1  Set = 6
[2804] 08/21/09 23:14:35 End of TF_OpenSet: Ret_val = 0x00000000 Buffs = 10 HiWater = 7
[2804] 08/21/09 23:14:35 GotoBlock: VCB_PBA = 3, VCB_LBA = 0, LBA = 0,
[2804] 08/21/09 23:14:35            PBA = 3, offset = 0
[2804] 08/21/09 23:14:35 Set 1 was written by version 12.5.
[6984] 08/21/09 23:14:39 Updating status for: 'Client Backup' (0x4 0x0)
[6984] 08/21/09 23:14:39 Status for: 'Client Backup' updated
[6880] 08/21/09 23:18:27 DeviceManager: timeout event fired
[6880] 08/21/09 23:18:27 DeviceManager: processing pending requests
[6880] 08/21/09 23:18:27 DeviceManager: going to sleep for 900000 msecs

<-snip as the entries are identical for the next 2 days->

[6880] 08/24/09 12:33:29 DeviceManager: processing pending requests
[6880] 08/24/09 12:33:29 DeviceManager: going to sleep for 900000 msecs

And from <name>-SBS1-beremote01.log I get

[3660] 08/21/09 23:14:34 ndmpProcessRequests
[3660] 08/21/09 23:14:34 ndmp_recv_msg
[3660] 08/21/09 23:14:34 VSS BackupComplete called with success.
[3660] 08/21/09 23:14:34 VssSnapshotVolume::GetFailedWriterStatus() - waiting for IVssBackupComponents::GatherWriterMetadata to complete.
[3660] 08/21/09 23:14:34 VssSnapshotVolume::GetFailedWriterStatus() - IVssBackupComponents::GatherWriterStatus complete.
[3660] 08/21/09 23:14:34 VssSnapshotVolume::GetFailedWriterStatus() - Issuing Async QueryStatus check.
[3660] 08/21/09 23:14:34 ndmpSendReply: message:0xf335
[3660] 08/21/09 23:14:34 ndmpFreeMessage: message:0xf335
[3660] 08/21/09 23:14:34 ndmpProcessRequests
[3660] 08/21/09 23:14:34 ndmp_recv_msg
[3660] 08/21/09 23:14:34 ndmpdSnapshotDelete:
[3660] 08/21/09 23:14:34 Attempting to delete VSS snapshot set: {e99272ed-d9df-42b7-810f-2def0a5c0aad}
[3660] 08/21/09 23:14:35 VSS snapshot set deleted. Snapshot SetID = {e99272ed-d9df-42b7-810f-2def0a5c0aad}
[3660] 08/21/09 23:14:35 ndmpSendReply: message:0xf301
[3660] 08/21/09 23:14:35 ndmpFreeMessage: message:0xf301
[3660] 08/21/09 23:14:35 ndmpProcessRequests
[3660] 08/21/09 23:14:35 ndmp_recv_msg
[3660] 08/21/09 23:14:35 ndmpdPKCSSession: mode:end.
[3660] 08/21/09 23:14:35 ndmpSendReply: message:0xf33b
[3660] 08/21/09 23:14:35 ndmpFreeMessage: message:0xf33b
[3660] 08/21/09 23:14:35 ndmpProcessRequests
[3660] 08/21/09 23:14:35 ndmp_recv_msg
[3660] 08/21/09 23:14:35 ndmpdConnectClose: called.
[3660] 08/21/09 23:14:35 ndmpClose
[3660] 08/21/09 23:14:35 @@@@@@@MyCloseSocket called with sockfd = 1844(0x734)    retval = 0
[3660] 08/21/09 23:14:35 ndmpFreeMessage: message:0x902
[3660] 08/21/09 23:14:35 ndmpFreeMessage: message:0x902
[3660] 08/21/09 23:14:35 ndmpDestroyConnection
[2992] 08/22/09 01:59:44 NrdsAdvertiserThread: negative (purge) advertisement cycle started.
[2992] 08/22/09 01:59:44 NrdsAdvertiserThread: no purge is pending.
[2992] 08/22/09 01:59:44 NrdsAdvertiserThread: negative (purge) advertisement cycle complete.  Waiting 240 minutes before advertising again.

followed by this repeated constantly

[2992] 08/22/09 13:59:45 NrdsAdvertiserThread: negative (purge) advertisement cycle started.
[2992] 08/22/09 13:59:45 NrdsAdvertiserThread: no purge is pending.
[2992] 08/22/09 13:59:45 NrdsAdvertiserThread: negative (purge) advertisement cycle complete.  Waiting 240 minutes before advertising again.
[2988] 08/22/09 14:02:49 NrdsAdvertiserThread: advertisement cycle started.
[2988] 08/22/09 14:02:49 Informational: Restrict Anonymous Support is enabled
[2988] 08/22/09 14:02:49 creating DLE for local machine
[2988] 08/22/09 14:02:49 EnumClusterDLEs: Could not opening cluster :
[2988] 08/22/09 14:02:49 NrdsAdvertiserThread: EnumSelfDLE for file system 7 returned 0(0x0) and 1 DLEs
[2988] 08/22/09 14:02:49 NrdsAdvertiserThread: Nrds Message Len : 136.
[2988] 08/22/09 14:02:49 RMAN_EnumSelfDLE: AgentConfig GetOracleDBNames returned error. If Oracle Agent is installed, please run AgentConfig.
[2988] 08/22/09 14:02:49 NrdsAdvertiserThread: EnumSelfDLE for file system 14 returned 0(0x0) and 0 DLEs
[2988] 08/22/09 14:02:49 evFileSystem::EV_EnumSelfDLE:
[2988] 08/22/09 14:02:49 evFileSystem::RefreshTopology()
[2988] 08/22/09 14:02:49 CEvServices::GetEVInstallPath : Could not find EV registry key.
[2988] 08/22/09 14:02:49 CEvServices::GetEVInstallPath : Probably EV is not installed on this machine.
[2988] 08/22/09 14:02:49 This EV version is not supported by Backup Exec.
[2988] 08/22/09 14:02:49 evFileSystem::RefreshTopology: Failed while requesting XML.
[2988] 08/22/09 14:02:49 NrdsAdvertiserThread: EnumSelfDLE for file system 37 returned 1(0x1) and 0 DLEs
[2988] 08/22/09 14:02:49 NrdsAdvertiserThread: EnumSelfDLE for file system 39 returned 0(0x0) and 0 DLEs
[2988] 08/22/09 14:02:49 ConnectToServerEndPoint: dest=<name>-SBS1, service=6101
[2988] 08/22/09 14:02:49 CreateConnection type=0 on socket 2184 via BESocket OK
[2988] 08/22/09 14:02:49 NrdsAdvertiserThread: send of <name>-sbs1.<name>.local type 7 subtype 2 to target=<name>-SBS1 port=6101 succeeded
[2988] 08/22/09 14:02:49 @@@@@@@MyCloseSocket called with sockfd = 2184(0x888)    retval = 0
[2988] 08/22/09 14:02:49 ConnectToServerEndPoint: dest=<name>-SBS1, service=6101
[2988] 08/22/09 14:02:49 CreateConnection type=0 on socket 2676 via BESocket OK
[2988] 08/22/09 14:02:49 NrdsAdvertiserThread: send of <name>-sbs1.<name>.local type 7 subtype 2 to target=<name>-SBS1 port=6101 succeeded
[2988] 08/22/09 14:02:49 @@@@@@@MyCloseSocket called with sockfd = 2676(0xa74)    retval = 0
[2988] 08/22/09 14:02:49 NrdsAdvertiserThread: advertisement cycle complete.  Waiting 240 minutes before advertising again.