17 years ago

12.0 sporadically hangs server

I've tried to solve this issue for a few months now since upgrading to 12.0. I can't find a definitive answer as to why BE is hanging the host server. I get error 0008821 on whatever job it hangs on.

Here are the logs from the most recent incident.

beengine.log

[4264] 02/12/09 17:00:05 JobEngine::LaunchJob
[4264] 02/12/09 17:00:05 RunJobWithGuidAndServer( {10BFC5CF-7004-4417-99B5-4E7EAAD6DF31}, ARCHIVE ) = 0
[5084] 02/12/09 17:00:05 Thread for job SQL Server Full ({10BFC5CF-7004-4417-99B5-4E7EAAD6DF31}) starting
[5084] 02/12/09 17:00:05 viaNetwork enabled 0
[5084] 02/12/09 17:00:05 viaNetwork useAny 0
[5084] 02/12/09 17:00:05 viaNetwork protocol 0
[5084] 02/12/09 17:00:05 viaNetwork subnet ---><---
[5084] 02/12/09 17:00:05 viaNetwork MAC ---><---
[5084] 02/12/09 17:00:05 viaNetwork IPv4 Enabled 0
[5084] 02/12/09 17:00:05 viaNetwork IPv4 subnetAddress 0.0.0.0
[5084] 02/12/09 17:00:05 viaNetwork IPv4 subnetMask 0.0.0.0
[5084] 02/12/09 17:00:05 viaNetwork IPv4 autoObtain 0
[5084] 02/12/09 17:00:05 viaNetwork IPv4 physical
[5084] 02/12/09 17:00:05 viaNetwork selectedProtocol 0
[5084] 02/12/09 17:00:05 viaNetwork InterfaceIndexProtocol 0
[5084] 02/12/09 17:00:05 viaNetwork InterfaceIndex 0
[5084] 02/12/09 17:00:05 viaNetwork subnet <zero>
[5084] 02/12/09 17:00:05 viaNetwork PrefixLength 0
[5084] 02/12/09 17:00:05 viaNetwork ipAddr <zero>
[5084] 02/12/09 17:00:05 viaNetwork FallBackOptions 0xF Protocol Tunnel NIC Subnet
[4312] 02/12/09 17:00:05 Updating status for: 'SQL Server Full' (0x0)
[4312] 02/12/09 17:00:05 Status for: 'SQL Server Full' updated
[5084] 02/12/09 17:00:05 Checking for Evaluation expiration.
[5084] 02/12/09 17:00:05 ENGSCRPT: ConvertDeviceName osId = 0X2b
[5084] 02/12/09 17:00:05 ENGSCRPT: IN - oldDeviceName = ERPSVR
[5084] 02/12/09 17:00:05 ENGSCRPT: OUT - newName = ERPSVR
[5084] 02/12/09 17:00:06 SetupCryptInfoInBSD: Backup encryption options: bHWEncryption=0,bSWEncryption=0,bSWEncryptionIfNoHW=0
[5084] 02/12/09 17:00:06 ENGSCRPT: ConvertDeviceName osId = 0X2b
[5084] 02/12/09 17:00:06 ENGSCRPT: IN - oldDeviceName = ERPSVR
[5084] 02/12/09 17:00:06 ENGSCRPT: OUT - newName = ERPSVR
[5084] 02/12/09 17:00:06 ENGSCRPT: ConvertDeviceName osId = 0X2b
[5084] 02/12/09 17:00:06 ENGSCRPT: IN - oldDeviceName = ERPSVR
[5084] 02/12/09 17:00:06 ENGSCRPT: OUT - newName = ERPSVR
[5084] 02/12/09 17:00:06 ENGSCRPT: No script found
[5084] 02/12/09 17:00:06 Failed to Load AllowExcludes key, We will update DR file evenif there are userExcludes. Error: 5
[1048] 02/12/09 17:00:06 DeviceManager: incoming event fired
[1048] 02/12/09 17:00:06 DeviceManager: processing pending requests
[1048] 02/12/09 17:00:06 DeviceManager: query cache miss
[1048] 02/12/09 17:00:06 Available and held drives from the pool
[1048] 02/12/09 17:00:06     SQL Server Full {4db14561-348d-4c17-b7bc-fc14d07bd540}.0
[1048] 02/12/09 17:00:06 Drives not in use by the Engine
[1048] 02/12/09 17:00:06     SQL Server Full {4db14561-348d-4c17-b7bc-fc14d07bd540}.0
[1048] 02/12/09 17:00:06 Drives available (not in use and not held)
[1048] 02/12/09 17:00:06     SQL Server Full {4db14561-348d-4c17-b7bc-fc14d07bd540}.0
[1048] 02/12/09 17:00:06 Handing out session {f9240806-5e2c-4937-b664-5221530fe090} based on available drive:
[1048] 02/12/09 17:00:06     SQL Server Full {4db14561-348d-4c17-b7bc-fc14d07bd540}.0
[1048] 02/12/09 17:00:06 DeviceManager: returned result to caller 0x00000000
[1048] 02/12/09 17:00:06 DeviceManager: going to sleep for 900000 msecs
[5332] 02/12/09 17:00:06 BackupJob: thread id 0x000014D4 acquired device SQL Server Full.
[5332] 02/12/09 17:00:06 BackupJob: thread id 0x000014D4 trying to mount appending volume.
[5332] 02/12/09 17:00:07 BackupJob: thread id 0x000014D4 unable to mount appending volume, attempting scratch mount.
[5332] 02/12/09 17:00:13 Updating session {f9240806-5e2c-4937-b664-5221530fe090} with drive SQL Server Full {4db14561-348d-4c17-b7bc-fc14d07bd540}.1
[5332] 02/12/09 17:00:13 BackupJob: thread id 0x000014D4 medium successfully mounted.
[5084] 02/12/09 17:00:13 Media Label: B2D000782
[5084] 02/12/09 17:00:13 Media Label: {8609b5de-fc3e-4ebd-a5a9-6429cbc24d9e}
[5084] 02/12/09 17:00:13 Overwrite Protected Until: 2/14/2009 5:00:12 PM
[5084] 02/12/09 17:00:13 Appendable Until: 12/31/1899 7:00:00 PM
[5084] 02/12/09 17:00:13 TAPEALERT: Get TapeAlert Flags Return Code = 0X0
[5084] 02/12/09 17:00:13 TAPEALERT: TapeAlert Device Flag = 0X0
[5084] 02/12/09 17:00:13 TAPEALERT: TapeAlert Changer Flag = 0X0
[5084] 02/12/09 17:00:13 TAPEALERT: Get TapeAlert Flags Return Code = 0X0
[5084] 02/12/09 17:00:13 TAPEALERT: Get TapeAlert Flags Return Code = 0X0
[5084] 02/12/09 17:00:13 Job Family ID: {0D708CE4-250E-4C2C-8306-0A49F1AD39CD}
[5084] 02/12/09 17:00:13 SQL Server Full Block size:   1024
[5084] 02/12/09 17:00:13 SQL Server Full Buffer size: 32768
[5084] 02/12/09 17:00:13 SQL Server Full Num buffers:    10
[5084] 02/12/09 17:00:13 SQL Server Full High water:      7
[5084] 02/12/09 17:00:13 Enter CheckHostBSDsForSnaps
[5084] 02/12/09 17:00:13 Exit CheckHostBSDsForSnaps: false
[5084] 02/12/09 17:00:13 NDMPAgentConnector:SetupConnection(): Data Server = ERPSVR
[5084] 02/12/09 17:00:13 Could not resolve the 'ndmp' service, error: 10109, using port 10000
[5084] 02/12/09 17:00:13 ndmpConnectEx: Querying the neighbour advertisement cache to discover information on 'ERPSVR' ...
[5084] 02/12/09 17:00:13 ndmpConnectEx : Control Connection information: A connection was established between end-points 10.0.0.25:2121 and 10.0.0.26:10000.
[5084] 02/12/09 17:00:13 NDMP version 3 connection CONNECTED
[5084] 02/12/09 17:00:15 IsLocalAgent:beclass::BEConvertServerNamePlus returned error: 87
[5084] 02/12/09 17:00:15 IsLocalAgent:beclass::BEConvertServerNamePlus returned error: 87
[5084] 02/12/09 17:00:15 DI processor not needed, performing traditional backup
[5084] 02/12/09 17:00:15 Failed to Load AllowExcludes key, We will update DR file evenif there are userExcludes. Error: 5
[5084] 02/12/09 17:00:15 TF_OpenTape()
[5084] 02/12/09 17:00:15 TF_GetChannel( ) allocated channel 02CF9180
[5084] 02/12/09 17:00:15 TF_GetDriveContext ...
     sessionGuid = {f9240806-5e2c-4937-b664-5221530fe090}
     initAsync = 1
