NBU 7.1 Socket read failed after adding new client

[Willie_SA]

NetBackup Master/Media server UNIX SOLARIS 10 , NetBackup 7.1

Client Windows 2008 (X64)    Client NBU 7.1

I added new cleint.

Can ping full name and IP from master and client

Can telnet from master on port 13723, 13724 and 13782

checked fireewall is OFF

Added client to Master server parameters

Checked services on client.

Bounced NBU on Master

Cannot connect to client. - socket read failed

What am I missing?

[Marianne]

NBU 7.1 will first attempt to connect to PBX (port 1556).
If that fails, vnetd (13724) will be attempted.

Do the following test:

Create bpcd log folder on client (install-path\veritas\netbackup\logs).

Run the following from master/media server:

bptestbpcd -client <client-name> -verbose -debug

Please post output of command as well as client's bpcd log.

[Willie_SA]

This is what I got from the screen - the commend is still running - but it just sits there - probibly waiting for a time out. If it is not enough - or wrong info - I can send more/other.

e -debugnv/netbackup/bin/admincmd # ./bptestbpcd -client cprvnmsdatapro1 -verbos

13:54:03.002 [27318] <2> bptestbpcd: VERBOSE = 0

13:54:03.003 [27318] <2> read_client: dname=., offline=0, online_at=0

13:54:03.003 [27318] <2> read_client: dname=.., offline=0, online_at=0

13:54:03.003 [27318] <2> read_client: dname=CO_0, offline=0, online_at=0

13:54:03.003 [27318] <2> read_client: dname=OA_0, offline=0, online_at=0

13:54:03.003 [27318] <2> read_client: dname=host_info, offline=0, online_at=0

13:54:03.003 [27318] <2> db_freeEXDB_INFO: ?

13:54:03.004 [27318] <2> file_to_addrinfo: ../../libvlibs/vnet_addrinfo.c.6635: 0: fopen() failed: 2 0x00000002

13:54:03.004 [27318] <2> file_to_addrinfo: ../../libvlibs/vnet_addrinfo.c.6636: 0: fopen() failed: /usr/openv/var/host_cache/0dc/f86cdedc+veritas_pbx,1,4,2,2,0+cprvnmsdatapro1.txt

13:54:03.014 [27318] <2> file_to_addrinfo: ../../libvlibs/vnet_addrinfo.c.6635: 0: fopen() failed: 2 0x00000002

13:54:03.014 [27318] <2> file_to_addrinfo: ../../libvlibs/vnet_addrinfo.c.6636: 0: fopen() failed: /usr/openv/var/host_cache/0dc/f86cdedc+vnetd,1,4,2,2,0+cprvnmsdatapro1.txt

13:54:03.028 [27318] <2> file_to_addrinfo: ../../libvlibs/vnet_addrinfo.c.6635: 0: fopen() failed: 2 0x00000002

13:54:03.028 [27318] <2> file_to_addrinfo: ../../libvlibs/vnet_addrinfo.c.6636: 0: fopen() failed: /usr/openv/var/host_cache/0dc/f86cdedc+bpcd,1,4,2,2,0+cprvnmsdatapro1.txt

13:54:03.038 [27318] <2> vnet_pbxConnect: pbxConnectEx Succeeded

13:54:03.039 [27318] <2> logconnections: BPCD CONNECT FROM 172.17.0.136.61077 TO 172.17.1.65.1556 fd = 4

13:54:03.041 [27318] <2> vnet_pbxConnect: pbxConnectEx Succeeded

13:54:03.114 [27318] <2> do_pbx_service: ../../libvlibs/vnet_connect.c.1776: 0: via PBX: VNETD CONNECT FROM 172.17.0.136.61078 TO 172.17.1.65.1556 fd = 5

13:54:03.114 [27318] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.445: 0: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a

13:54:03.325 [27318] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.462: 0: ipc_string: 60032 e -debugnv/netbackup/bin/admincmd # ./bptestbpcd -client cprvnmsdatapro1 -verbos

13:54:03.002 [27318] <2> bptestbpcd: VERBOSE = 0

13:54:03.003 [27318] <2> read_client: dname=., offline=0, online_at=0

13:54:03.003 [27318] <2> read_client: dname=.., offline=0, online_at=0

