cancel
Showing results for 
Search instead for 
Did you mean: 

12.0 sporadically hangs server

Mike_Barron
Not applicable

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.

 

This has happened with our SQL server backup the last two times. Previously it happened with differential and full backups on different servers.

 

I have no clue, so any help would be appreciated

 

Also, I have the latest SP and updates installed.

 

Thanks,

Message Edited by Mike_Barron on 02-13-2009 09:25 AM
Message Edited by Mike_Barron on 02-13-2009 09:26 AM
0 REPLIES 0