network connection timed out (41) - on Novell client 6.5

[m54samrr]

This is for Netbackup 7.1 Enterprise Server running on Windows Server 2008 R2 Enterprise SP1

Client: Novell server with a 6.5 BU Client

We have been assured Open File Manager is indeed "disabled" on the client, we had the client rebooted last evening prior to the scheduled incremental to see if there was something possibly stuck on the client that was preventing Netbackup from connecting.  Standard bpclntcmd -hn and -ip tests verify that the connectivity is there:

“D:\Program Files\Veritas\NetBackup\bin>bpclntcmd -hn servername
host servername: servername at 10.204.253.1
aliases:     servername     10.204.253.1

D:\Program Files\Veritas\NetBackup\bin>bpclntcmd -ip 10.204.253.1
host 10.204.253.1: servername at 10.204.253.1
aliases:     servername     10.204.253.1”

I also ran the bptestbpcd cmd with the –verbose and –debug switches:

“D:\Program Files\Veritas\NetBackup\bin\admincmd>bptestbpcd -client Client_servername -verbose -debug

09:17:15.569 [6276.8680] <2> bptestbpcd: VERBOSE = 0

09:17:16.630 [6276.8680] <2> vnet_async_connect: ../../libvlibs/vnet_connect.c.1376: 0: getsockopt SO_ERROR returned: 10061 0x0000274d

09:17:17.051 [6276.8680] <2> vnet_version_connect: ../../libvlibs/vnet_vnetd.c.1663: 0: Function failed: 24 0x00000018

09:17:17.051 [6276.8680] <2> do_vnetd_service: ../../libvlibs/vnet_connect.c.1610: 0: vnet_version_connect failed: 24 0x00000018

09:17:17.051 [6276.8680] <2> vnet_async_connect: ../../libvlibs/vnet_connect.c.1353: 0: do_service failed: 24 0x00000018

09:17:17.066 [6276.8680] <2> logconnections: BPCD CONNECT FROM 10.249.32.77.1021 TO 10.204.253.1.13782 fd = 616

09:17:17.066 [6276.8680] <2> vnet_vnetd_push_ipaddr: ../../libvlibs/vnet_vnetd.c.1783: 0: bptr[i]: 10 0x0000000a

09:17:17.066 [6276.8680] <2> vnet_vnetd_push_ipaddr: ../../libvlibs/vnet_vnetd.c.1783: 0: bptr[i]: 249 0x000000f9

09:17:17.066 [6276.8680] <2> vnet_vnetd_push_ipaddr: ../../libvlibs/vnet_vnetd.c.1783: 0: bptr[i]: 32 0x00000020

09:17:17.066 [6276.8680] <2> vnet_vnetd_push_ipaddr: ../../libvlibs/vnet_vnetd.c.1783: 0: bptr[i]: 77 0x0000004d0 1 2

10.249.32.77:1021 -> 10.204.253.1:13782

10.249.32.77:13724 <- 10.204.253.1:966

09:17:19.032 [6276.8680] <2> bpcr_get_peername_rqst: Server peername length = 23

09:17:19.251 [6276.8680] <2> bpcr_get_hostname_rqst: Server hostname length = 22

09:17:19.469 [6276.8680] <2> bpcr_get_clientname_rqst: Server client name length = 6

09:17:19.687 [6276.8680] <2> bpcr_get_version_rqst: bpcd version: 06520000

09:17:19.906 [6276.8680] <2> bpcr_get_platform_rqst: Server client platform length = 7

09:17:20.124 [6276.8680] <2> bpcr_get_version_rqst: bpcd version: 06520000

09:17:20.140 [6276.8680] <2> get_short: (2) premature end of file (byte 1)

09:17:20.140 [6276.8680] <2> bpcr_patch_version_rqst: get_short failed: 5

09:17:20.140 [6276.8680] <2> bpcr_patch_version_rqst: bpcd returned failure: 23

09:17:20.140 [6276.8680] <16> bpcr_patch_version_rqst() failed, status = 23,  errno = 0: get_patch_version

<16>bptestbpcd main: Function get_client_patch_version(Client_servername) failed: 23

09:17:20.140 [6276.8680] <16> bptestbpcd main: Function get_client_patch_version(Client_servername) failed: 23

09:17:20.140 [6276.8680] <2> get_long: (2) premature end of file (byte 1)

09:17:20.140 [6276.8680] <2> bpcr_patch_version_rqst: bpcr_get_version_rqst() failed: 0

09:17:20.140 [6276.8680] <2> bpcr_patch_version_rqst: bpcd returned failure: 23

