Verification seems to hang - how to troubleshoot?

[Ian_L]

Whilst juggling tapes and trying to solve this problem, I have come across another problem unfortunately.

The backup stage appears to have completed successfully, but the verification process appears to be hanging.

Looking at the Job Actrivity pane, it seems to be stuck on a single file. The file is a .GBK file around 850Mb in size. So far the verification of this file has taken 1hr 40mins which seems to be excessive.

The file is an old archive file, it is not in use.

What steps should I take to troubleshoot this issue? Can I get more detailed activity (something that shows progress _is_ being made)?

Or is 1hr 45mins (now) an acceptable time to verify an 850Mb file? I hope not - we have lots of these :\

Thanks to everyone here who has supported me so far as I try to come to grips with Backup Exec so far.

Ian

[Ben_L_]

How long does the backup take?

[Ian_L]

Hi Ben

Backup takes about 4 hours in total. Then the verification starts

Thanks for replying
Ian

[Ian_L]

Actually it hung the entire system!

It seems monumentally slow accessing resources across the network. I have uninstalled and re-installed the program but it has made little difference.

The system did seem to continue in the background but new processes would not launch (though they would load into memory). Ended up having to do a hard reset.

Can I enable verbose debug logging somehow?

Thanks

[Ian_L]

When I say monumentally slow, it takes 30 seconds (a timed 30 seconds - not a finger in the air 30 seconds :D ) to expand a node on a networked machine, or to select that folder for backup.

[Ben_L_]

Ian,

if the backup takes 4 hours, then the verify can take the same amount of time to verify the data.  This is fairly normal.

As for debugging, yes you can enable debugging. just follow this technote to enable it.
http://seer.entsupport.symantec.com/docs/254212.htm

[Ian_L]

Hi Ben,

The backup is around 50Gb. It takes 4 hours to back this up (roughly). Why does it take (in the end before I had to reboot the server) more than 2 hours to verify 1.7%? Assuming I reset the machine _just_ before it moved on to the next file, a 4 hour backup will take around 117hours!


I mentioned the other problem I was having so I have created another backup job. I have uninstalled and re-installed the agent on the networked machine (we only backup one machine and the server) which appears to have helped with the slow network response.

Last nights backup finished the backup section at 23:49 after starting at 21:00. It backed up a total of 81Gb (the reinstalled network agent has really helped here).

Today I come in and the verify process, which started at 23:49 (2 seconds later than the backup finished) and is still running now (8:50am) having verified 556Mb.

I think that there definitely is a problem. I shall leave the job running for today, incase there is anything you would like me to try whilst it is running. Also incase it is unstable again, maybe we might be able to track that down at the same time.

I shall also enable debugging when I get the chance, but I don't want to do anything that will upset the system or lose me a chance to find the problem.

Thanks again for replying Ben, I look forward to hearing back from you.

Ian

[Ian_L]

Looks like it hung the system again. Tried to fire up event viewer and again it loads into memory but no window opens.

Will reboot the system with debugging enabled. If you could please advise what I am supposed to be looking for to troubleshoot these issues, I would be very grateful.

Ian

[Ben_L_]

My best suggestion at this point would be to call into support and have them take a look at the issues you are facing.

[Ian_L]

Thanks Ben,

I'll see what other support options are available to us (I have detailed the problem as I have experienced it, but the problem in actuality is with a client).

Could you explain what the 'technical support' means next to your name - I thought I was already dealing with someone from support. Are there different levels of support - i.e a call in is escalating the problem to more 'technical' support?

It would be nice to finish the problem here incase someone else experiences it and they can at least have access to a guide for basic troubleshooting (check agents are upto date etc, enable debugging, look in the log for errors etc)

Also I can bookmark it in case another client has the problem - looks so much more professional than phoning support again :)

Thanks again for your efforts Ben, if we can try and finish it here that would be ideal.

Ian

[Ian_L]

There are plenty of other hanging under verify issues  - that is why I think an attempt to solve this problem online, may benefit other users.

Of course, every one of those cases linked to are different to each other, and this situation. But a good generic troubleshooting guide would be incredibly useful to all of them I would imagine.

Only my opinion of course.

Ian

[Ian_L]

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.

Does this give me anything to hunt down?

Cheers

[Ian_L · Accepted solution]

Don't know if this has just slipped under the radar with the updated information or if we have reached the limit of support available on here since Ben_L suggested calling support instead of using the forums.

Hopefully we will get a resolution one way or another anyway.

It is definitely a problem with *that* installation. I have uninstalled and re-installed it on that machine and it continues to fail quite spectacularly. Installing it on another machine works fine so the pressure is off me for now at least, but I can't imagine that Symantec Technical Support can't give you a better idea of some troubleshooting steps other than telling me verification normally takes the same time as a backup and pointing me to enable debugging.

It does strike me as kind of pointless helping someone to enable debugging then abondoning the question when they post the logs - what do you expect them to do! </rant>

Anyways - lets hope we can sort this out either way. Excuse my tone but I've had a crappy morning already dealing with SAGE support and it annoys me that Symantec appear no better. Actually, that is a little unfair - at least Symantec haven't washed their hands off the problem the minute the software completed installing, regardless of whether it worked or not. But you're not far behind at this point!

Hurrumph :)