[5084] 02/12/09 17:00:15 HARDWARE COMPRESSION ===> Compression is NOT configurable.
[5084] 02/12/09 17:00:15 HARDWARE ENCRYPTION ===> Encryption is NOT supported.
[5084] 02/12/09 17:00:15 GET_DRV_INF: bsize = 1024
[5084] 02/12/09 17:00:15 TF_GetDriveContext returning 0x00000000, context = 2D0F270
[5084] 02/12/09 17:00:15 Allocated 2 buffers, size 32768 bytes, total used: 65696
[5084] 02/12/09 17:00:15 HARDWARE COMPRESSION ===> Compression is NOT configurable.
[5084] 02/12/09 17:00:15 HARDWARE ENCRYPTION ===> Encryption is NOT supported.
[5084] 02/12/09 17:00:15 GET_DRV_INF: bsize = 1024
[5084] 02/12/09 17:00:15 DeviceIsNT4Server: agent info: [Major Version=5 Minor Version=2 Build Number=3790 ServicePack Major=2 ServicePack Minor=0 SuiteMask=272 ProductType=3 ProcessorType=Intel x86].
[5084] 02/12/09 17:00:15 DeviceIsIA64Server: agent info: [Major Version=5 Minor Version=2 Build Number=3790 ServicePack Major=2 ServicePack Minor=0 SuiteMask=272 ProductType=3 ProcessorType=Intel x86].
[5084] 02/12/09 17:00:15 TF_OpenSet( )
[5084] 02/12/09 17:00:15 FreeFormatEnv( cur_fmt=65535 )
[5084] 02/12/09 17:00:15 RewindDrive mover ret = 0 (0x0)
[5084] 02/12/09 17:00:15   ret_val = 0
[5084] 02/12/09 17:00:15 Requested Set: ID = ffffffff Seq = -1 Set = -1
[5084] 02/12/09 17:00:15 Attempting to VCB storage media
[5084] 02/12/09 17:00:15   TpRead( ):
[5084] 02/12/09 17:00:15 Error = 1101 Req = 6144 Got = 1024
[5084] 02/12/09 17:00:15 HARDWARE COMPRESSION ===> Compression is NOT configurable.
[5084] 02/12/09 17:00:15 HARDWARE ENCRYPTION ===> Encryption is NOT supported.
[5084] 02/12/09 17:00:15 GET_DRV_INF: bsize = 1024
[5084] 02/12/09 17:00:15 FreeFormatEnv( cur_fmt=65535 )
[5084] 02/12/09 17:00:15 SetupFormatEnv( fmt=0 )
[5084] 02/12/09 17:00:15 Current media tape header was written by "VERITAS:PVL".
[5084] 02/12/09 17:00:15   TpRead( ):
[5084] 02/12/09 17:00:15 Error = 1104 Req = 6144 Got = 0
[5084] 02/12/09 17:00:15 FreeFormatEnv( cur_fmt=0 )
[5084] 02/12/09 17:00:15 RewindDrive mover ret = 0 (0x0)
[5084] 02/12/09 17:00:15   ret_val = 0
[5084] 02/12/09 17:00:15 PositionAtSet( ): TF Msg = e
[5084] 02/12/09 17:00:15 RewindDrive mover ret = 0 (0x0)
[5084] 02/12/09 17:00:15   ret_val = 0
[5084] 02/12/09 17:00:15 RewindDrive mover ret = 0 (0x0)
[5084] 02/12/09 17:00:15   ret_val = 0
[5084] 02/12/09 17:00:15   UI Msg = 8003
[5084] 02/12/09 17:00:15 HARDWARE COMPRESSION ===> Compression is NOT configurable.
[5084] 02/12/09 17:00:15 HARDWARE ENCRYPTION ===> Encryption is NOT supported.
[5084] 02/12/09 17:00:15 GET_DRV_INF: bsize = 1024
[5084] 02/12/09 17:00:15 RewindDrive mover ret = 0 (0x0)
[5084] 02/12/09 17:00:15   ret_val = 0
[5084] 02/12/09 17:00:15 FreeFormatEnv( cur_fmt=65535 )
[5084] 02/12/09 17:00:15 SetupFormatEnv( fmt=0 )
[5084] 02/12/09 17:00:15 End of TF_OpenSet: Ret_val = 0x00000000 Buffs = 2 HiWater = 7
[5084] 02/12/09 17:00:15 B2D Buffered Writes ===> Setting buffering to default.
[5084] 02/12/09 17:00:15 WriteEndSet( 1 ) returning 0x00000000
[5084] 02/12/09 17:00:15 Current Block is = 3
[5084] 02/12/09 17:00:15 Media Server to initiate connection for data transfer
[5084] 02/12/09 17:00:15 TF_InitMediaServerReverseConnection : Data Connection information: A connection was established between end-points 10.0.0.25:2122 and 10.0.0.26:3234.
[5084] 02/12/09 17:00:17
dataStartBackup: ndmpSendRequest returned: 0x0, 0
[5084] 02/12/09 17:00:18 TF_NDMPStartWrite(): Started MediaServerWriteThread 932
[4312] 02/12/09 17:00:20 Updating status for: 'SQL Server Full' (0x1)
[4312] 02/12/09 17:00:20 Status for: 'SQL Server Full' updated
[1048] 02/12/09 17:15:06 DeviceManager: timeout event fired
[1048] 02/12/09 17:15:06 DeviceManager: processing pending requests
[1048] 02/12/09 17:15:06 DeviceManager: going to sleep for 900000 msecs

