EUB
8 years agoLevel 4
Communication errors
Hello I got: Win2008R2 Master server Tape Library Quantum Scalar i500 Oracle(RHEL) client machine 3 defferent Windows 2008R2 client machine All 3 Windows client backups fails with error 98: ...
Here some logs from linux client(oracle):
more /usr/openv/netbackup/logs/user_ops/dbext/logs/16210.0.1469728327
Backup started Thu Jul 28 23:52:08 2016
23:52:09 Initiating backup
23:52:14 INF - Starting bpbrm
23:52:18 INF - Data socket = kzwnb01.eub.kz.IPC:/tmp/vnet-23466469728336472524000005994-8CAH0F;d15070320c90dd5ffac89c4ea9cdd487;11;1800
23:52:18 INF - Name socket = kzwnb01.eub.kz.IPC:/tmp/vnet-23467469728336748882000005994-J6NAJG;0a108b72858ec6d9bd551781ef6f47e2;11;1800
23:52:18 INF - Job id = 494667
23:52:18 INF - Backup id = KZLORA04.EUB.KZ_1469728332
23:52:18 INF - Backup time = 1469728332
23:52:19 INF - Policy name = KZLORA04_RMAN
23:52:19 INF - Snapshot = 0
23:52:19 INF - Frozen image = 0
23:52:19 INF - Backup copy = 0
23:52:20 INF - Master server = kzwnb01.eub.kz
23:52:20 INF - Media server = kzwnb01.eub.kz
23:52:20 INF - Multiplexing = 0
23:52:20 INF - New data socket = kzwnb01.eub.kz.IPC:/tmp/vnet-23460469728336212972000005994-KxZxkF;705f029b4a0a3b6cfb04117e0c2fd54b;11;1800
23:52:20 INF - Encrypt = 0
23:52:21 INF - Use shared memory = 0
23:52:21 INF - Compression = 1
23:52:21 INF - Encrypt = 0
23:52:21 INF - Keep logs = 28
23:52:21 INF - Client read timeout = 11800
23:52:22 INF - Media mount timeout = 0
23:52:23 INF - Waiting for mount of media id 000031 on server kzwnb01.eub.kz for writing
00:22:24 INF - Server status = 6
00:22:25 INF - Backup by oracle on client KZLORA04.EUB.KZ using policy KZLORA04_RMAN, sched Default-Application-Backup:the backup failed to back up the requested files
more /usr/openv/netbackup/logs/user_ops/dbext/logs/8917.0.1469744559
Backup started Fri Jul 29 04:22:39 2016
04:22:40 Initiating backup
04:22:45 INF - Starting bpbrm
04:22:49 INF - Data socket = kzwnb01.eub.kz.IPC:/tmp/vnet-09842469744567634243000006003-ej7Pmz;875d7aabfe6ff2b16a21976d8824cb61;11;1800
04:22:49 INF - Name socket = kzwnb01.eub.kz.IPC:/tmp/vnet-09845469744567914147000006003-rEMi6z;1b6c020056facf0c0385460f839867c9;11;1800
04:22:49 INF - Job id = 494897
04:22:49 INF - Backup id = KZLORA04.EUB.KZ_1469744564
04:22:50 INF - Backup time = 1469744564
04:22:50 INF - Policy name = KZLORA04_RMAN
04:22:50 INF - Snapshot = 0
04:22:50 INF - Frozen image = 0
04:22:51 INF - Backup copy = 0
04:22:51 INF - Master server = kzwnb01.eub.kz
04:22:51 INF - Media server = kzwnb01.eub.kz
04:22:51 INF - Multiplexing = 0
04:22:51 INF - New data socket = kzwnb01.eub.kz.IPC:/tmp/vnet-09841469744567347672000006003-hfeiCy;850f6d95072bbe80eb9a6f7d5c7e57ec;11;1800
04:22:52 INF - Encrypt = 0
04:22:52 INF - Use shared memory = 0
04:22:52 INF - Compression = 1
04:22:52 INF - Encrypt = 0
04:22:52 INF - Keep logs = 28
04:22:53 INF - Client read timeout = 11800
04:22:53 INF - Media mount timeout = 0
04:22:54 INF - Waiting for mount of media id 000031 on server kzwnb01.eub.kz for writing
04:23:02 INF - Waiting for mount of media id 000039 on server kzwnb01.eub.kz for writing
04:23:47 INF - Mounted media id 000039
04:25:00 INF - Beginning backup on server kzwnb01.eub.kz of client KZLORA04.EUB.KZ
04:25:09 INF - Server status = 0
04:25:10 INF - Backup by oracle on client KZLORA04.EUB.KZ using policy KZLORA04_RMAN, sched Default-Application-Backup:the requested operation was successfully completed
more /usr/openv/netbackup/logs/vnetd/log.072916
00:00:21.127 [7174] <2> setup_debug_log: switched debug log file for vnetd
00:22:23.544 [7174] <2> vnet_pbxAcceptSocket: Accepted sock[9] from 172.20.2.42:63851
00:22:23.544 [4350] <8> ProcessRequests: [vnetd.c:635] msg VNETD ACCEPT FROM 172.20.2.42.63851 TO 172.20.1.66.1556 fd = 9
00:22:23.549 [4350] <8> vnet_version_accept: [vnetd.c:1092] *actual_version 11 0xb
00:22:23.590 [4350] <8> ProcessRequests: [vnetd.c:718] msg Request VN_REQUEST_CONNECT_FORWARD_SOCKET(10)
00:22:23.590 [4350] <8> vnet_generate_hashes: [vnet_vnetd.c:1592] hash_str1 d98e9d5f31b49718fc042bc9d50f1083
00:22:23.590 [4350] <8> vnet_generate_hashes: [vnet_vnetd.c:1593] hash_str2 9bd1cb593c3423ffe14d6a14714c1d3f
00:22:23.590 [4350] <8> process_connect_forward_socket: [vnetd.c:1972] ipc_string /tmp/vnet-04350469730143590705000005997-AHrPJK
00:22:23.796 [4350] <8> vnet_send_network_socket: [vnet_vnetd.c:1400] hash_str2 9bd1cb593c3423ffe14d6a14714c1d3f
00:22:23.797 [4350] <8> ProcessRequests: [vnetd.c:720] status 0 0x0
00:22:25.052 [7174] <2> vnet_pbxAcceptSocket: Accepted sock[9] from 172.20.2.42:63864
00:22:25.052 [4362] <8> ProcessRequests: [vnetd.c:635] msg VNETD ACCEPT FROM 172.20.2.42.63864 TO 172.20.1.66.1556 fd = 9
00:22:25.054 [4362] <8> vnet_version_accept: [vnetd.c:1092] *actual_version 11 0xb
00:22:25.096 [7174] <2> vnet_pbxAcceptSocket: Accepted sock[9] from 172.20.2.42:63866
00:22:25.097 [4364] <8> ProcessRequests: [vnetd.c:635] msg VNETD ACCEPT FROM 172.20.2.42.63866 TO 172.20.1.66.1556 fd = 9
00:22:25.097 [4362] <8> ProcessRequests: [vnetd.c:718] msg Request VN_REQUEST_CONNECT_FORWARD_SOCKET(10)
00:22:25.097 [4362] <8> vnet_generate_hashes: [vnet_vnetd.c:1592] hash_str1 576d95acd0f17fbe6bd549e0aab642ce
00:22:25.097 [4362] <8> vnet_generate_hashes: [vnet_vnetd.c:1593] hash_str2 3c2f65ced6ec152d45b2eddfa580d20e
00:22:25.097 [4362] <8> process_connect_forward_socket: [vnetd.c:1972] ipc_string /tmp/vnet-04362469730145097185000005997-6HhwGO
00:22:25.099 [4364] <8> vnet_version_accept: [vnetd.c:1092] *actual_version 11 0xb
00:22:25.141 [4364] <8> ProcessRequests: [vnetd.c:718] msg Request VN_REQUEST_CONNECT_FORWARD_SOCKET(10)
00:22:25.141 [4364] <8> vnet_generate_hashes: [vnet_vnetd.c:1592] hash_str1 5b74da90edf0ef5a00c351fa99595d90
00:22:25.142 [4364] <8> vnet_generate_hashes: [vnet_vnetd.c:1593] hash_str2 d22a419731e051d6da314c20bd947b20
00:22:25.142 [4364] <8> process_connect_forward_socket: [vnetd.c:1972] ipc_string /tmp/vnet-04364469730145141749000005997-gk5KNO
00:22:25.303 [4362] <8> vnet_send_network_socket: [vnet_vnetd.c:1400] hash_str2 3c2f65ced6ec152d45b2eddfa580d20e
00:22:25.303 [4362] <8> ProcessRequests: [vnetd.c:720] status 0 0x0
00:22:25.352 [4364] <8> vnet_send_network_socket: [vnet_vnetd.c:1400] hash_str2 d22a419731e051d6da314c20bd947b20
00:22:25.352 [4364] <8> ProcessRequests: [vnetd.c:720] status 0 0x0
02:26:27.258 [7174] <2> vnet_pbxAcceptSocket: Accepted sock[9] from 172.20.2.42:57941
more /usr/openv/netbackup/logs/dbclient/log.072916
00:07:24.487 [16210] <16> readCommFile: ERR - timed out after 900 seconds while reading from /usr/openv/netbackup/logs/user_ops/dbext/logs/16210.0.1469728327
00:07:24.498 [16210] <2> conf_update_time: ../../libvlibs/nbconf_glue.cpp.436: errno: 2 2 0x00000002
00:07:24.498 [16210] <2> conf_update_time: ../../libvlibs/nbconf_glue.cpp.437: path: /home/oracle/bp.conf
00:22:23.359 [16210] <16> readCommFile: ERR - timed out after 900 seconds while reading from /usr/openv/netbackup/logs/user_ops/dbext/logs/16210.0.1469728327
00:22:23.359 [16210] <32> serverResponse: ERR - could not read from comm file </usr/openv/netbackup/logs/user_ops/dbext/logs/16210.0.1469728327>
00:22:23.359 [16210] <16> CreateNewImage: ERR - serverResponse() failed
00:22:23.362 [16210] <16> VxBSACreateObject: ERR - Could not create new image with file /29rbkbg0_1_2.
00:22:23.362 [16210] <16> xbsa_CreateObject: ERR - VxBSACreateObject: Failed with error:
Server Status: Communication with the server has not been initiated or the server status has not been retrieved from the serve
00:22:35.962 [16210] <2> conf_update_time: ../../libvlibs/nbconf_glue.cpp.436: errno: 2 2 0x00000002
00:22:35.962 [16210] <2> conf_update_time: ../../libvlibs/nbconf_glue.cpp.437: path: /home/oracle/bp.conf
00:22:35.963 [16210] <4> sbtend: INF - --- END of SESSION ---
00:22:35.963 [16210] <8> close_image: Session being terminated abnormally, cleaning up
00:22:35.963 [16210] <4> close_image: INF - backup FAILED
00:22:35.963 [16210] <4> close_image: INF ---- end of Backup ---
00:22:35.963 [16210] <16> VxBSAEndTxn: ERR - Transaction ended with active Backup/Restore.
00:22:35.963 [16210] <16> xbsa_EndTransaction: ERR - VxBSAEndTxn: Failed with error:
The transaction was aborted.
Forget about Oracle backups for now (or start a new discussion for that).
This is the error that you need to troubleshoot first:
28.07.2016 13:31:11 - Error bptm(pid=4040) error requesting media, TpErrno = Robot operation failed
28.07.2016 13:31:11 - Warning bptm(pid=4040) media id 000106 load operation reported an error
Media id 000106 could not be loaded into the tape drive.
Have you confirmed that the media and tape drive(s) are compatibile?
E.g. LTO6 can write to LTO5 and LTO6 tapes.
Are you seeing the same issue with other media id's or just this one?
Thanks for quick apply
All tape media are LTO6, all drives are compatibile
Errors appers with different drive ID an different media ID
Tape library reports dont include robot fails(reports via library web-interface)
Policies are old and works well.
Is the master server also the media server and robot control host?
This is where you need to troubleshoot the load error.
Ensure bptm folder exists under NetBackup\logs and turn up logging level in Host Properties to 3 or higher.
(Remember to drop down logging level when problem has been fixed).
Add VERBOSE entry to vm.conf (in volmgr folder) and restart NBU Device Management service.
After next status 98 error, check bptm log for errors as well as Event Viewer System and Application logs.
Other troubleshooting can be done by loading/unloading these tapes that gave the errors with 'robtest' utility.