13:54:03.003 [27318] <2> read_client: dname=CO_0, offline=0, online_at=0

13:54:03.003 [27318] <2> read_client: dname=OA_0, offline=0, online_at=0

13:54:03.003 [27318] <2> read_client: dname=host_info, offline=0, online_at=0

13:54:03.003 [27318] <2> db_freeEXDB_INFO: ?

13:54:03.004 [27318] <2> file_to_addrinfo: ../../libvlibs/vnet_addrinfo.c.6635: 0: fopen() failed: 2 0x00000002

13:54:03.004 [27318] <2> file_to_addrinfo: ../../libvlibs/vnet_addrinfo.c.6636: 0: fopen() failed: /usr/openv/var/host_cache/0dc/f86cdedc+veritas_pbx,1,4,2,2,0+cprvnmsdatapro1.txt

13:54:03.014 [27318] <2> file_to_addrinfo: ../../libvlibs/vnet_addrinfo.c.6635: 0: fopen() failed: 2 0x00000002

13:54:03.014 [27318] <2> file_to_addrinfo: ../../libvlibs/vnet_addrinfo.c.6636: 0: fopen() failed: /usr/openv/var/host_cache/0dc/f86cdedc+vnetd,1,4,2,2,0+cprvnmsdatapro1.txt

[Willie_SA]

Attached find the full output.

BTW it did not write to the log file - maybe I did something wrong.

[Marianne]

I am suprised that nothing is logged in client's bpcd folder...

Initial connection on port 1556 was successful:

13:54:03.039 [27318] <2> logconnections: BPCD CONNECT FROM 172.17.0.136.61077 TO 172.17.1.65.1556 fd = 4

13:54:03.041 [27318] <2> vnet_pbxConnect: pbxConnectEx Succeeded

I was expecting to see and error in client's bpcd log with 'Connect Back'...

Is IP address correct for client?

Which NBU services are running on the Client?

All of these should be running:

                NetBackup Client Service
                NetBackup Legacy Client Service
                NetBackup Legacy Network Service
                Symantec Private Branch Exchange

[Willie_SA]

Ok, I thought I did it wrong. Created log file on mastr.

The command was done on Master and the output is from the screen of master.

Do you need the client log?

These services are running (same on other clients) and I did restart the services.

NetBackup Client Service
                NetBackup Legacy Client Service
                NetBackup Legacy Network Service
 

IP 172.17.1.65 is the correct IP add.

[Marianne]

Yes, we need to see on client what happens when master/media server tries to connect to bpcd (via PBX or vnetd) on client. See my 1st reply:

Create bpcd log folder on client (install-path\veritas\netbackup\logs).

Hopefully Symantec Private Branch Exchange is also running on client? (a bit further down in the Services list...)

[mph999]

So am I ...

Make sure the bpcd folder is created under ...netbackup\logs (on the client)

Martin

[Willie_SA]

Attached is the client bpcd log.

Thank you

[mph999]

14:55:46.750 [15268.14340] <2> setup_debug_log: switched debug log file for bpcd

14:55:46.750 [15268.14340] <2> bpcd main: VERBOSE = 0

14:55:46.750 [15268.14340] <2> logparams: C:\Program Files\Veritas\NetBackup\bin\bpcd.exe -standalone

14:55:46.753 [15268.14340] <2> process_requests: offset to GMT -7200

14:55:46.762 [15268.14340] <2> logconnections: BPCD ACCEPT FROM 172.17.0.136.41418 TO 172.17.1.65.1556 fd = 528

14:55:46.762 [15268.14340] <2> process_requests: setup_sockopts complete

14:55:46.777 [15268.14340] <2> bpcd peer_hostname: Connection from host cprvnmsnetb.citypower.co.za (172.17.0.136) port 41418

14:55:46.777 [15268.14340] <2> bpcd valid_server: comparing cprvnmsnetb and cprvnmsnetb.citypower.co.za

14:55:46.778 [15268.14340] <2> file_to_addrinfo: ../../libvlibs/vnet_addrinfo.c.6635: 0: fopen() failed: 2 0x00000002