beremote.log

[2868] 02/12/09 17:05:36 NrdsAdvertiserThread: negative (purge) advertisement cycle started.

[2868] 02/12/09 17:05:36 NrdsAdvertiserThread: no purge is pending.
[2868] 02/12/09 17:05:36 NrdsAdvertiserThread: negative (purge) advertisement cycle complete. Waiting 60 minutes before advertising again.
[2864] 02/12/09 17:07:35 NrdsAdvertiserThread: advertisement cycle started.
[2864] 02/12/09 17:07:35 Informational: Restrict Anonymous Support is enabled
[2864] 02/12/09 17:07:35 creating DLE for local machine
[2864] 02/12/09 17:07:35 EnumClusterDLEs: Could not opening cluster :
[2864] 02/12/09 17:07:35 NrdsAdvertiserThread: EnumSelfDLE for file system 7 returned 0(0x0) and 1 DLEs
[2864] 02/12/09 17:07:35 NrdsAdvertiserThread: Nrds Message Len : 139.
[2864] 02/12/09 17:07:35 RMAN_EnumSelfDLE: AgentConfig GetOracleDBNames returned error. If Oracle Agent is installed, please run AgentConfig.
[2864] 02/12/09 17:07:35 NrdsAdvertiserThread: EnumSelfDLE for file system 14 returned 0(0x0) and 0 DLEs
[2864] 02/12/09 17:07:35 evFileSystem::EV_EnumSelfDLE:
[2864] 02/12/09 17:07:35 evFileSystem::RefreshTopology()
[2864] 02/12/09 17:07:35 CEvServices::GetEVInstallPath : Could not find EV registry key.
[2864] 02/12/09 17:07:35 CEvServices::GetEVInstallPath : Probably EV is not installed on this machine.
[2864] 02/12/09 17:07:35 This EV version is not supported by Backup Exec.
[2864] 02/12/09 17:07:35 evFileSystem::RefreshTopology: Failed while requesting XML.
[2864] 02/12/09 17:07:35 NrdsAdvertiserThread: EnumSelfDLE for file system 37 returned 1(0x1) and 0 DLEs
[2864] 02/12/09 17:07:35 ConnectToServerEndPoint: dest=ARCHIVE, service=6101
[2864] 02/12/09 17:07:35 CreateConnection type=0 on socket 1132 via BESocket OK
[2864] 02/12/09 17:07:35 NrdsAdvertiserThread: send of Archive.braunambulances.com type 7 subtype 2 to target=ARCHIVE port=6101 succeeded
[2864] 02/12/09 17:07:35 @@@@@@@MyCloseSocket called with sockfd = 1132(0x46c) retval = 0
[2864] 02/12/09 17:07:35 ConnectToServerEndPoint: dest=ARCHIVE, service=6101
[2864] 02/12/09 17:07:35 CreateConnection type=0 on socket 1124 via BESocket OK
[2864] 02/12/09 17:07:35 NrdsAdvertiserThread: send of Archive.braunambulances.com type 7 subtype 2 to target=ARCHIVE port=6101 succeeded
[2864] 02/12/09 17:07:35 @@@@@@@MyCloseSocket called with sockfd = 1124(0x464) retval = 0
[2864] 02/12/09 17:07:35 NrdsAdvertiserThread: advertisement cycle complete. Waiting 60 minutes before advertising again.