09:17:20.140 [6276.8680] <16> bpcr_patch_version_rqst() failed, status = 23,  errno = 0: get_patch_version

<16>bptestbpcd main: Function get_server_patch_version(Client_servername) failed: 23

09:17:20.140 [6276.8680] <16> bptestbpcd main: Function get_server_patch_version(Client_servername) failed: 23

09:17:20.140 [6276.8680] <2> get_long: (2) premature end of file (byte 1)

09:17:20.140 [6276.8680] <2> get_master_and_emm_servers: bpcr_read_host_config_rqst() failed: 16

<16>bptestbpcd main: Function get_master_and_emm_servers(Client_servername)failed: 16

09:17:20.140 [6276.8680] <16> bptestbpcd main: Function get_master_and_emm_servers(Client_servername) failed: 16

PEER_NAME = Main_Backup_servername

HOST_NAME = Client_servername

CLIENT_NAME = servername

VERSION = 0x06520000

PLATFORM = NetWare

PATCH_VERSION =

SERVER_PATCH_VERSION =

MASTER_SERVER = _UNKNOWN_

EMM_SERVER = _UNKNOWN_

09:17:20.140 [6276.8680] <2> vnet_vnetd_push_ipaddr: ../../libvlibs/vnet_vnetd.c.1783: 0: bptr[i]: 10 0x0000000a

09:17:20.140 [6276.8680] <2> vnet_vnetd_push_ipaddr: ../../libvlibs/vnet_vnetd.c.1783: 0: bptr[i]: 249 0x000000f9

09:17:20.140 [6276.8680] <2> vnet_vnetd_push_ipaddr: ../../libvlibs/vnet_vnetd.c.1783: 0: bptr[i]: 32 0x00000020

09:17:20.140 [6276.8680] <2> vnet_vnetd_push_ipaddr: ../../libvlibs/vnet_vnetd.c.1783: 0: bptr[i]: 77 0x0000004d

09:17:20.140 [6276.8680] <2> vnet_pop_byte: ../../libvlibs/vnet.c.1159: 0: errno: 0 0x00000000

09:17:20.140 [6276.8680] <2> vnet_pop_byte: ../../libvlibs/vnet.c.1161: 0: Function failed: 9 0x00000009

09:17:20.140 [6276.8680] <2> vnet_pop_string: ../../libvlibs/vnet.c.1241: 0: Function failed: 9 0x00000009

09:17:20.140 [6276.8680] <2> vnet_pop_signed: ../../libvlibs/vnet.c.1285: 0: Function failed: 9 0x00000009

09:17:20.140 [6276.8680] <2> vnet_pop_status: ../../libvlibs/vnet.c.1363: 0: Function failed: 9 0x00000009

09:17:20.140 [6276.8680] <2> vnet_begin_connect_back: ../../libvlibs/vnet_vnetd.c.613: 0: status: 9 0x00000009

09:17:20.140 [6276.8680] <2> bpcr_get_vnetd_socket_rqst: vnet_begin_connect_back failed: 9

09:17:20.140 [6276.8680] <2> bpcr_new_standard_socket_rqst: bpcr_get_vnetd_socket_rqst failed: 23

<16>bptestbpcd main: Function bpcr_new_standard_socket_rqst(Client_servername) failed: 23

09:17:20.140 [6276.8680] <16> bptestbpcd main: Function bpcr_new_standard_socket_rqst(Client_servername) failed: 23

09:17:20.140 [6276.8680] <2> put_short: (10) network write() error: An operation was attempted on something that is not a socket. ; socket = 616

09:17:20.140 [6276.8680] <2> bpcr_disconnect_rqst: bpcr protocol error - couldn't send request type

<16>bptestbpcd main: Function bpcr_new_standard_socket_rqst(Client_servername) failed: 23

09:17:20.140 [6276.8680] <16> bptestbpcd main: Function bpcr_new_standard_socket_rqst(Client_servername) failed: 23

<2>bptestbpcd: socket close failed

09:17:20.140 [6276.8680] <2> bptestbpcd: socket close failed<2>bptestbpcd: EXIT status = 22

09:17:20.140 [6276.8680] <2> bptestbpcd: EXIT status = 22socket close failed”

The details on the error in the Netbackup Admin Console are also listed below.

"Detailed Status:

5/10/2012 11:29:54 PM - Info bpbrm(pid=152) servername is the host to backup data from     
5/10/2012 11:29:54 PM - Info bpbrm(pid=152) reading file list from client        
5/10/2012 11:29:58 PM - Info bpbrm(pid=152) starting bpbkar32 on client         
5/10/2012 11:29:58 PM - Info bpbkar32(pid=0) Backup started           
5/10/2012 11:29:59 PM - Info bptm(pid=2628) start            
5/10/2012 11:29:59 PM - Info bptm(pid=2628) using 65536 data buffer size        
5/10/2012 11:29:59 PM - Info bptm(pid=2628) setting receive network buffer to 263168 bytes      
5/10/2012 11:29:59 PM - Info bptm(pid=2628) using 30 data buffers         
5/10/2012 11:30:00 PM - Info nbjm(pid=8168) starting backup job (jobid=14997) for client servername, policy Server_Policy_Novell, schedule Incremental  
5/10/2012 11:30:00 PM - Info nbjm(pid=8168) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=14997, request id:{48851B37-501D-40B4-BD5E-73D70B037AC2})  
5/10/2012 11:30:00 PM - requesting resource osprscbackup-hcart-robot-tld-1
5/10/2012 11:30:00 PM - requesting resource main_servername.NBU_CLIENT.MAXJOBS.servername
5/10/2012 11:30:00 PM - requesting resource main_servername.NBU_POLICY.MAXJOBS.Server_Policy_Novell
5/10/2012 11:30:00 PM - granted resource main_servername.NBU_CLIENT.MAXJOBS.servername
5/10/2012 11:30:00 PM - granted resource main_servername.NBU_POLICY.MAXJOBS.Server_Policy_Novell
5/10/2012 11:30:00 PM - granted resource BD1740
5/10/2012 11:30:00 PM - granted resource HP.ULTRIUM4-SCSI.000
5/10/2012 11:30:00 PM - granted resource osprscbackup-hcart-robot-tld-1
5/10/2012 11:30:00 PM - estimated 51800200 Kbytes needed
5/10/2012 11:30:00 PM - Info nbjm(pid=8168) started backup job for client servername, policy Server_Policy_Novell, schedule Incremental on storage unit osprscbackup-hcart-robot-tld-1
5/10/2012 11:30:00 PM - Info bptm(pid=2628) start backup           
5/10/2012 11:30:00 PM - Info bptm(pid=2628) backup child process is pid 944.3068       
5/10/2012 11:30:00 PM - Info bptm(pid=2628) Waiting for mount of media id BD1740 (copy 1) on server osprscbackup.
5/10/2012 11:30:00 PM - Info bptm(pid=944) start            
5/10/2012 11:30:01 PM - started process bpbrm (152)
5/10/2012 11:30:05 PM - connecting
5/10/2012 11:30:10 PM - connected; connect time: 00:00:05
5/10/2012 11:30:11 PM - mounting BD1740
5/10/2012 11:30:57 PM - Info bptm(pid=2628) media id BD1740 mounted on drive index 0, drivepath {4,0,0,0}, drivename HP.ULTRIUM4-SCSI.000, copy 1
5/10/2012 11:31:08 PM - mounted; mount time: 00:00:57
5/10/2012 11:31:12 PM - positioning BD1740 to file 472
5/10/2012 11:31:54 PM - positioned BD1740; position time: 00:00:42
5/10/2012 11:31:54 PM - begin writing
5/11/2012 12:35:52 AM - Error bpbrm(pid=152) cannot send mail to     
5/11/2012 12:36:03 AM - end writing; write time: 01:04:09
network connection timed out(41)"

Any help would be much appreciated, we are at kind of a roadblock at this point on this one Novell server.  This has been going on over a week that this server has not been backed up.

Thanks!

[Marianne]

Do you have bpcd log on client?

Please follow steps under Troubleshooting heading in this TN to increase logging level (although OFM is disabled):

http://www.symantec.com/docs/TECH56502

Please post log as attachment.

[m54samrr]

I just made the request to our sister dept. to follow those steps, once they reply with the logs I will post them up, thank you for the response.

[m54samrr]

Ok follow up here, our sister dept. followed the steps in that KB article, and well the increase in logging was horrendous.  At this point after a day of logging, the resultant log is close to 3.5Gb. 

I'm having them try and use this Novell TID http://www.novell.com/support/kb/doc.php?id=3992687 to ensure that OFM is deactivated and the driver unloaded during backup times.  If that doesn't work then we will probably try and reload the BU client on the Novell server.

[m54samrr · Accepted solution]

I wanted to post a solution to this thread I started back a couple weeks previous.  In the end we had the Novell NBU client restarted which reset the NBU service on the client.  This resolved our issues after ensuring we had the master server and media server defined in the host record.  In the end there were other mitigating factors including network contention and outages that were not reported and taken into account when trying to figure out why this client was not responding to the requests made on the master server for backup's/restores ect.