14:55:46.779 [15268.14340] <2> file_to_addrinfo: ../../libvlibs/vnet_addrinfo.c.6636: 0: fopen() failed: C:\Program Files\Veritas\NetBackup\var\host_cache\1c3\ba5d9fc3+0,1,2,0,1,0+cprvnmsnetb.citypower.co.za.txt

14:55:48.438 [15268.14340] <4> bpcd valid_server: hostname comparison succeeded

14:55:51.148 [15268.14340] <2> process_requests: output socket port number = 1

14:55:51.148 [15268.14340] <2> get_long: (1) cannot read (byte 1) from network: A non-blocking socket operation could not be completed immediately.

14:55:51.148 [15268.14340] <2> get_vnetd_forward_socket: get_string ipc_string failed: 10035

14:55:51.148 [15268.14340] <16> process_requests: get_vnetd_forward_socket failed: 23

15:05:12.890 [8888.13468] <2> setup_debug_log: switched debug log file for bpcd

15:05:12.890 [8888.13468] <2> bpcd main: VERBOSE = 0

15:05:12.890 [8888.13468] <2> logparams: C:\Program Files\Veritas\NetBackup\bin\bpcd.exe -standalone

15:05:12.892 [8888.13468] <2> process_requests: offset to GMT -7200

15:05:12.902 [8888.13468] <2> logconnections: BPCD ACCEPT FROM 172.17.0.136.42993 TO 172.17.1.65.1556 fd = 532

15:05:12.902 [8888.13468] <2> process_requests: setup_sockopts complete

15:05:12.915 [8888.13468] <2> bpcd peer_hostname: Connection from host cprvnmsnetb.citypower.co.za (172.17.0.136) port 42993

15:05:12.915 [8888.13468] <2> bpcd valid_server: comparing cprvnmsnetb and cprvnmsnetb.citypower.co.za

15:05:12.918 [8888.13468] <4> bpcd valid_server: hostname comparison succeeded

15:05:12.918 [8888.13468] <2> process_requests: output socket port number = 1

15:05:12.918 [8888.13468] <2> get_long: (1) cannot read (byte 1) from network: A non-blocking socket operation could not be completed immediately.

15:05:12.918 [8888.13468] <2> get_vnetd_forward_socket: get_string ipc_string failed: 10035

15:05:12.918 [8888.13468] <16> process_requests: get_vnetd_forward_socket failed: 23

[Willie_SA]

You are correct again.

The Symantec Private Branch Exchange is there and it is started.

TX

[Willie_SA]

Sorry - those log was wrong.

Here is the correct log

[mph999]

Right, accept my apologies in advance if I am wrong - it's late here, I'm a bit tired and having trouble thinking ..

From this :

15:05:12.918 [8888.13468] <2> get_vnetd_forward_socket: get_string ipc_string failed: 10035

15:05:12.918 [8888.13468] <16> process_requests: get_vnetd_forward_socket failed: 23

Looks like bpcd is trying to connect back via vnetd.

We could look at the output of netstat -a  and -an (can't think which so just get both, thx) 

I don't know yet if we need to see the vnetd log (again on client) but if we do, we would need you to get the vnetd log AND the bpcd log again (so that they both cover the same time period ) - hold back on this for the minute.

Can you check the firewall if definately off.

This issue could be to do with the state of the sockets on the client - netstat will show what state they re in.  To be honest, it is probably just easier to reboot the client and see if that resolves the issue,

Thanks,

martin

[mph999 · Accepted solution]

Hmm, looks like I 'might' be on the right lines:

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

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

At the moment, I am going to suggest this is not a NBU issue.

Try looking here ...

 http://support.microsoft.com/default.aspx?scid=kb;en-us;184802

 http://support.microsoft.com/default.aspx?scid=kb;en-us;Q126962

Martin

[Willie_SA]

Hi, Sorry for the delay - but other things took my week-end.

Anyway - I am now totally confused.

All of a sudden the system can connect and all seems to be OK now. I tested and tried everything for more than 2 weeks. And without any changes it just worked.

I can now schedule the backup as it should be.

Thank you for everyones' time on this.

[Marianne]

Client was probably rebooted in the meantime - possibly because the OS issues that caused this also caused problems with application on the client... as Martin suggested over the weekend.

Keep an eye on this client - this issue might very well pop up again.