16:07:15.098 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 21 16:07:15.098 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:07:15.114 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:07:15.114 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54310 TO xxx.10.212.239.1556 fd = 1120 16:07:15.114 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:07:15.145 [3976.3196] <2> db_end: Need to collect reply 16:07:15.161 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 258, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:07:15.161 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:07:15.161 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:07:15.161 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:07:15.161 [3976.3196] <2> read_backup: fragment_num = 258 16:07:15.161 [3976.3196] <2> read_backup: Kbytes = 2000000 16:07:15.161 [3976.3196] <2> read_backup: remainder = 0 16:07:15.161 [3976.3196] <2> read_backup: id = QXH126 16:07:15.161 [3976.3196] <2> read_backup: file_num = 21 16:07:15.161 [3976.3196] <2> read_backup: block_size = 65536 16:07:15.161 [3976.3196] <2> read_backup: offset = 625042 16:07:15.161 [3976.3196] <2> read_backup: data_format = 0 16:07:15.161 [3976.3196] <2> read_backup: **************************************************** 16:07:15.161 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:07:15.161 [3976.3196] <2> read_data: Total Kbytes transferred 512096384 16:07:15.176 [3976.3196] <2> read_position: read position on drive index 0, is LBA 625043 16:07:15.176 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:07:15.176 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430834835 16:07:15.176 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430834835 16:07:20.168 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:07:23.538 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:07:23.538 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:07:23.538 [2352.4600] <16> socksend: failed to send this: 16:07:25.862 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:07:36.268 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:07:40.542 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:07:41.884 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:07:41.884 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:07:41.884 [2352.4600] <16> socksend: failed to send this: 16:07:43.553 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:07:46.190 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:07:59.887 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:08:06.174 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:08:06.174 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:08:06.174 [2352.4600] <16> socksend: failed to send this: 16:08:07.001 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:08:09.372 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:08:14.036 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:08:14.036 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:08:14.036 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:08:14.036 [3976.3196] <2> read_data: waited for empty buffer 486 times, delayed 1183 times 16:08:14.036 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430834894 4 bptm 3976 waited for empty buffer 486 times, delayed 1183 times 16:08:14.036 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 81, msg = LOG 1430834894 4 bptm 3976 waited for empty buffer 486 times, delayed 1183 times 16:08:14.036 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:08:14.052 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:08:14.052 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54311 TO xxx.10.212.239.1556 fd = 1144 16:08:14.052 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:08:14.083 [3976.3196] <2> db_end: Need to collect reply 16:08:14.099 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:08:14.099 [3976.3196] <2> read_data: Total Kbytes transferred 514096384 16:08:14.099 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:08:14.099 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:08:14.099 [3976.3196] <16> socksend: failed to send this: 16:08:14.099 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:08:14.099 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430834894 16:08:14.099 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430834894 16:08:14.099 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:08:14.114 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:08:14.114 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54312 TO xxx.10.212.239.1556 fd = 1168 16:08:14.114 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:08:14.161 [3976.3196] <2> db_end: Need to collect reply 16:08:14.177 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 258, 2000000 Kbytes at 33979.510 Kbytes/sec 16:08:14.177 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:08:14.177 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430834894 QXH126 22 16:08:14.177 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430834894 QXH126 22 16:08:14.177 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 22 16:08:14.177 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:08:14.192 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430834894 QXH126 16:08:14.192 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430834894 QXH126 16:08:14.192 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 22 16:08:14.192 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:08:14.208 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:08:14.208 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54313 TO xxx.10.212.239.1556 fd = 1168 16:08:14.208 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:08:14.239 [3976.3196] <2> db_end: Need to collect reply 16:08:14.255 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 259, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:08:14.255 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:08:14.255 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:08:14.255 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:08:14.255 [3976.3196] <2> read_backup: fragment_num = 259 16:08:14.255 [3976.3196] <2> read_backup: Kbytes = 2000000 16:08:14.255 [3976.3196] <2> read_backup: remainder = 0 16:08:14.255 [3976.3196] <2> read_backup: id = QXH126 16:08:14.255 [3976.3196] <2> read_backup: file_num = 22 16:08:14.255 [3976.3196] <2> read_backup: block_size = 65536 16:08:14.255 [3976.3196] <2> read_backup: offset = 656294 16:08:14.255 [3976.3196] <2> read_backup: data_format = 0 16:08:14.255 [3976.3196] <2> read_backup: **************************************************** 16:08:14.255 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:08:14.255 [3976.3196] <2> read_data: Total Kbytes transferred 514096384 16:08:14.255 [3976.3196] <2> read_position: read position on drive index 0, is LBA 656295 16:08:14.255 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:08:14.255 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430834894 16:08:14.255 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430834894 16:08:16.938 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:08:16.938 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:08:16.938 [2352.4600] <16> socksend: failed to send this: 16:08:17.921 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:08:21.291 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:08:24.052 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:08:25.581 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:08:25.581 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:08:25.581 [2352.4600] <16> socksend: failed to send this: 16:08:26.798 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:08:28.545 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:08:30.979 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:08:34.005 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:08:34.005 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:08:34.005 [2352.4600] <16> socksend: failed to send this: 16:08:38.732 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:08:41.680 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:08:45.674 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:08:47.343 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:08:47.343 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:08:47.343 [2352.4600] <16> socksend: failed to send this: 16:08:49.730 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:08:49.730 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:08:49.730 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:08:49.730 [3976.3196] <2> read_data: waited for empty buffer 178 times, delayed 569 times 16:08:49.730 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430834929 4 bptm 3976 waited for empty buffer 178 times, delayed 569 times 16:08:49.730 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 80, msg = LOG 1430834929 4 bptm 3976 waited for empty buffer 178 times, delayed 569 times 16:08:49.730 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:08:49.730 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:08:49.730 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54314 TO xxx.10.212.239.1556 fd = 1144 16:08:49.730 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:08:49.777 [3976.3196] <2> db_end: Need to collect reply 16:08:49.793 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:08:49.793 [3976.3196] <2> read_data: Total Kbytes transferred 516096384 16:08:49.793 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:08:49.793 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:08:49.793 [3976.3196] <16> socksend: failed to send this: 16:08:49.793 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:08:49.793 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430834929 16:08:49.793 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430834929 16:08:49.793 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:08:49.808 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:08:49.808 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54315 TO xxx.10.212.239.1556 fd = 1120 16:08:49.808 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:08:49.855 [3976.3196] <2> db_end: Need to collect reply 16:08:49.871 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 259, 2000000 Kbytes at 56377.731 Kbytes/sec 16:08:49.871 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:08:49.871 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430834929 QXH126 23 16:08:49.871 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430834929 QXH126 23 16:08:49.871 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 23 16:08:49.871 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:08:49.886 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430834929 QXH126 16:08:49.886 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430834929 QXH126 16:08:49.886 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 23 16:08:49.886 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:08:49.886 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:08:49.886 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54316 TO xxx.10.212.239.1556 fd = 1120 16:08:49.886 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:08:49.917 [3976.3196] <2> db_end: Need to collect reply 16:08:49.933 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 260, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:08:49.933 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:08:49.933 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:08:49.933 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:08:49.933 [3976.3196] <2> read_backup: fragment_num = 260 16:08:49.933 [3976.3196] <2> read_backup: Kbytes = 2000000 16:08:49.933 [3976.3196] <2> read_backup: remainder = 0 16:08:49.933 [3976.3196] <2> read_backup: id = QXH126 16:08:49.933 [3976.3196] <2> read_backup: file_num = 23 16:08:49.933 [3976.3196] <2> read_backup: block_size = 65536 16:08:49.933 [3976.3196] <2> read_backup: offset = 687546 16:08:49.933 [3976.3196] <2> read_backup: data_format = 0 16:08:49.933 [3976.3196] <2> read_backup: **************************************************** 16:08:49.933 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:08:49.933 [3976.3196] <2> read_data: Total Kbytes transferred 516096384 16:08:49.933 [3976.3196] <2> read_position: read position on drive index 0, is LBA 687547 16:08:49.933 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:08:49.933 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430834929 16:08:49.933 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430834929 16:08:59.387 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:09:04.987 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:09:08.107 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:09:08.107 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:09:08.107 [2352.4600] <16> socksend: failed to send this: 16:09:10.323 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:09:17.702 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:09:33.521 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:09:34.987 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:09:34.987 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:09:34.987 [2352.4600] <16> socksend: failed to send this: 16:09:36.313 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:09:39.355 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:09:42.803 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:09:44.519 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:09:44.519 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:09:44.519 [2352.4600] <16> socksend: failed to send this: 16:09:46.874 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:09:54.129 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:09:54.129 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:09:54.129 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:09:54.129 [3976.3196] <2> read_data: waited for empty buffer 58 times, delayed 528 times 16:09:54.129 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430834994 4 bptm 3976 waited for empty buffer 58 times, delayed 528 times 16:09:54.129 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 79, msg = LOG 1430834994 4 bptm 3976 waited for empty buffer 58 times, delayed 528 times 16:09:54.129 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:09:54.129 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:09:54.129 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54317 TO xxx.10.212.239.1556 fd = 432 16:09:54.129 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:09:54.207 [3976.3196] <2> db_end: Need to collect reply 16:09:54.222 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:09:54.222 [3976.3196] <2> read_data: Total Kbytes transferred 518096384 16:09:54.222 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:09:54.222 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:09:54.222 [3976.3196] <16> socksend: failed to send this: 16:09:54.222 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:09:54.222 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430834994 16:09:54.222 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430834994 16:09:54.222 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:09:54.222 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:09:54.222 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54318 TO xxx.10.212.239.1556 fd = 1120 16:09:54.222 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:09:54.269 [3976.3196] <2> db_end: Need to collect reply 16:09:54.300 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 260, 2000000 Kbytes at 31155.560 Kbytes/sec 16:09:54.300 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:09:54.300 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430834994 QXH126 24 16:09:54.300 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430834994 QXH126 24 16:09:54.300 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 24 16:09:54.300 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:09:54.300 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430834994 QXH126 16:09:54.300 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430834994 QXH126 16:09:54.300 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 24 16:09:54.300 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:09:54.300 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:09:54.300 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54319 TO xxx.10.212.239.1556 fd = 1168 16:09:54.300 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:09:54.347 [3976.3196] <2> db_end: Need to collect reply 16:09:54.363 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 261, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:09:54.363 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:09:54.363 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:09:54.363 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:09:54.363 [3976.3196] <2> read_backup: fragment_num = 261 16:09:54.363 [3976.3196] <2> read_backup: Kbytes = 2000000 16:09:54.363 [3976.3196] <2> read_backup: remainder = 0 16:09:54.363 [3976.3196] <2> read_backup: id = QXH126 16:09:54.363 [3976.3196] <2> read_backup: file_num = 24 16:09:54.363 [3976.3196] <2> read_backup: block_size = 65536 16:09:54.363 [3976.3196] <2> read_backup: offset = 718798 16:09:54.363 [3976.3196] <2> read_backup: data_format = 0 16:09:54.363 [3976.3196] <2> read_backup: **************************************************** 16:09:54.363 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:09:54.363 [3976.3196] <2> read_data: Total Kbytes transferred 518096384 16:09:54.363 [3976.3196] <2> read_position: read position on drive index 0, is LBA 718799 16:09:54.363 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:09:54.363 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430834994 16:09:54.363 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430834994 16:09:57.233 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:09:58.918 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:09:58.918 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:09:58.918 [2352.4600] <16> socksend: failed to send this: 16:10:00.462 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:10:03.302 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:10:05.813 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:10:07.249 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:10:07.249 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:10:07.249 [2352.4600] <16> socksend: failed to send this: 16:10:08.575 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:10:16.624 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:10:19.557 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:10:21.523 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:10:21.523 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:10:21.523 [2352.4600] <16> socksend: failed to send this: 16:10:22.989 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:10:25.922 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:10:28.559 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:10:28.559 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:10:28.559 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:10:28.559 [3976.3196] <2> read_data: waited for empty buffer 56 times, delayed 309 times 16:10:28.559 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835028 4 bptm 3976 waited for empty buffer 56 times, delayed 309 times 16:10:28.559 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 79, msg = LOG 1430835028 4 bptm 3976 waited for empty buffer 56 times, delayed 309 times 16:10:28.559 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:10:28.574 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:10:28.574 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54320 TO xxx.10.212.239.1556 fd = 1144 16:10:28.574 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:10:28.606 [3976.3196] <2> db_end: Need to collect reply 16:10:28.621 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:10:28.621 [3976.3196] <2> read_data: Total Kbytes transferred 520096384 16:10:28.621 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:10:28.621 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:10:28.621 [3976.3196] <16> socksend: failed to send this: 16:10:28.621 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:10:28.621 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835028 16:10:28.621 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835028 16:10:28.621 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:10:28.621 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:10:28.621 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54321 TO xxx.10.212.239.1556 fd = 1168 16:10:28.621 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:10:28.668 [3976.3196] <2> db_end: Need to collect reply 16:10:28.684 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 261, 2000000 Kbytes at 58488.083 Kbytes/sec 16:10:28.684 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:10:28.684 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835028 QXH126 25 16:10:28.684 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835028 QXH126 25 16:10:28.684 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 25 16:10:28.684 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:10:28.699 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835028 QXH126 16:10:28.699 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835028 QXH126 16:10:28.699 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 25 16:10:28.699 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:10:28.699 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:10:28.699 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54322 TO xxx.10.212.239.1556 fd = 1120 16:10:28.699 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:10:28.730 [3976.3196] <2> db_end: Need to collect reply 16:10:28.746 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 262, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:10:28.746 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:10:28.746 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:10:28.746 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:10:28.746 [3976.3196] <2> read_backup: fragment_num = 262 16:10:28.746 [3976.3196] <2> read_backup: Kbytes = 2000000 16:10:28.746 [3976.3196] <2> read_backup: remainder = 0 16:10:28.746 [3976.3196] <2> read_backup: id = QXH126 16:10:28.746 [3976.3196] <2> read_backup: file_num = 25 16:10:28.746 [3976.3196] <2> read_backup: block_size = 65536 16:10:28.746 [3976.3196] <2> read_backup: offset = 750050 16:10:28.746 [3976.3196] <2> read_backup: data_format = 0 16:10:28.746 [3976.3196] <2> read_backup: **************************************************** 16:10:28.746 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:10:28.746 [3976.3196] <2> read_data: Total Kbytes transferred 520096384 16:10:28.746 [3976.3196] <2> read_position: read position on drive index 0, is LBA 750051 16:10:28.746 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:10:28.746 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835028 16:10:28.746 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835028 16:10:29.776 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:10:29.776 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:10:29.776 [2352.4600] <16> socksend: failed to send this: 16:10:32.958 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:10:37.997 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:10:40.914 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:10:41.866 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:10:41.866 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:10:41.866 [2352.4600] <16> socksend: failed to send this: 16:10:42.989 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:10:44.955 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:10:47.342 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:10:48.465 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:10:48.465 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:10:48.465 [2352.4600] <16> socksend: failed to send this: 16:10:49.666 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:10:51.601 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:10:58.433 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:10:59.338 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:10:59.338 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:10:59.338 [2352.4600] <16> socksend: failed to send this: 16:11:00.384 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:11:00.384 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:11:00.384 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:11:00.384 [3976.3196] <2> read_data: waited for empty buffer 68 times, delayed 507 times 16:11:00.384 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835060 4 bptm 3976 waited for empty buffer 68 times, delayed 507 times 16:11:00.384 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 79, msg = LOG 1430835060 4 bptm 3976 waited for empty buffer 68 times, delayed 507 times 16:11:00.384 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:11:00.415 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:11:00.415 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54323 TO xxx.10.212.239.1556 fd = 1144 16:11:00.415 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:11:00.446 [3976.3196] <2> db_end: Need to collect reply 16:11:00.462 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:11:00.462 [3976.3196] <2> read_data: Total Kbytes transferred 522096384 16:11:00.462 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:11:00.462 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:11:00.462 [3976.3196] <16> socksend: failed to send this: 16:11:00.462 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:11:00.462 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835060 16:11:00.462 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835060 16:11:00.462 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:11:00.477 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:11:00.477 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54324 TO xxx.10.212.239.1556 fd = 1120 16:11:00.477 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:11:00.524 [3976.3196] <2> db_end: Need to collect reply 16:11:00.540 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 262, 2000000 Kbytes at 63217.119 Kbytes/sec 16:11:00.540 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:11:00.540 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835060 QXH126 26 16:11:00.540 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835060 QXH126 26 16:11:00.540 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 26 16:11:00.540 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:11:00.540 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835060 QXH126 16:11:00.540 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835060 QXH126 16:11:00.540 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 26 16:11:00.540 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:11:00.540 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:11:00.540 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54325 TO xxx.10.212.239.1556 fd = 1120 16:11:00.540 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:11:00.586 [3976.3196] <2> db_end: Need to collect reply 16:11:00.586 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 263, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:11:00.586 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:11:00.586 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:11:00.586 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:11:00.586 [3976.3196] <2> read_backup: fragment_num = 263 16:11:00.586 [3976.3196] <2> read_backup: Kbytes = 2000000 16:11:00.586 [3976.3196] <2> read_backup: remainder = 0 16:11:00.586 [3976.3196] <2> read_backup: id = QXH126 16:11:00.586 [3976.3196] <2> read_backup: file_num = 26 16:11:00.586 [3976.3196] <2> read_backup: block_size = 65536 16:11:00.586 [3976.3196] <2> read_backup: offset = 781302 16:11:00.586 [3976.3196] <2> read_backup: data_format = 0 16:11:00.586 [3976.3196] <2> read_backup: **************************************************** 16:11:00.586 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:11:00.586 [3976.3196] <2> read_data: Total Kbytes transferred 522096384 16:11:00.602 [3976.3196] <2> read_position: read position on drive index 0, is LBA 781303 16:11:00.602 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:11:00.602 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835060 16:11:00.602 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835060 16:11:03.082 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:11:05.688 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:11:06.873 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:11:06.873 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:11:06.873 [2352.4600] <16> socksend: failed to send this: 16:11:08.075 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:11:10.165 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:11:18.636 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:11:19.759 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:11:19.759 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:11:19.759 [2352.4600] <16> socksend: failed to send this: 16:11:19.759 [2352.4600] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:11:19.775 [2352.4600] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:11:19.775 [2352.4600] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54326 TO xxx.10.212.239.1556 fd = 1160 16:11:19.775 [2352.4600] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:11:19.822 [2352.4600] <2> db_end: Need to collect reply 16:11:19.837 [2352.4600] <4> report_throughput: VBRT 1 2352 1 1 HP.ULTRIUM4-SCSI.002 VAB456 0 1 0 39600000 39600000 (bptm.c.25633) 16:11:19.837 [2352.4600] <2> write_data: Total Kbytes transferred 523200000 16:11:20.992 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:11:23.971 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:11:32.084 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:11:33.893 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:11:33.893 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:11:33.893 [2352.4600] <16> socksend: failed to send this: 16:11:35.282 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:11:38.714 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:11:38.714 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:11:38.714 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:11:38.714 [3976.3196] <2> read_data: waited for empty buffer 68 times, delayed 540 times 16:11:38.714 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835098 4 bptm 3976 waited for empty buffer 68 times, delayed 540 times 16:11:38.714 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 79, msg = LOG 1430835098 4 bptm 3976 waited for empty buffer 68 times, delayed 540 times 16:11:38.714 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:11:38.714 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:11:38.714 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54327 TO xxx.10.212.239.1556 fd = 1144 16:11:38.714 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:11:38.761 [3976.3196] <2> db_end: Need to collect reply 16:11:38.776 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:11:38.776 [3976.3196] <2> read_data: Total Kbytes transferred 524096384 16:11:38.776 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:11:38.776 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:11:38.776 [3976.3196] <16> socksend: failed to send this: 16:11:38.776 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:11:38.776 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835098 16:11:38.776 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835098 16:11:38.776 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:11:38.776 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:11:38.776 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54328 TO xxx.10.212.239.1556 fd = 1120 16:11:38.776 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:11:38.823 [3976.3196] <2> db_end: Need to collect reply 16:11:38.839 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 263, 2000000 Kbytes at 52478.287 Kbytes/sec 16:11:38.839 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:11:38.839 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835098 QXH126 27 16:11:38.839 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835098 QXH126 27 16:11:38.839 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 27 16:11:38.839 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:11:38.839 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835098 QXH126 16:11:38.839 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835098 QXH126 16:11:38.839 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 27 16:11:38.839 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:11:38.854 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:11:38.854 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54329 TO xxx.10.212.239.1556 fd = 1168 16:11:38.854 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:11:38.885 [3976.3196] <2> db_end: Need to collect reply 16:11:38.917 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 264, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:11:38.917 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:11:38.917 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:11:38.917 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:11:38.917 [3976.3196] <2> read_backup: fragment_num = 264 16:11:38.917 [3976.3196] <2> read_backup: Kbytes = 2000000 16:11:38.917 [3976.3196] <2> read_backup: remainder = 0 16:11:38.917 [3976.3196] <2> read_backup: id = QXH126 16:11:38.917 [3976.3196] <2> read_backup: file_num = 27 16:11:38.917 [3976.3196] <2> read_backup: block_size = 65536 16:11:38.917 [3976.3196] <2> read_backup: offset = 812554 16:11:38.917 [3976.3196] <2> read_backup: data_format = 0 16:11:38.917 [3976.3196] <2> read_backup: **************************************************** 16:11:38.917 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:11:38.917 [3976.3196] <2> read_data: Total Kbytes transferred 524096384 16:11:38.917 [3976.3196] <2> read_position: read position on drive index 0, is LBA 812555 16:11:38.917 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:11:38.917 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835098 16:11:38.917 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835098 16:11:45.422 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:11:46.857 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:11:46.857 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:11:46.857 [2352.4600] <16> socksend: failed to send this: 16:11:48.651 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:11:51.865 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:11:57.341 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:11:58.854 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:11:58.854 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:11:58.854 [2352.4600] <16> socksend: failed to send this: 16:12:00.102 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:12:02.723 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:12:05.125 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:12:06.857 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:12:06.857 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:12:06.857 [2352.4600] <16> socksend: failed to send this: 16:12:08.152 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:12:12.161 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:12:19.415 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:12:19.415 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:12:19.415 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:12:19.415 [3976.3196] <2> read_data: waited for empty buffer 69 times, delayed 503 times 16:12:19.415 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835xxx 4 bptm 3976 waited for empty buffer 69 times, delayed 503 times 16:12:19.415 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 79, msg = LOG 1430835xxx 4 bptm 3976 waited for empty buffer 69 times, delayed 503 times 16:12:19.415 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:12:19.431 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:12:19.431 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54330 TO xxx.10.212.239.1556 fd = 1164 16:12:19.431 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:12:19.478 [3976.3196] <2> db_end: Need to collect reply 16:12:19.509 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:12:19.509 [3976.3196] <2> read_data: Total Kbytes transferred 526096384 16:12:19.509 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:12:19.509 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:12:19.509 [3976.3196] <16> socksend: failed to send this: 16:12:19.509 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:12:19.509 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835xxx 16:12:19.509 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835xxx 16:12:19.509 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:12:19.509 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:12:19.509 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54331 TO xxx.10.212.239.1556 fd = 1168 16:12:19.509 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:12:19.540 [3976.3196] <2> db_end: Need to collect reply 16:12:19.571 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 264, 2000000 Kbytes at 49385.155 Kbytes/sec 16:12:19.571 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:12:19.571 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835xxx QXH126 28 16:12:19.571 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835xxx QXH126 28 16:12:19.571 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 28 16:12:19.571 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:12:19.571 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835xxx QXH126 16:12:19.571 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835xxx QXH126 16:12:19.571 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 28 16:12:19.571 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:12:19.587 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:12:19.587 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54332 TO xxx.10.212.239.1556 fd = 1120 16:12:19.587 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:12:19.634 [3976.3196] <2> db_end: Need to collect reply 16:12:19.649 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 265, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:12:19.649 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:12:19.649 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:12:19.649 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:12:19.649 [3976.3196] <2> read_backup: fragment_num = 265 16:12:19.649 [3976.3196] <2> read_backup: Kbytes = 2000000 16:12:19.649 [3976.3196] <2> read_backup: remainder = 0 16:12:19.649 [3976.3196] <2> read_backup: id = QXH126 16:12:19.649 [3976.3196] <2> read_backup: file_num = 28 16:12:19.649 [3976.3196] <2> read_backup: block_size = 65536 16:12:19.649 [3976.3196] <2> read_backup: offset = 843806 16:12:19.649 [3976.3196] <2> read_backup: data_format = 0 16:12:19.649 [3976.3196] <2> read_backup: **************************************************** 16:12:19.649 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:12:19.649 [3976.3196] <2> read_data: Total Kbytes transferred 526096384 16:12:19.649 [3976.3196] <2> read_position: read position on drive index 0, is LBA 843807 16:12:19.649 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:12:19.649 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835xxx 16:12:19.649 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835xxx 16:12:20.804 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:12:20.804 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:12:20.804 [2352.4600] <16> socksend: failed to send this: 16:12:22.020 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:12:24.282 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:12:26.607 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:12:27.403 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:12:27.403 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:12:27.403 [2352.4600] <16> socksend: failed to send this: 16:12:28.027 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:12:30.569 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:12:32.597 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:12:35.078 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:12:35.078 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:12:35.078 [2352.4600] <16> socksend: failed to send this: 16:12:39.930 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:12:41.693 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:12:44.376 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:12:45.873 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:12:45.873 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:12:45.873 [2352.4600] <16> socksend: failed to send this: 16:12:46.544 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:12:46.544 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:12:46.544 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:12:46.544 [3976.3196] <2> read_data: waited for empty buffer 40 times, delayed 179 times 16:12:46.544 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835166 4 bptm 3976 waited for empty buffer 40 times, delayed 179 times 16:12:46.544 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 79, msg = LOG 1430835166 4 bptm 3976 waited for empty buffer 40 times, delayed 179 times 16:12:46.544 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:12:46.544 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:12:46.544 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54333 TO xxx.10.212.239.1556 fd = 432 16:12:46.544 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:12:46.575 [3976.3196] <2> db_end: Need to collect reply 16:12:46.591 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:12:46.591 [3976.3196] <2> read_data: Total Kbytes transferred 528096384 16:12:46.591 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:12:46.591 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:12:46.591 [3976.3196] <16> socksend: failed to send this: 16:12:46.591 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:12:46.591 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835166 16:12:46.591 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835166 16:12:46.591 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:12:46.591 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:12:46.591 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54334 TO xxx.10.212.239.1556 fd = 1120 16:12:46.591 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:12:46.638 [3976.3196] <2> db_end: Need to collect reply 16:12:46.669 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 265, 2000000 Kbytes at 74366.030 Kbytes/sec 16:12:46.669 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:12:46.669 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835166 QXH126 29 16:12:46.669 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835166 QXH126 29 16:12:46.669 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 29 16:12:46.669 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:12:46.685 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835166 QXH126 16:12:46.685 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835166 QXH126 16:12:46.685 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 29 16:12:46.685 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:12:46.685 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:12:46.685 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54335 TO xxx.10.212.239.1556 fd = 1168 16:12:46.685 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:12:46.716 [3976.3196] <2> db_end: Need to collect reply 16:12:46.731 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 266, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:12:46.731 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:12:46.731 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:12:46.731 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:12:46.731 [3976.3196] <2> read_backup: fragment_num = 266 16:12:46.731 [3976.3196] <2> read_backup: Kbytes = 2000000 16:12:46.731 [3976.3196] <2> read_backup: remainder = 0 16:12:46.731 [3976.3196] <2> read_backup: id = QXH126 16:12:46.731 [3976.3196] <2> read_backup: file_num = 29 16:12:46.731 [3976.3196] <2> read_backup: block_size = 65536 16:12:46.731 [3976.3196] <2> read_backup: offset = 875058 16:12:46.731 [3976.3196] <2> read_backup: data_format = 0 16:12:46.731 [3976.3196] <2> read_backup: **************************************************** 16:12:46.731 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:12:46.731 [3976.3196] <2> read_data: Total Kbytes transferred 528096384 16:12:46.731 [3976.3196] <2> read_position: read position on drive index 0, is LBA 875059 16:12:46.731 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:12:46.731 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835166 16:12:46.731 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835166 16:12:48.588 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:12:50.023 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:12:50.928 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:12:50.928 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:12:50.928 [2352.4600] <16> socksend: failed to send this: 16:12:51.724 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:13:02.067 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:13:05.327 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:13:06.060 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:13:06.060 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:13:06.060 [2352.4600] <16> socksend: failed to send this: 16:13:06.747 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:13:08.603 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:13:16.715 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:13:18.073 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:13:18.073 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:13:18.073 [2352.4600] <16> socksend: failed to send this: 16:13:18.899 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:13:20.553 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:13:20.553 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:13:20.553 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:13:20.553 [3976.3196] <2> read_data: waited for empty buffer 51 times, delayed 287 times 16:13:20.553 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835200 4 bptm 3976 waited for empty buffer 51 times, delayed 287 times 16:13:20.553 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 79, msg = LOG 1430835200 4 bptm 3976 waited for empty buffer 51 times, delayed 287 times 16:13:20.553 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:13:20.569 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:13:20.569 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54336 TO xxx.10.212.239.1556 fd = 1140 16:13:20.569 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:13:20.616 [3976.3196] <2> db_end: Need to collect reply 16:13:20.647 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:13:20.647 [3976.3196] <2> read_data: Total Kbytes transferred 530096384 16:13:20.647 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:13:20.647 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:13:20.647 [3976.3196] <16> socksend: failed to send this: 16:13:20.647 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:13:20.647 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835200 16:13:20.647 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835200 16:13:20.647 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:13:20.662 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:13:20.662 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54337 TO xxx.10.212.239.1556 fd = 1168 16:13:20.662 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:13:20.694 [3976.3196] <2> db_end: Need to collect reply 16:13:20.709 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 266, 2000000 Kbytes at 59134.857 Kbytes/sec 16:13:20.709 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:13:20.709 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835200 QXH126 30 16:13:20.709 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835200 QXH126 30 16:13:20.709 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 30 16:13:20.709 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:13:20.803 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835200 QXH126 16:13:20.803 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835200 QXH126 16:13:20.803 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 30 16:13:20.803 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:13:20.803 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:13:20.803 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54338 TO xxx.10.212.239.1556 fd = 1120 16:13:20.803 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:13:20.850 [3976.3196] <2> db_end: Need to collect reply 16:13:20.865 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 267, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:13:20.865 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:13:20.865 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:13:20.865 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:13:20.865 [3976.3196] <2> read_backup: fragment_num = 267 16:13:20.865 [3976.3196] <2> read_backup: Kbytes = 2000000 16:13:20.865 [3976.3196] <2> read_backup: remainder = 0 16:13:20.865 [3976.3196] <2> read_backup: id = QXH126 16:13:20.865 [3976.3196] <2> read_backup: file_num = 30 16:13:20.865 [3976.3196] <2> read_backup: block_size = 65536 16:13:20.865 [3976.3196] <2> read_backup: offset = 906310 16:13:20.865 [3976.3196] <2> read_backup: data_format = 0 16:13:20.865 [3976.3196] <2> read_backup: **************************************************** 16:13:20.865 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:13:20.865 [3976.3196] <2> read_data: Total Kbytes transferred 530096384 16:13:20.865 [3976.3196] <2> read_position: read position on drive index 0, is LBA 906311 16:13:20.865 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:13:20.865 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835200 16:13:20.865 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835200 16:13:23.174 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:13:25.186 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:13:25.186 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:13:25.186 [2352.4600] <16> socksend: failed to send this: 16:13:25.951 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:13:28.026 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:13:32.628 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:13:38.026 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:13:38.026 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:13:38.026 [2352.4600] <16> socksend: failed to send this: 16:13:39.523 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:13:42.487 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:13:45.108 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:13:46.887 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:13:46.887 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:13:46.887 [2352.4600] <16> socksend: failed to send this: 16:13:54.328 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:14:01.707 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:14:05.201 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:14:05.201 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:14:05.201 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:14:05.201 [3976.3196] <2> read_data: waited for empty buffer 54 times, delayed 359 times 16:14:05.201 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835245 4 bptm 3976 waited for empty buffer 54 times, delayed 359 times 16:14:05.201 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 79, msg = LOG 1430835245 4 bptm 3976 waited for empty buffer 54 times, delayed 359 times 16:14:05.201 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:14:05.217 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:14:05.217 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54340 TO xxx.10.212.239.1556 fd = 1164 16:14:05.217 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:14:05.264 [3976.3196] <2> db_end: Need to collect reply 16:14:05.264 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:14:05.264 [3976.3196] <2> read_data: Total Kbytes transferred 532096384 16:14:05.264 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:14:05.264 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:14:05.264 [3976.3196] <16> socksend: failed to send this: 16:14:05.264 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:14:05.264 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835245 16:14:05.264 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835245 16:14:05.264 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:14:05.279 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:14:05.279 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54341 TO xxx.10.212.239.1556 fd = 1120 16:14:05.279 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:14:05.326 [3976.3196] <2> db_end: Need to collect reply 16:14:05.357 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 267, 2000000 Kbytes at 45110.069 Kbytes/sec 16:14:05.357 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:14:05.357 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835245 QXH126 31 16:14:05.357 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835245 QXH126 31 16:14:05.357 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 31 16:14:05.357 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:14:05.373 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835245 QXH126 16:14:05.373 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835245 QXH126 16:14:05.373 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 31 16:14:05.373 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:14:05.389 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:14:05.389 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54342 TO xxx.10.212.239.1556 fd = 1120 16:14:05.389 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:14:05.420 [3976.3196] <2> db_end: Need to collect reply 16:14:05.435 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 268, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:14:05.435 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:14:05.435 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:14:05.435 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:14:05.435 [3976.3196] <2> read_backup: fragment_num = 268 16:14:05.435 [3976.3196] <2> read_backup: Kbytes = 2000000 16:14:05.435 [3976.3196] <2> read_backup: remainder = 0 16:14:05.435 [3976.3196] <2> read_backup: id = QXH126 16:14:05.435 [3976.3196] <2> read_backup: file_num = 31 16:14:05.435 [3976.3196] <2> read_backup: block_size = 65536 16:14:05.435 [3976.3196] <2> read_backup: offset = 937562 16:14:05.435 [3976.3196] <2> read_backup: data_format = 0 16:14:05.435 [3976.3196] <2> read_backup: **************************************************** 16:14:05.435 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:14:05.435 [3976.3196] <2> read_data: Total Kbytes transferred 532096384 16:14:05.451 [3976.3196] <2> read_position: read position on drive index 0, is LBA 937563 16:14:05.451 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:14:05.451 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835245 16:14:05.451 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835245 16:14:07.666 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:14:07.666 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:14:07.666 [2352.4600] <16> socksend: failed to send this: 16:14:09.585 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:14:12.440 [224.4408] <2> initialize: fd values STDOUTSOCK=244 STDERRSOCK=508 16:14:12.456 [224.4408] <2> bptm: instance - 549118402 16:14:12.456 [224.4408] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1430298873 -jm 16:14:12.456 [224.4408] <2> bptm: Event Global\NetBackup Terminate Event, pid: 224 created. 16:14:12.456 [224.4408] <2> bptm: PORT_STATUS = 0x00000000 16:14:12.456 [224.4408] <2> drivename_open: Called with Create 0, file HP.ULTRIUM4-SCSI.000 16:14:12.456 [224.4408] <2> drivename_checklock: Called 16:14:12.456 [224.4408] <2> drivename_checklock: File is locked 16:14:12.456 [224.4408] <2> report_drives: DRIVE = HP.ULTRIUM4-SCSI.000 LOCK = TRUE CURTIME = 1430835252 16:14:12.456 [224.4408] <2> drivename_close: Called for file HP.ULTRIUM4-SCSI.000 16:14:12.456 [224.4408] <2> report_drives: MODE = 0 16:14:12.456 [224.4408] <2> report_drives: TIME = 1430833465 16:14:12.456 [224.4408] <2> report_drives: MASTER = masterserver 16:14:12.456 [224.4408] <2> report_drives: SR_KEY = 0 1 16:14:12.456 [224.4408] <2> report_drives: PATH = {5,0,0,0} 16:14:12.456 [224.4408] <2> report_drives: MEDIA = QXH126 16:14:12.456 [224.4408] <2> report_drives: REQID = 88868 16:14:12.456 [224.4408] <2> report_drives: ALOCID = 20988 16:14:12.456 [224.4408] <2> report_drives: RBID = {11683187-5EFB-4C23-9B08-2F757808F9E9} 16:14:12.456 [224.4408] <2> report_drives: PID = 3976 16:14:12.456 [224.4408] <2> report_drives: FILE = C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.000 16:14:12.456 [224.4408] <2> drivename_open: Called with Create 0, file HP.ULTRIUM4-SCSI.002 16:14:12.456 [224.4408] <2> drivename_checklock: Called 16:14:12.456 [224.4408] <2> drivename_checklock: File is locked 16:14:12.456 [224.4408] <2> report_drives: DRIVE = HP.ULTRIUM4-SCSI.002 LOCK = TRUE CURTIME = 1430835252 16:14:12.456 [224.4408] <2> drivename_close: Called for file HP.ULTRIUM4-SCSI.002 16:14:12.456 [224.4408] <2> report_drives: MODE = 0 16:14:12.456 [224.4408] <2> report_drives: TIME = 1430816888 16:14:12.456 [224.4408] <2> report_drives: MASTER = masterserver 16:14:12.456 [224.4408] <2> report_drives: SR_KEY = 0 1 16:14:12.456 [224.4408] <2> report_drives: PATH = {5,0,2,0} 16:14:12.456 [224.4408] <2> report_drives: MEDIA = VAB456 16:14:12.456 [224.4408] <2> report_drives: REQID = 88868 16:14:12.456 [224.4408] <2> report_drives: ALOCID = 20984 16:14:12.456 [224.4408] <2> report_drives: RBID = {2D2E0007-3CCC-4DF3-A193-4BACFB9EB309} 16:14:12.456 [224.4408] <2> report_drives: PID = 2352 16:14:12.456 [224.4408] <2> report_drives: FILE = C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.002 16:14:12.456 [224.4408] <2> main: Sending [EXIT STATUS 0] to NBJM 16:14:12.456 [224.4408] <2> bptm: EXITING with status 0 <---------- 16:14:12.456 [224.4408] <2> bptm: Global\NetBackup Terminate Event, pid: 224 closed. 16:14:12.908 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:14:21.410 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:14:23.080 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:14:23.080 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:14:23.080 [2352.4600] <16> socksend: failed to send this: 16:14:24.406 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:14:28.040 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:14:30.365 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:14:31.488 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:14:31.488 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:14:31.488 [2352.4600] <16> socksend: failed to send this: 16:14:33.001 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:14:35.934 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:14:44.343 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:14:45.154 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:14:45.154 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:14:45.154 [2352.4600] <16> socksend: failed to send this: 16:14:45.950 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:14:45.950 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:14:45.950 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:14:45.950 [3976.3196] <2> read_data: waited for empty buffer 52 times, delayed 224 times 16:14:45.950 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835285 4 bptm 3976 waited for empty buffer 52 times, delayed 224 times 16:14:45.950 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 79, msg = LOG 1430835285 4 bptm 3976 waited for empty buffer 52 times, delayed 224 times 16:14:45.950 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:14:45.965 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:14:45.965 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54348 TO xxx.10.212.239.1556 fd = 1164 16:14:45.965 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:14:46.012 [3976.3196] <2> db_end: Need to collect reply 16:14:46.028 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:14:46.028 [3976.3196] <2> read_data: Total Kbytes transferred 534096384 16:14:46.028 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:14:46.028 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:14:46.028 [3976.3196] <16> socksend: failed to send this: 16:14:46.028 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:14:46.028 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835286 16:14:46.028 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835286 16:14:46.028 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:14:46.043 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:14:46.043 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54349 TO xxx.10.212.239.1556 fd = 1168 16:14:46.043 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:14:46.075 [3976.3196] <2> db_end: Need to collect reply 16:14:46.090 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 268, 2000000 Kbytes at 49386.374 Kbytes/sec 16:14:46.090 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:14:46.090 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835286 QXH126 32 16:14:46.090 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835286 QXH126 32 16:14:46.090 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 32 16:14:46.090 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:14:46.090 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835286 QXH126 16:14:46.090 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835286 QXH126 16:14:46.090 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 32 16:14:46.090 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:14:46.106 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:14:46.106 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54350 TO xxx.10.212.239.1556 fd = 1168 16:14:46.106 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:14:46.153 [3976.3196] <2> db_end: Need to collect reply 16:14:46.168 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 269, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:14:46.168 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:14:46.168 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:14:46.168 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:14:46.168 [3976.3196] <2> read_backup: fragment_num = 269 16:14:46.168 [3976.3196] <2> read_backup: Kbytes = 2000000 16:14:46.168 [3976.3196] <2> read_backup: remainder = 0 16:14:46.168 [3976.3196] <2> read_backup: id = QXH126 16:14:46.168 [3976.3196] <2> read_backup: file_num = 32 16:14:46.168 [3976.3196] <2> read_backup: block_size = 65536 16:14:46.168 [3976.3196] <2> read_backup: offset = 968814 16:14:46.168 [3976.3196] <2> read_backup: data_format = 0 16:14:46.168 [3976.3196] <2> read_backup: **************************************************** 16:14:46.168 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:14:46.168 [3976.3196] <2> read_data: Total Kbytes transferred 534096384 16:14:46.184 [3976.3196] <2> read_position: read position on drive index 0, is LBA 968815 16:14:46.184 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:14:46.184 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835286 16:14:46.184 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835286 16:14:47.791 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:14:50.224 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:14:51.691 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:14:51.691 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:14:51.691 [2352.4600] <16> socksend: failed to send this: 16:14:53.890 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:14:58.040 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:15:00.349 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:15:01.691 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:15:01.691 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:15:01.691 [2352.4600] <16> socksend: failed to send this: 16:15:02.361 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:15:09.647 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:15:11.846 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:15:12.720 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:15:12.720 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:15:12.720 [2352.4600] <16> socksend: failed to send this: 16:15:13.625 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:15:15.949 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:15:15.949 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:15:15.949 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:15:15.949 [3976.3196] <2> read_data: waited for empty buffer 82 times, delayed 346 times 16:15:15.949 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835315 4 bptm 3976 waited for empty buffer 82 times, delayed 346 times 16:15:15.949 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 79, msg = LOG 1430835315 4 bptm 3976 waited for empty buffer 82 times, delayed 346 times 16:15:15.949 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:15:15.949 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:15:15.949 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54351 TO xxx.10.212.239.1556 fd = 1164 16:15:15.949 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:15:16.012 [3976.3196] <2> db_end: Need to collect reply 16:15:16.027 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:15:16.027 [3976.3196] <2> read_data: Total Kbytes transferred 536096384 16:15:16.027 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:15:16.027 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:15:16.027 [3976.3196] <16> socksend: failed to send this: 16:15:16.027 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:15:16.027 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835316 16:15:16.027 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835316 16:15:16.027 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:15:16.043 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:15:16.043 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54352 TO xxx.10.212.239.1556 fd = 1120 16:15:16.043 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:15:16.074 [3976.3196] <2> db_end: Need to collect reply 16:15:16.121 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 269, 2000000 Kbytes at 67193.012 Kbytes/sec 16:15:16.121 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:15:16.121 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835316 QXH126 33 16:15:16.121 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835316 QXH126 33 16:15:16.121 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 33 16:15:16.121 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:15:16.136 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835316 QXH126 16:15:16.136 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835316 QXH126 16:15:16.136 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 33 16:15:16.136 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:15:16.152 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:15:16.152 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54353 TO xxx.10.212.239.1556 fd = 1120 16:15:16.152 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:15:16.199 [3976.3196] <2> db_end: Need to collect reply 16:15:16.214 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 270, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:15:16.214 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:15:16.214 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:15:16.214 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:15:16.214 [3976.3196] <2> read_backup: fragment_num = 270 16:15:16.214 [3976.3196] <2> read_backup: Kbytes = 2000000 16:15:16.214 [3976.3196] <2> read_backup: remainder = 0 16:15:16.214 [3976.3196] <2> read_backup: id = QXH126 16:15:16.214 [3976.3196] <2> read_backup: file_num = 33 16:15:16.214 [3976.3196] <2> read_backup: block_size = 65536 16:15:16.214 [3976.3196] <2> read_backup: offset = 1000066 16:15:16.214 [3976.3196] <2> read_backup: data_format = 0 16:15:16.214 [3976.3196] <2> read_backup: **************************************************** 16:15:16.214 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:15:16.214 [3976.3196] <2> read_data: Total Kbytes transferred 536096384 16:15:16.230 [3976.3196] <2> read_position: read position on drive index 0, is LBA 1000067 16:15:16.230 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:15:16.230 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835316 16:15:16.230 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835316 16:15:19.569 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:15:21.144 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:15:21.144 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:15:21.144 [2352.4600] <16> socksend: failed to send this: 16:15:22.314 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:15:26.776 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:15:33.952 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:15:35.091 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:15:35.091 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:15:35.091 [2352.4600] <16> socksend: failed to send this: 16:15:36.308 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:15:38.336 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:15:40.894 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:15:41.815 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:15:41.815 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:15:41.815 [2352.4600] <16> socksend: failed to send this: 16:15:43.016 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:15:44.826 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:15:53.624 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:15:53.624 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:15:53.624 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:15:53.624 [3976.3196] <2> read_data: waited for empty buffer 51 times, delayed 372 times 16:15:53.624 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835353 4 bptm 3976 waited for empty buffer 51 times, delayed 372 times 16:15:53.624 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 79, msg = LOG 1430835353 4 bptm 3976 waited for empty buffer 51 times, delayed 372 times 16:15:53.624 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:15:53.640 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:15:53.640 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54354 TO xxx.10.212.239.1556 fd = 1144 16:15:53.640 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:15:53.671 [3976.3196] <2> db_end: Need to collect reply 16:15:53.687 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:15:53.687 [3976.3196] <2> read_data: Total Kbytes transferred 538096384 16:15:53.687 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:15:53.687 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:15:53.687 [3976.3196] <16> socksend: failed to send this: 16:15:53.687 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:15:53.687 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835353 16:15:53.687 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835353 16:15:53.687 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:15:53.702 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:15:53.702 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54355 TO xxx.10.212.239.1556 fd = 1168 16:15:53.702 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:15:53.749 [3976.3196] <2> db_end: Need to collect reply 16:15:53.765 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 270, 2000000 Kbytes at 53484.516 Kbytes/sec 16:15:53.765 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:15:53.765 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835353 QXH126 34 16:15:53.765 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835353 QXH126 34 16:15:53.765 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 34 16:15:53.765 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:15:53.780 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835353 QXH126 16:15:53.780 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835353 QXH126 16:15:53.780 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 34 16:15:53.780 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:15:53.796 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:15:53.796 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54356 TO xxx.10.212.239.1556 fd = 1168 16:15:53.796 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:15:53.827 [3976.3196] <2> db_end: Need to collect reply 16:15:53.843 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 271, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:15:53.843 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:15:53.843 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:15:53.843 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:15:53.843 [3976.3196] <2> read_backup: fragment_num = 271 16:15:53.843 [3976.3196] <2> read_backup: Kbytes = 2000000 16:15:53.843 [3976.3196] <2> read_backup: remainder = 0 16:15:53.843 [3976.3196] <2> read_backup: id = QXH126 16:15:53.843 [3976.3196] <2> read_backup: file_num = 34 16:15:53.843 [3976.3196] <2> read_backup: block_size = 65536 16:15:53.843 [3976.3196] <2> read_backup: offset = 1031318 16:15:53.843 [3976.3196] <2> read_backup: data_format = 0 16:15:53.843 [3976.3196] <2> read_backup: **************************************************** 16:15:53.843 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:15:53.843 [3976.3196] <2> read_data: Total Kbytes transferred 538096384 16:15:53.843 [3976.3196] <2> read_position: read position on drive index 0, is LBA 1031319 16:15:53.843 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:15:53.843 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835353 16:15:53.843 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835353 16:15:56.198 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:15:56.198 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:15:56.198 [2352.4600] <16> socksend: failed to send this: 16:15:58.741 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:16:03.218 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:16:13.655 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:16:16.120 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:16:16.120 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:16:16.120 [2352.4600] <16> socksend: failed to send this: 16:16:18.335 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:16:22.937 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:16:31.767 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:16:34.029 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:16:34.029 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:16:34.029 [2352.4600] <16> socksend: failed to send this: 16:16:35.933 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:16:40.784 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:16:47.149 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:16:58.194 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:16:58.194 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:16:58.194 [2352.4600] <16> socksend: failed to send this: 16:17:00.675 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:17:00.675 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:17:00.675 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:17:00.675 [3976.3196] <2> read_data: waited for empty buffer 293 times, delayed 797 times 16:17:00.675 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835420 4 bptm 3976 waited for empty buffer 293 times, delayed 797 times 16:17:00.675 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 80, msg = LOG 1430835420 4 bptm 3976 waited for empty buffer 293 times, delayed 797 times 16:17:00.675 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:17:00.690 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:17:00.690 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54361 TO xxx.10.212.239.1556 fd = 1144 16:17:00.690 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:17:00.722 [3976.3196] <2> db_end: Need to collect reply 16:17:00.737 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:17:00.737 [3976.3196] <2> read_data: Total Kbytes transferred 540096384 16:17:00.737 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:17:00.737 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:17:00.737 [3976.3196] <16> socksend: failed to send this: 16:17:00.737 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:17:00.737 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835420 16:17:00.737 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835420 16:17:00.737 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:17:00.753 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:17:00.753 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54362 TO xxx.10.212.239.1556 fd = 1120 16:17:00.753 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:17:00.800 [3976.3196] <2> db_end: Need to collect reply 16:17:00.815 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 271, 2000000 Kbytes at 29926.232 Kbytes/sec 16:17:00.815 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:17:00.815 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835420 QXH126 35 16:17:00.815 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835420 QXH126 35 16:17:00.815 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 35 16:17:00.815 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:17:00.831 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835420 QXH126 16:17:00.831 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835420 QXH126 16:17:00.831 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 35 16:17:00.831 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:17:00.846 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:17:00.846 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54363 TO xxx.10.212.239.1556 fd = 1120 16:17:00.846 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:17:00.878 [3976.3196] <2> db_end: Need to collect reply 16:17:00.893 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 272, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:17:00.893 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:17:00.893 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:17:00.893 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:17:00.893 [3976.3196] <2> read_backup: fragment_num = 272 16:17:00.893 [3976.3196] <2> read_backup: Kbytes = 2000000 16:17:00.893 [3976.3196] <2> read_backup: remainder = 0 16:17:00.893 [3976.3196] <2> read_backup: id = QXH126 16:17:00.893 [3976.3196] <2> read_backup: file_num = 35 16:17:00.893 [3976.3196] <2> read_backup: block_size = 65536 16:17:00.893 [3976.3196] <2> read_backup: offset = 1062570 16:17:00.893 [3976.3196] <2> read_backup: data_format = 0 16:17:00.893 [3976.3196] <2> read_backup: **************************************************** 16:17:00.893 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:17:00.893 [3976.3196] <2> read_data: Total Kbytes transferred 540096384 16:17:00.893 [3976.3196] <2> read_position: read position on drive index 0, is LBA 1062571 16:17:00.893 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:17:00.893 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835420 16:17:00.893 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835420 16:17:09.411 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:17:19.270 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:17:21.845 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:17:21.845 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:17:21.845 [2352.4600] <16> socksend: failed to send this: 16:17:23.748 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:17:26.759 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:17:35.526 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:17:37.414 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:17:37.414 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:17:37.414 [2352.4600] <16> socksend: failed to send this: 16:17:38.802 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:17:43.030 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:17:47.398 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:17:49.629 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:17:49.629 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:17:49.629 [2352.4600] <16> socksend: failed to send this: 16:17:57.382 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:18:01.969 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:18:01.969 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:18:01.969 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:18:01.969 [3976.3196] <2> read_data: waited for empty buffer 538 times, delayed 1057 times 16:18:01.969 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835481 4 bptm 3976 waited for empty buffer 538 times, delayed 1057 times 16:18:01.969 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 81, msg = LOG 1430835481 4 bptm 3976 waited for empty buffer 538 times, delayed 1057 times 16:18:01.969 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:18:02.000 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:18:02.000 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54364 TO xxx.10.212.239.1556 fd = 1144 16:18:02.000 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:18:02.031 [3976.3196] <2> db_end: Need to collect reply 16:18:02.047 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:18:02.047 [3976.3196] <2> read_data: Total Kbytes transferred 542096384 16:18:02.047 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:18:02.047 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:18:02.047 [3976.3196] <16> socksend: failed to send this: 16:18:02.047 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:18:02.047 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835482 16:18:02.047 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835482 16:18:02.047 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:18:02.062 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:18:02.062 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54365 TO xxx.10.212.239.1556 fd = 1168 16:18:02.062 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:18:02.109 [3976.3196] <2> db_end: Need to collect reply 16:18:02.125 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 272, 2000000 Kbytes at 32746.623 Kbytes/sec 16:18:02.125 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:18:02.125 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835482 QXH126 36 16:18:02.125 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835482 QXH126 36 16:18:02.125 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 36 16:18:02.125 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:18:02.140 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835482 QXH126 16:18:02.140 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835482 QXH126 16:18:02.140 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 36 16:18:02.140 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:18:02.156 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:18:02.156 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54366 TO xxx.10.212.239.1556 fd = 1168 16:18:02.156 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:18:02.187 [3976.3196] <2> db_end: Need to collect reply 16:18:02.203 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 273, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:18:02.203 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:18:02.203 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:18:02.203 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:18:02.203 [3976.3196] <2> read_backup: fragment_num = 273 16:18:02.203 [3976.3196] <2> read_backup: Kbytes = 2000000 16:18:02.203 [3976.3196] <2> read_backup: remainder = 0 16:18:02.203 [3976.3196] <2> read_backup: id = QXH126 16:18:02.203 [3976.3196] <2> read_backup: file_num = 36 16:18:02.203 [3976.3196] <2> read_backup: block_size = 65536 16:18:02.203 [3976.3196] <2> read_backup: offset = 1093822 16:18:02.203 [3976.3196] <2> read_backup: data_format = 0 16:18:02.203 [3976.3196] <2> read_backup: **************************************************** 16:18:02.203 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:18:02.203 [3976.3196] <2> read_data: Total Kbytes transferred 542096384 16:18:02.203 [3976.3196] <2> read_position: read position on drive index 0, is LBA 1093823 16:18:02.203 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:18:02.203 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835482 16:18:02.203 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835482 16:18:05.869 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:18:08.068 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:18:08.068 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:18:08.068 [2352.4600] <16> socksend: failed to send this: 16:18:09.660 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:18:18.271 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:18:21.656 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:18:23.248 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:18:23.248 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:18:23.248 [2352.4600] <16> socksend: failed to send this: 16:18:25.323 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:18:28.864 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:18:32.000 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:18:36.118 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:18:36.118 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:18:36.118 [2352.4600] <16> socksend: failed to send this: 16:18:37.553 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:18:40.907 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:18:43.123 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:18:43.123 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:18:43.123 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:18:43.123 [3976.3196] <2> read_data: waited for empty buffer 88 times, delayed 386 times 16:18:43.123 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835523 4 bptm 3976 waited for empty buffer 88 times, delayed 386 times 16:18:43.123 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 79, msg = LOG 1430835523 4 bptm 3976 waited for empty buffer 88 times, delayed 386 times 16:18:43.123 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:18:43.123 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:18:43.123 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54367 TO xxx.10.212.239.1556 fd = 1144 16:18:43.123 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:18:43.185 [3976.3196] <2> db_end: Need to collect reply 16:18:43.201 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:18:43.201 [3976.3196] <2> read_data: Total Kbytes transferred 544096384 16:18:43.201 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:18:43.201 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:18:43.201 [3976.3196] <16> socksend: failed to send this: 16:18:43.201 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:18:43.201 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835523 16:18:43.201 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835523 16:18:43.201 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:18:43.201 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:18:43.201 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54368 TO xxx.10.212.239.1556 fd = 1120 16:18:43.201 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:18:43.232 [3976.3196] <2> db_end: Need to collect reply 16:18:43.263 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 273, 2000000 Kbytes at 48877.050 Kbytes/sec 16:18:43.263 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:18:43.263 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835523 QXH126 37 16:18:43.263 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835523 QXH126 37 16:18:43.263 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 37 16:18:43.263 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:18:43.263 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835523 QXH126 16:18:43.263 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835523 QXH126 16:18:43.263 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 37 16:18:43.263 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:18:43.263 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:18:43.263 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54369 TO xxx.10.212.239.1556 fd = 1168 16:18:43.263 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:18:43.325 [3976.3196] <2> db_end: Need to collect reply 16:18:43.341 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 274, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:18:43.341 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:18:43.341 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:18:43.341 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:18:43.341 [3976.3196] <2> read_backup: fragment_num = 274 16:18:43.341 [3976.3196] <2> read_backup: Kbytes = 2000000 16:18:43.341 [3976.3196] <2> read_backup: remainder = 0 16:18:43.341 [3976.3196] <2> read_backup: id = QXH126 16:18:43.341 [3976.3196] <2> read_backup: file_num = 37 16:18:43.341 [3976.3196] <2> read_backup: block_size = 65536 16:18:43.341 [3976.3196] <2> read_backup: offset = 1125074 16:18:43.341 [3976.3196] <2> read_backup: data_format = 0 16:18:43.341 [3976.3196] <2> read_backup: **************************************************** 16:18:43.341 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:18:43.341 [3976.3196] <2> read_data: Total Kbytes transferred 544096384 16:18:43.341 [3976.3196] <2> read_position: read position on drive index 0, is LBA 1125075 16:18:43.341 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:18:43.341 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835523 16:18:43.341 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835523 16:18:45.369 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:18:45.369 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:18:45.369 [2352.4600] <16> socksend: failed to send this: 16:18:51.063 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:18:54.620 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:18:57.101 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:18:58.349 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:18:58.349 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:18:58.349 [2352.4600] <16> socksend: failed to send this: 16:18:59.831 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:19:01.859 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:19:05.119 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:19:09.596 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:19:09.596 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:19:09.596 [2352.4600] <16> socksend: failed to send this: 16:19:10.501 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:19:12.436 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:19:14.589 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:19:15.821 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:19:15.821 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:19:15.821 [2352.4600] <16> socksend: failed to send this: 16:19:17.147 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:19:17.147 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:19:17.147 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:19:17.147 [3976.3196] <2> read_data: waited for empty buffer 194 times, delayed 538 times 16:19:17.147 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835557 4 bptm 3976 waited for empty buffer 194 times, delayed 538 times 16:19:17.147 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 80, msg = LOG 1430835557 4 bptm 3976 waited for empty buffer 194 times, delayed 538 times 16:19:17.147 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:19:17.163 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:19:17.163 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54370 TO xxx.10.212.239.1556 fd = 1164 16:19:17.163 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:19:17.194 [3976.3196] <2> db_end: Need to collect reply 16:19:17.209 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:19:17.209 [3976.3196] <2> read_data: Total Kbytes transferred 546096384 16:19:17.209 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:19:17.209 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:19:17.209 [3976.3196] <16> socksend: failed to send this: 16:19:17.209 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:19:17.209 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835557 16:19:17.209 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835557 16:19:17.209 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:19:17.225 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:19:17.225 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54371 TO xxx.10.212.239.1556 fd = 1168 16:19:17.225 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:19:17.272 [3976.3196] <2> db_end: Need to collect reply 16:19:17.287 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 274, 2000000 Kbytes at 59161.096 Kbytes/sec 16:19:17.287 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:19:17.287 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835557 QXH126 38 16:19:17.287 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835557 QXH126 38 16:19:17.287 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 38 16:19:17.287 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:19:17.287 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835557 QXH126 16:19:17.287 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835557 QXH126 16:19:17.287 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 38 16:19:17.287 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:19:17.303 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:19:17.303 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54372 TO xxx.10.212.239.1556 fd = 1168 16:19:17.303 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:19:17.334 [3976.3196] <2> db_end: Need to collect reply 16:19:17.350 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 275, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:19:17.350 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:19:17.350 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:19:17.350 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:19:17.350 [3976.3196] <2> read_backup: fragment_num = 275 16:19:17.350 [3976.3196] <2> read_backup: Kbytes = 2000000 16:19:17.350 [3976.3196] <2> read_backup: remainder = 0 16:19:17.350 [3976.3196] <2> read_backup: id = QXH126 16:19:17.350 [3976.3196] <2> read_backup: file_num = 38 16:19:17.350 [3976.3196] <2> read_backup: block_size = 65536 16:19:17.350 [3976.3196] <2> read_backup: offset = 1156326 16:19:17.350 [3976.3196] <2> read_backup: data_format = 0 16:19:17.350 [3976.3196] <2> read_backup: **************************************************** 16:19:17.350 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:19:17.350 [3976.3196] <2> read_data: Total Kbytes transferred 546096384 16:19:17.350 [3976.3196] <2> read_position: read position on drive index 0, is LBA 1156327 16:19:17.350 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:19:17.350 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835557 16:19:17.350 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835557 16:19:19.518 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:19:24.900 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:19:25.618 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:19:25.618 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:19:25.618 [2352.4600] <16> socksend: failed to send this: 16:19:26.523 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:19:28.691 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:19:31.406 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:19:32.997 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:19:32.997 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:19:32.997 [2352.4600] <16> socksend: failed to send this: 16:19:36.070 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:19:42.092 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:19:44.963 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:19:47.162 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:19:47.162 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:19:47.162 [2352.4600] <16> socksend: failed to send this: 16:19:48.441 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:19:56.897 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:19:56.897 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:19:56.897 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:19:56.897 [3976.3196] <2> read_data: waited for empty buffer 423 times, delayed 842 times 16:19:56.897 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835596 4 bptm 3976 waited for empty buffer 423 times, delayed 842 times 16:19:56.897 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 80, msg = LOG 1430835596 4 bptm 3976 waited for empty buffer 423 times, delayed 842 times 16:19:56.897 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:19:56.912 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:19:56.912 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54373 TO xxx.10.212.239.1556 fd = 1164 16:19:56.912 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:19:56.959 [3976.3196] <2> db_end: Need to collect reply 16:19:56.975 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:19:56.975 [3976.3196] <2> read_data: Total Kbytes transferred 548096384 16:19:56.975 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:19:56.975 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:19:56.975 [3976.3196] <16> socksend: failed to send this: 16:19:56.975 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:19:56.975 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835596 16:19:56.975 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835596 16:19:56.975 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:19:56.990 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:19:56.990 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54374 TO xxx.10.212.239.1556 fd = 1120 16:19:56.990 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:19:57.037 [3976.3196] <2> db_end: Need to collect reply 16:19:57.053 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 275, 2000000 Kbytes at 50572.736 Kbytes/sec 16:19:57.053 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:19:57.053 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835597 QXH126 39 16:19:57.053 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835597 QXH126 39 16:19:57.053 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 39 16:19:57.053 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:19:57.084 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835597 QXH126 16:19:57.084 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835597 QXH126 16:19:57.084 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 39 16:19:57.084 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:19:57.100 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:19:57.100 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54375 TO xxx.10.212.239.1556 fd = 1120 16:19:57.100 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:19:57.146 [3976.3196] <2> db_end: Need to collect reply 16:19:57.162 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 276, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:19:57.162 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:19:57.162 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:19:57.162 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:19:57.162 [3976.3196] <2> read_backup: fragment_num = 276 16:19:57.162 [3976.3196] <2> read_backup: Kbytes = 2000000 16:19:57.162 [3976.3196] <2> read_backup: remainder = 0 16:19:57.162 [3976.3196] <2> read_backup: id = QXH126 16:19:57.162 [3976.3196] <2> read_backup: file_num = 39 16:19:57.162 [3976.3196] <2> read_backup: block_size = 65536 16:19:57.162 [3976.3196] <2> read_backup: offset = 1187578 16:19:57.162 [3976.3196] <2> read_backup: data_format = 0 16:19:57.162 [3976.3196] <2> read_backup: **************************************************** 16:19:57.162 [3976.3196] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 2000000, opt_remainder = 0 16:19:57.162 [3976.3196] <2> read_data: Total Kbytes transferred 548096384 16:19:57.162 [3976.3196] <2> read_position: read position on drive index 0, is LBA 1187579 16:19:57.162 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:19:57.162 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835597 16:19:57.162 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835597 16:20:04.681 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:20:06.320 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:20:06.320 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:20:06.320 [2352.4600] <16> socksend: failed to send this: 16:20:08.004 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:20:10.516 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:20:12.310 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:20:13.730 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:20:13.730 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:20:13.730 [2352.4600] <16> socksend: failed to send this: 16:20:14.775 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:20:21.514 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:20:23.932 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:20:25.258 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:20:25.258 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:20:25.258 [2352.4600] <16> socksend: failed to send this: 16:20:26.366 [3976.3196] <2> read_data: Total_Kbytes_Read = 1600000 16:20:34.244 [3976.3196] <2> read_data: Total_Kbytes_Read = 1800000 16:20:41.951 [3976.3196] <2> read_data: Total_Kbytes_Read = 2000000 16:20:41.951 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:20:41.951 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:20:41.951 [3976.3196] <2> read_data: waited for empty buffer 279 times, delayed 500 times 16:20:41.951 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835641 4 bptm 3976 waited for empty buffer 279 times, delayed 500 times 16:20:41.951 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 80, msg = LOG 1430835641 4 bptm 3976 waited for empty buffer 279 times, delayed 500 times 16:20:41.951 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:20:41.951 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:20:41.951 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54376 TO xxx.10.212.239.1556 fd = 1164 16:20:41.951 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:20:42.013 [3976.3196] <2> db_end: Need to collect reply 16:20:42.029 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 2000000 2000000 (bptm.c.15089) 16:20:42.029 [3976.3196] <2> read_data: Total Kbytes transferred 550096384 16:20:42.029 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:20:42.029 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:20:42.029 [3976.3196] <16> socksend: failed to send this: 16:20:42.029 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:20:42.029 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835642 16:20:42.029 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835642 16:20:42.029 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:20:42.044 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:20:42.044 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54377 TO xxx.10.212.239.1556 fd = 1168 16:20:42.044 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:20:42.076 [3976.3196] <2> db_end: Need to collect reply 16:20:42.091 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 276, 2000000 Kbytes at 44654.818 Kbytes/sec 16:20:42.091 [3976.3196] <2> read_backup: current media id is QXH126, next media id is QXH126 16:20:42.091 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835642 QXH126 40 16:20:42.091 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835642 QXH126 40 16:20:42.091 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 40 16:20:42.091 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:20:42.107 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835642 QXH126 16:20:42.107 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835642 QXH126 16:20:42.107 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 40 16:20:42.107 [3976.3196] <2> read_backup: copy 2, fragment 277 is the last fragment for duplicate 16:20:42.107 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:20:42.122 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:20:42.122 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54378 TO xxx.10.212.239.1556 fd = 1168 16:20:42.122 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:20:42.169 [3976.3196] <2> db_end: Need to collect reply 16:20:42.185 [3976.3196] <4> read_backup: begin reading backup id OldSan_1128792038 (duplicate), copy 2, fragment 277, from media id QXH126 on drive HP.ULTRIUM4-SCSI.000 (index 0) 16:20:42.185 [3976.3196] <2> read_backup: could not open suspend event, The system cannot find the file specified. 16:20:42.185 [3976.3196] <2> bptm: Created stop_db_restore_event is 16:20:42.185 [3976.3196] <2> read_backup: ********** Using Fragment ************************** 16:20:42.185 [3976.3196] <2> read_backup: fragment_num = 277 16:20:42.185 [3976.3196] <2> read_backup: Kbytes = 1496978 16:20:42.185 [3976.3196] <2> read_backup: remainder = 0 16:20:42.185 [3976.3196] <2> read_backup: id = QXH126 16:20:42.185 [3976.3196] <2> read_backup: file_num = 40 16:20:42.185 [3976.3196] <2> read_backup: block_size = 65536 16:20:42.185 [3976.3196] <2> read_backup: offset = 1218830 16:20:42.185 [3976.3196] <2> read_backup: data_format = 0 16:20:42.185 [3976.3196] <2> read_backup: **************************************************** 16:20:42.185 [3976.3196] <2> read_data: last_frag = 1, opt_bytes_left = 0, tape_Kbytes_left = 1496978, opt_remainder = 0 16:20:42.185 [3976.3196] <2> read_data: Total Kbytes transferred 550096384 16:20:42.200 [3976.3196] <2> read_position: read position on drive index 0, is LBA 1218831 16:20:42.200 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0 16:20:42.200 [3976.3196] <2> set_job_details: Tfile (88868): BEGIN_READING 1430835642 16:20:42.200 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 25, msg = BEGIN_READING 1430835642 16:20:48.253 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:20:48.253 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:20:48.253 [2352.4600] <16> socksend: failed to send this: 16:20:53.199 [3976.3196] <2> read_data: Total_Kbytes_Read = 200000 16:20:54.915 [3976.3196] <2> read_data: Total_Kbytes_Read = 400000 16:20:59.376 [3976.3196] <2> read_data: Total_Kbytes_Read = 600000 16:21:03.791 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:21:03.791 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:21:03.791 [2352.4600] <16> socksend: failed to send this: 16:21:05.835 [3976.3196] <2> read_data: Total_Kbytes_Read = 800000 16:21:12.184 [3976.3196] <2> read_data: Total_Kbytes_Read = 1000000 16:21:14.883 [3976.3196] <2> read_data: Total_Kbytes_Read = 1200000 16:21:20.921 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:21:20.921 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:21:20.921 [2352.4600] <16> socksend: failed to send this: 16:21:23.167 [3976.3196] <2> read_data: Total_Kbytes_Read = 1400000 16:21:24.680 [3976.3196] <2> read_data: read short block, bytes = 18432, remainder = 0 16:21:24.680 [3976.3196] <2> read_data: ReadFile returned FALSE, A tape access reached a filemark. (1101);bytes = 0 16:21:24.680 [3976.3196] <2> read_data: ReadFile detected EOM or EOF, bytes = 0 16:21:24.680 [3976.3196] <2> read_data: waited for empty buffer 51 times, delayed 354 times 16:21:24.680 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835684 4 bptm 3976 waited for empty buffer 51 times, delayed 354 times 16:21:24.680 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 79, msg = LOG 1430835684 4 bptm 3976 waited for empty buffer 51 times, delayed 354 times 16:21:24.680 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:21:24.696 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:24.696 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54380 TO xxx.10.212.239.1556 fd = 1144 16:21:24.696 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:21:24.696 [2352.4600] <2> write_data: writing block shorter than BUFF_SIZE, 18432 bytes 16:21:24.696 [2352.4600] <2> write_data: writing short block, 18432 bytes, remainder 0 16:21:24.696 [2352.4600] <2> write_data: waited for full buffer 208403 times, delayed 825555 times 16:21:24.696 [2352.4600] <2> set_job_details: Tfile (88868): LOG 1430835684 4 bptm 2352 waited for full buffer 208403 times, delayed 825555 times 16:21:24.696 [2352.4600] <2> send_job_file: job ID 88868, ftype = 3 msg len = 85, msg = LOG 1430835684 4 bptm 2352 waited for full buffer 208403 times, delayed 825555 times 16:21:24.696 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:21:24.696 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:21:24.696 [2352.4600] <16> socksend: failed to send this: 16:21:24.696 [2352.4600] <2> write_data: Total Kbytes transferred 551593362 16:21:24.696 [2352.4600] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = 0 16:21:24.696 [2352.4600] <2> write_backup: tp = 549550634, stp = 530763761, et = 18786873, mpx_total_kbytes[TWIN_INDEX = 0] = 551593362 16:21:24.696 [2352.4600] <2> io_ioctl: command (0)MTWEOF 1 0x81 from (bptm.c.20388) on drive index 2 16:21:24.696 [2352.4600] <2> write_backup: Immediate BU done WEOF time 0 16:21:24.696 [2352.4600] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:21:24.712 [2352.4600] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:24.712 [2352.4600] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54381 TO xxx.10.212.239.1556 fd = 1152 16:21:24.712 [2352.4600] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:21:24.743 [2352.4600] <2> db_end: Need to collect reply 16:21:24.743 [3976.3196] <2> db_end: Need to collect reply 16:21:24.758 [2352.4600] <4> report_throughput: VBRT 1 2352 5 1 HP.ULTRIUM4-SCSI.002 VAB456 0 1 0 28393362 28393362 (bptm.c.20638) 16:21:24.758 [2352.4600] <2> write_backup_update_frags: ************** Fragment 1: ******************* 16:21:24.758 [2352.4600] <2> write_backup_update_frags: ++++ total image kbytes so far = 551593362 ++++ ` 16:21:24.758 [2352.4600] <2> write_backup_update_frags: ++++ fragment_num = 1 ++++ 16:21:24.758 [2352.4600] <2> write_backup_update_frags: copy_num = 1 16:21:24.758 [2352.4600] <2> write_backup_update_frags: Kbytes = 551593362 16:21:24.758 [2352.4600] <2> write_backup_update_frags: remainder = 0 16:21:24.758 [2352.4600] <2> write_backup_update_frags: id = VAB456 16:21:24.758 [2352.4600] <2> write_backup_update_frags: file_num = 13 16:21:24.758 [2352.4600] <2> write_backup_update_frags: block_size = 65536 16:21:24.758 [2352.4600] <2> write_backup_update_frags: offset = 5882731 16:21:24.758 [2352.4600] <2> write_backup_update_frags: data_format = 1 16:21:24.758 [2352.4600] <2> write_backup_update_frags: ****************************************************** 16:21:24.758 [2352.4600] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 77 16:21:24.758 [3976.3196] <4> report_throughput: VBRT 1 3976 4 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 1496978 1496978 (bptm.c.15089) 16:21:24.758 [3976.3196] <2> read_data: Total Kbytes transferred 551593362 16:21:24.758 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:21:24.758 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:21:24.758 [3976.3196] <16> socksend: failed to send this: 16:21:24.758 [3976.3196] <2> read_data: Could not send KeepAlive to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:21:24.758 [3976.3196] <2> set_job_details: Tfile (88868): END_READING 1430835684 16:21:24.758 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 23, msg = END_READING 1430835684 16:21:24.758 [3976.3196] <2> wait_for_tar: waiting for write side of duplicate to exit, timeout is 300 16:21:24.774 [2352.4600] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:24.774 [2352.4600] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54382 TO xxx.10.212.239.1556 fd = 1152 16:21:24.774 [2352.4600] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:21:24.821 [2352.4600] <2> db_end: Need to collect reply 16:21:25.180 [2352.4600] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:21:25.195 [2352.4600] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:25.195 [2352.4600] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54383 TO xxx.10.212.239.1556 fd = 1152 16:21:25.195 [2352.4600] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:21:25.226 [2352.4600] <2> db_end: Need to collect reply 16:21:25.242 [2352.4600] <4> write_backup: successfully wrote backup id OldSan_1128792038, copy 1, fragment 1, 551593362 Kbytes at 29360.573 Kbytes/sec 16:21:25.772 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:21:25.788 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:25.788 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54384 TO xxx.10.212.239.1556 fd = 1120 16:21:25.788 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:21:25.835 [3976.3196] <2> db_end: Need to collect reply 16:21:25.866 [3976.3196] <4> read_backup: successfully read (duplicate) backup id OldSan_1128792038, copy 2, fragment 277, 1496978 Kbytes at 35240.425 Kbytes/sec 16:21:25.866 [3976.3196] <2> connect_tir_socket: common.c.6514: connecting to Host: mediaserver 16:21:25.866 [3976.3196] <2> connect_tir_socket: common.c.6515: connecting to TirIpc: 52765 16:21:25.866 [3976.3196] <8> file_to_cache_item: [vnet_addrinfo.c:6577] fopen() failed ERRNO=2 FILE=C:\Program Files\Veritas\NetBackup\var\host_cache\0e0\871238e0+veritas_pbx,1,400,2,1,0+mediaserver.txt 16:21:25.866 [3976.3196] <8> file_to_cache_item: [vnet_addrinfo.c:6577] fopen() failed ERRNO=2 FILE=C:\Program Files\Veritas\NetBackup\var\host_cache\0e0\871238e0+vnetd,1,400,2,1,0+mediaserver.txt 16:21:25.866 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:25.882 [3976.3196] <8> do_pbx_service: [vnet_connect.c:2108] via PBX VNETD CONNECT FROM xxx.10.212.226.54385 TO xxx.10.212.226.1556 fd = 1168 16:21:25.882 [3976.3196] <8> vnet_vnetd_daemon_socket: [vnet_vnetd.c:381] VN_REQUEST_DAEMON_SOCKET 2 0x2 16:21:25.882 [3976.3196] <8> vnet_vnetd_daemon_socket: [vnet_vnetd.c:395] ipc_string 52765 16:21:25.944 [2352.4600] <2> io_set_recvbuf: setting receive network buffer to 263168 bytes 16:21:25.944 [3976.3196] <2> io_set_sendbuf: setting send network buffer to 132096 bytes 16:21:25.944 [2352.4600] <2> set_job_details: Tfile (88868): LOG 1430835685 4 bptm 2352 setting receive network buffer to 263168 bytes 16:21:25.944 [3976.3196] <2> io_set_sendbuf: send network buffer is 132096 bytes 16:21:25.944 [2352.4600] <2> send_job_file: job ID 88868, ftype = 3 msg len = 74, msg = LOG 1430835685 4 bptm 2352 setting receive network buffer to 263168 bytes 16:21:25.944 [3976.3196] <2> connect_tir_socket: tir socket connected, fd is 1168 16:21:25.944 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONING 1430835685 QXH126 41 16:21:25.944 [2352.4600] <2> io_set_recvbuf: receive network buffer is 263168 bytes 16:21:25.944 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 33, msg = POSITIONING 1430835685 QXH126 41 16:21:25.944 [2352.4600] <2> create_data_socket: tir socket created, fd is 736 16:21:25.944 [3976.3196] <2> io_position_for_read: positioning QXH126 to file number 41 16:21:25.944 [3976.3196] <2> io_read_back_header: drive index 0, reading backup header 16:21:25.960 [3976.3196] <2> set_job_details: Tfile (88868): POSITIONED 1430835685 QXH126 16:21:25.960 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 29, msg = POSITIONED 1430835685 QXH126 16:21:25.960 [3976.3196] <2> io_position_for_read: successfully positioned QXH126 to file number 41 16:21:26.006 [3976.3196] <2> read_position: read position on drive index 0, is LBA 1242224 16:21:26.006 [3976.3196] <2> append_to_client_log: d:\nb\nb_7.5.0.7\src\nb\dblib\dbmisc.c.3319: about to call ConnectToBPCD connect_opts = 0xffffffff 16:21:26.006 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 223 16:21:26.022 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:26.022 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54388 TO xxx.10.212.239.1556 fd = 1144 16:21:26.022 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:21:26.053 [3976.3196] <2> db_CLIENTsend: reset client protocol version from 0 to 8 16:21:26.256 [3976.3196] <2> db_getCLIENT: db_CLIENTreceive: no entity was found 227 16:21:26.256 [3976.3196] <2> ConnectToBPCD: db_getCLIENT(masterserver) failed: 227 16:21:26.256 [3976.3196] <2> local_bpcr_connect: bpcr.c.278: connect_opts = 0x01000100 connect_opts2 = 0x01000100 16:21:26.256 [3976.3196] <2> local_bpcr_connect: bpcr.c.285: connect_opts = 0x01000100 16:21:26.256 [3976.3196] <2> local_bpcr_connect: bpcr.c.324: daemon_port_type = 0 16:21:26.272 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:26.272 [3976.3196] <2> logconnections: BPCD CONNECT FROM xxx.10.212.226.54389 TO xxx.10.212.239.1556 fd = 1144 16:21:26.287 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:26.303 [3976.3196] <8> do_pbx_service: [vnet_connect.c:2108] via PBX VNETD CONNECT FROM xxx.10.212.226.54390 TO xxx.10.212.239.1556 fd = 1164 16:21:26.303 [3976.3196] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:443] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa 16:21:26.506 [3976.3196] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:460] ipc_string 51751 16:21:27.972 [3976.3196] <2> read_data_tir: beginning duplicate of TIR information, expected size is 150158410 + 0 GB 16:21:27.972 [3976.3196] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 1 IS_NDMP 0 16:21:27.972 [2352.4600] <2> write_data_tir: size of tir data received from read side is 150158410 bytes + 0 GB 16:21:27.972 [2352.4600] <2> append_to_client_log: d:\nb\nb_7.5.0.7\src\nb\dblib\dbmisc.c.3319: about to call ConnectToBPCD connect_opts = 0xffffffff 16:21:27.972 [2352.4600] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 223 16:21:27.988 [2352.4600] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:27.988 [2352.4600] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54391 TO xxx.10.212.239.1556 fd = 1144 16:21:27.988 [2352.4600] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:21:28.034 [2352.4600] <2> db_CLIENTsend: reset client protocol version from 0 to 8 16:21:28.253 [2352.4600] <2> db_getCLIENT: db_CLIENTreceive: no entity was found 227 16:21:28.253 [2352.4600] <2> ConnectToBPCD: db_getCLIENT(masterserver) failed: 227 16:21:28.253 [2352.4600] <2> local_bpcr_connect: bpcr.c.278: connect_opts = 0x01000100 connect_opts2 = 0x01000100 16:21:28.253 [2352.4600] <2> local_bpcr_connect: bpcr.c.285: connect_opts = 0x01000100 16:21:28.253 [2352.4600] <2> local_bpcr_connect: bpcr.c.324: daemon_port_type = 0 16:21:28.268 [2352.4600] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:28.268 [2352.4600] <2> logconnections: BPCD CONNECT FROM xxx.10.212.226.54392 TO xxx.10.212.239.1556 fd = 1144 16:21:28.284 [2352.4600] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:28.300 [2352.4600] <8> do_pbx_service: [vnet_connect.c:2108] via PBX VNETD CONNECT FROM xxx.10.212.226.54393 TO xxx.10.212.239.1556 fd = 1124 16:21:28.300 [2352.4600] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:443] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa 16:21:28.502 [2352.4600] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:460] ipc_string 51753 16:21:29.984 [2352.4600] <2> write_data_tir: INF - Begin writing True Image Recovery information for copy 1. 16:21:30.016 [2352.4600] <2> write_data_tir: absolute block position prior to writing backup header(s) is 14501380, copy 1 16:21:30.016 [2352.4600] <2> write_data_tir: block position check: actual 14501380, expected 14501380 16:21:30.016 [2352.4600] <2> io_write_back_header: drive index 2, OldSan_1128792038, file num = 14, mpx_headers = 0, copy 1 16:21:30.031 [2352.4600] <2> ndmp_setup_for_write: CINDEX 0, TWIN_INDEX 0, IS_NDMP 0, is_tir 1 16:21:30.031 [2352.4600] <2> write_data_tir: writing first TIR block to media, bytes = 65536 16:21:32.465 [3976.3196] <2> read_data_tir: remove rounded, total_bytes_read 150159360, extra 950 16:21:32.481 [3976.3196] <2> read_data_tir: ReadFile() A tape access reached a filemark. ; read 0 bytes 16:21:32.481 [3976.3196] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:21:32.481 [2352.4600] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:21:32.496 [3976.3196] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:32.496 [3976.3196] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54394 TO xxx.10.212.239.1556 fd = 1168 16:21:32.496 [3976.3196] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:21:32.496 [2352.4600] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:32.496 [2352.4600] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54395 TO xxx.10.212.239.1556 fd = 736 16:21:32.496 [2352.4600] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:21:32.527 [3976.3196] <2> db_end: Need to collect reply 16:21:32.543 [3976.3196] <4> report_throughput: VBRT 1 3976 6 1 HP.ULTRIUM4-SCSI.000 QXH126 0 1 0 146639 146639 (bptm.c.15960) 16:21:32.543 [3976.3196] <2> read_data_tir: Total Kbytes transferred 551740001 16:21:32.543 [3976.3196] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.000, from bptm.c.16444 16:21:32.543 [3976.3196] <2> openTpreqFile: tpreq_file: C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.000, serial_num: F0A233609C 16:21:32.543 [3976.3196] <2> get_drive_path: SCSI coordinates {5,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi#5&2eb07dfa&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b} 16:21:32.543 [3976.3196] <2> check_serial_num: serial number match for drive with SCSI coordinates {5,0,0,0}, dos_path \\.\Tape0, drive serial number F0A233609C, expected serial number F0A233609C 16:21:32.543 [2352.4600] <2> db_end: Need to collect reply 16:21:32.559 [2352.4600] <4> report_throughput: VBRT 1 2352 7 1 HP.ULTRIUM4-SCSI.002 VAB456 0 1 0 146640 146640 (bptm.c.27986) 16:21:32.559 [2352.4600] <2> write_data_tir: Total Kbytes transferred 551740001 16:21:32.559 [2352.4600] <2> io_terminate_tape: writing empty backup header, drive index 2, copy 1 16:21:32.559 [2352.4600] <2> io_ioctl: command (0)MTWEOF 1 0x1 from (bptm.c.8863) on drive index 2 16:21:32.559 [3976.3196] <2> init_tape: \\.\Tape0 (SCSI coordinates {5,0,0,0}) configured with blocksize 0 16:21:32.559 [3976.3196] <2> init_tape: \\.\Tape0 (SCSI coordinates {5,0,0,0}) has compression enabled 16:21:32.574 [3976.3196] <2> io_open: SCSI RESERVE 16:21:32.574 [3976.3196] <2> io_open: file C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.000 successfully opened (mode 2) 16:21:32.574 [3976.3196] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tpunmount) 16:21:32.574 [3976.3196] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.000, from bptm.c.16480 16:21:32.574 [3976.3196] <2> drivename_write: Called with mode 1 16:21:32.574 [3976.3196] <2> drivename_unlock: unlocked 16:21:32.574 [3976.3196] <2> drivename_checklock: Called 16:21:32.574 [3976.3196] <2> drivename_lock: lock established 16:21:32.574 [3976.3196] <2> drivename_unlock: unlocked 16:21:32.574 [3976.3196] <2> drivename_close: Called for file HP.ULTRIUM4-SCSI.000 16:21:32.574 [3976.3196] <2> tpunmount: NOP: MEDIA_DONE 0 88868 0 QXH126 4002557 180 {11683187-5EFB-4C23-9B08-2F757808F9E9} 16:21:32.574 [3976.3196] <2> notify: executing - C:\Program Files\Veritas\NetBackup\bin\restore_notify.cmd bptm OldSan_1128792038 duplication 16:21:32.808 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835692 4 bptm 3976 completed reading backup image 16:21:32.808 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 58, msg = LOG 1430835692 4 bptm 3976 completed reading backup image 16:21:32.808 [3976.3196] <2> bptm: Calling tpunmount for media QXH126 16:21:32.808 [3976.3196] <2> send_MDS_msg: MEDIA_DONE 0 88868 0 QXH126 4002557 180 {11683187-5EFB-4C23-9B08-2F757808F9E9} 16:21:32.808 [3976.3196] <2> JobInst::sendIrmMsg: starting 16:21:32.808 [3976.3196] <2> packageBptmResourceDoneMsg: msg (MEDIA_DONE 0 88868 0 QXH126 4002557 180 {11683187-5EFB-4C23-9B08-2F757808F9E9}) 16:21:32.808 [3976.3196] <2> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid 88868 copyNum 0 mediaId QXH126 mediaKey 4002557 unloadDelay 180 allocId {11683187-5EFB-4C23-9B08-2F757808F9E9} 16:21:32.808 [3976.3196] <2> packageBptmResourceDoneMsg: returns 0 16:21:32.808 [3976.3196] <2> JobInst::sendIrmMsg: returning 16:21:32.808 [3976.3196] <16> socksend: failed writing to socket (h_errno=10054) 16:21:32.808 [3976.3196] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:21:32.808 [3976.3196] <16> socksend: failed to send this: 16:21:32.808 [3976.3196] <2> main: Could not send EXIT status to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:21:32.808 [3976.3196] <2> get_short_base: (1) cannot read (byte 1) from network: An existing connection was forcibly closed by the remote host. 16:21:32.808 [3976.3196] <2> main: Got bpduplicate acknowledgement status: -3, err: 10054 16:21:32.808 [3976.3196] <2> bptm: EXITING with status 0 <---------- 16:21:32.808 [3976.3196] <2> set_job_details: Tfile (88868): LOG 1430835692 4 bptm 3976 EXITING with status 0 <---------- 16:21:32.808 [3976.3196] <2> send_job_file: job ID 88868, ftype = 3 msg len = 61, msg = LOG 1430835692 4 bptm 3976 EXITING with status 0 <---------- 16:21:32.808 [3976.3196] <2> bptm: Global\NetBackup Terminate Event, pid: 3976 closed. 16:21:35.086 [2352.4600] <2> io_terminate_tape: absolute block position prior to writing empty header is 14503674, copy 1 16:21:35.086 [2352.4600] <2> io_write_back_header: drive index 2, empty_file, file num = 15, mpx_headers = 0, copy 1 16:21:35.101 [2352.4600] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.002, from bptm.c.8976 16:21:35.101 [2352.4600] <2> io_terminate_tape: block position check: actual 14503674, expected 14503674 16:21:35.101 [2352.4600] <2> send_MDS_msg: MEDIADB 1 20984 VAB456 4002446 *NULL* 20 1430805241 1430816886 2147483647 0 928086063 13 13 11 23 0 0 1024 0 14503674 0 16:21:35.117 [2352.4600] <2> openTpreqFile: tpreq_file: C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.002, serial_num: F0A2336094 16:21:35.117 [2352.4600] <2> get_drive_path: SCSI coordinates {5,0,2,0}, dos_path \\.\Tape2, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi#5&2eb07dfa&0&000200#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b} 16:21:35.164 [2352.4600] <2> check_serial_num: serial number match for drive with SCSI coordinates {5,0,2,0}, dos_path \\.\Tape2, drive serial number F0A2336094, expected serial number F0A2336094 16:21:35.273 [2352.4600] <2> init_tape: \\.\Tape2 (SCSI coordinates {5,0,2,0}) configured with blocksize 0 16:21:35.289 [2352.4600] <2> init_tape: \\.\Tape2 (SCSI coordinates {5,0,2,0}) has compression enabled 16:21:35.289 [2352.4600] <2> io_open: SCSI RESERVE 16:21:35.289 [2352.4600] <2> io_open: file C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.002 successfully opened (mode 2) 16:21:39.516 [2352.4600] <2> io_terminate_tape: locate block positioned tape to 14503674 in io_terminate_tape 16:21:39.532 [2352.4600] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.002, from bptm.c.9159 16:21:39.532 [2352.4600] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from io_terminate_tape) 16:21:39.532 [2352.4600] <2> write_data_tir: adding copy 1 fragment -1 (146640 Kbytes) for TIR data, filenum 14 16:21:39.532 [2352.4600] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 77 16:21:39.548 [2352.4600] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:21:39.548 [2352.4600] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54396 TO xxx.10.212.239.1556 fd = 736 16:21:39.548 [2352.4600] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:21:39.579 [2352.4600] <2> db_end: Need to collect reply 16:21:39.891 [2352.4600] <2> send_MDS_msg: MEDIADB 1 20984 VAB456 4002446 *NULL* 20 1430805241 1430816886 2147483647 0 928232703 14 14 11 23 0 0 1024 0 14503674 0 16:21:39.906 [2352.4600] <2> notify: executing - C:\Program Files\Veritas\NetBackup\bin\backup_notify.cmd bptm OldSan_1128792038 16:21:39.984 [2352.4600] <2> updateEMM_freespace: updateEMM_freespace() (1 0) 16:21:39.984 [2352.4600] <2> updateEMM_freespace: 0, mediaserver-hcart3-robot-tld-2-singledrive (1 0 2 1) 16:21:39.984 [2352.4600] <2> bptm: Calling tpunmount for media VAB456 16:21:39.984 [2352.4600] <2> drivename_write: Called with mode 1 16:21:39.984 [2352.4600] <2> drivename_unlock: unlocked 16:21:39.984 [2352.4600] <2> drivename_checklock: Called 16:21:39.984 [2352.4600] <2> drivename_lock: lock established 16:21:39.984 [2352.4600] <2> drivename_unlock: unlocked 16:21:39.984 [2352.4600] <2> drivename_close: Called for file HP.ULTRIUM4-SCSI.002 16:21:39.984 [2352.4600] <2> send_MDS_msg: MEDIA_DONE 0 88868 0 VAB456 4002446 180 {2D2E0007-3CCC-4DF3-A193-4BACFB9EB309} 16:21:39.984 [2352.4600] <2> JobInst::sendIrmMsg: starting 16:21:39.984 [2352.4600] <2> packageBptmResourceDoneMsg: msg (MEDIA_DONE 0 88868 0 VAB456 4002446 180 {2D2E0007-3CCC-4DF3-A193-4BACFB9EB309}) 16:21:39.984 [2352.4600] <2> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid 88868 copyNum 0 mediaId VAB456 mediaKey 4002446 unloadDelay 180 allocId {2D2E0007-3CCC-4DF3-A193-4BACFB9EB309} 16:21:39.984 [2352.4600] <2> packageBptmResourceDoneMsg: returns 0 16:21:39.984 [2352.4600] <2> JobInst::sendIrmMsg: returning 16:21:39.984 [2352.4600] <16> socksend: failed writing to socket (h_errno=10054) 16:21:39.984 [2352.4600] <16> socksend: failed writing to socket: An existing connection was forcibly closed by the remote host. 16:21:39.984 [2352.4600] <16> socksend: failed to send this: 16:21:39.984 [2352.4600] <2> main: Could not send EXIT status to bpduplicate on socket. Error = 10054 - An existing connection was forcibly closed by the remote host. 16:21:39.984 [2352.4600] <2> get_short_base: (1) cannot read (byte 1) from network: An existing connection was forcibly closed by the remote host. 16:21:39.984 [2352.4600] <2> main: Got bpduplicate acknowledgement status: -3, err: 10054 16:21:39.984 [2352.4600] <2> bptm: EXITING with status 0 <---------- 16:21:39.984 [2352.4600] <2> set_job_details: Tfile (88868): LOG 1430835699 4 bptm 2352 EXITING with status 0 <---------- 16:21:39.984 [2352.4600] <2> send_job_file: job ID 88868, ftype = 3 msg len = 61, msg = LOG 1430835699 4 bptm 2352 EXITING with status 0 <---------- 16:21:39.984 [2352.4600] <2> bptm: Global\NetBackup Terminate Event, pid: 2352 closed. 16:24:12.525 [5452.5324] <2> initialize: fd values STDOUTSOCK=244 STDERRSOCK=508 16:24:12.525 [5452.5324] <2> bptm: instance - 549718460 16:24:12.525 [5452.5324] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1430298875 -jm 16:24:12.525 [5452.5324] <2> bptm: Event Global\NetBackup Terminate Event, pid: 5452 created. 16:24:12.525 [5452.5324] <2> bptm: PORT_STATUS = 0x00000000 16:24:12.525 [5452.5324] <2> drivename_open: Called with Create 0, file HP.ULTRIUM4-SCSI.000 16:24:12.525 [5452.5324] <2> drivename_checklock: Called 16:24:12.525 [5452.5324] <2> report_drives: DRIVE = HP.ULTRIUM4-SCSI.000 LOCK = FALSE CURTIME = 1430835852 16:24:12.525 [5452.5324] <2> drivename_close: Called for file HP.ULTRIUM4-SCSI.000 16:24:12.525 [5452.5324] <2> report_drives: MODE = 1 16:24:12.525 [5452.5324] <2> report_drives: TIME = 1430835692 16:24:12.525 [5452.5324] <2> report_drives: MASTER = masterserver 16:24:12.525 [5452.5324] <2> report_drives: SR_KEY = 0 1 16:24:12.525 [5452.5324] <2> report_drives: PATH = {5,0,0,0} 16:24:12.525 [5452.5324] <2> report_drives: MEDIA = QXH126 16:24:12.525 [5452.5324] <2> report_drives: REQID = 88868 16:24:12.525 [5452.5324] <2> report_drives: ALOCID = 20988 16:24:12.525 [5452.5324] <2> report_drives: RBID = {11683187-5EFB-4C23-9B08-2F757808F9E9} 16:24:12.525 [5452.5324] <2> report_drives: PID = 3976 16:24:12.525 [5452.5324] <2> report_drives: FILE = C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.000 16:24:12.525 [5452.5324] <2> drivename_open: Called with Create 0, file HP.ULTRIUM4-SCSI.002 16:24:12.525 [5452.5324] <2> drivename_checklock: Called 16:24:12.525 [5452.5324] <2> report_drives: DRIVE = HP.ULTRIUM4-SCSI.002 LOCK = FALSE CURTIME = 1430835852 16:24:12.525 [5452.5324] <2> drivename_close: Called for file HP.ULTRIUM4-SCSI.002 16:24:12.525 [5452.5324] <2> report_drives: MODE = 1 16:24:12.525 [5452.5324] <2> report_drives: TIME = 1430835699 16:24:12.525 [5452.5324] <2> report_drives: MASTER = masterserver 16:24:12.525 [5452.5324] <2> report_drives: SR_KEY = 0 1 16:24:12.525 [5452.5324] <2> report_drives: PATH = {5,0,2,0} 16:24:12.525 [5452.5324] <2> report_drives: MEDIA = VAB456 16:24:12.525 [5452.5324] <2> report_drives: REQID = 88868 16:24:12.525 [5452.5324] <2> report_drives: ALOCID = 20984 16:24:12.525 [5452.5324] <2> report_drives: RBID = {2D2E0007-3CCC-4DF3-A193-4BACFB9EB309} 16:24:12.525 [5452.5324] <2> report_drives: PID = 2352 16:24:12.525 [5452.5324] <2> report_drives: FILE = C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.002 16:24:12.525 [5452.5324] <2> main: Sending [EXIT STATUS 0] to NBJM 16:24:12.525 [5452.5324] <2> bptm: EXITING with status 0 <---------- 16:24:12.525 [5452.5324] <2> bptm: Global\NetBackup Terminate Event, pid: 5452 closed. 16:24:34.537 [1168.3316] <2> initialize: fd values STDOUTSOCK=244 STDERRSOCK=508 16:24:34.553 [1168.3316] <2> bptm: instance - 549740487 16:24:34.553 [1168.3316] <2> bptm: INITIATING (VERBOSE = 5): -unload -dn HP.ULTRIUM4-SCSI.000 -dp {5,0,0,0} -dk 2000023 -m QXH126 -mk 4002557 -mds 16 -alocid 20988 -jobid -1430298876 -jm 16:24:34.553 [1168.3316] <2> bptm: Event Global\NetBackup Terminate Event, pid: 1168 created. 16:24:34.553 [1168.3316] <2> bptm: PORT_STATUS = 0x00000000 16:24:34.553 [1168.3316] <8> vnet_same_host_and_update: [vnet_addrinfo.c:2829] name2 is empty 0 0x0 16:24:34.553 [1168.3316] <4> bptm: emmserver_name = masterserver 16:24:34.553 [1168.3316] <4> bptm: emmserver_port = 1556 16:24:34.568 [1168.3316] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:604) 16:24:34.568 [1168.3316] <2> Orb::init: initializing ORB EMMlib_Orb with: bptm -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:842) 16:24:34.568 [1168.3316] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:857) 16:24:34.568 [1168.3316] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1498) 16:24:34.568 [1168.3316] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1507) 16:24:34.584 [1168.3316] <2> send_brm_msg: PID of bpxm = 1168 16:24:34.584 [1168.3316] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD/6 16:24:34.584 [1168.3316] <2> nbjm_media_request: old_media_id = NULL, media_id = QXH126 16:24:34.584 [1168.3316] <2> RequestInitialResources: starting 16:24:34.584 [1168.3316] <2> RequestInitialResources: started 16:24:34.584 [1168.3316] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:604) 16:24:34.584 [1168.3316] <2> Orb::init: Created anon service name: NB_1168_11436916(Orb.cpp:714) 16:24:34.584 [1168.3316] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_1168_11436916(Orb.cpp:731) 16:24:34.584 [1168.3316] <2> Orb::init: initializing ORB Default_DAEMON_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_1168_11436916 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:842) 16:24:34.584 [1168.3316] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:857) 16:24:34.584 [1168.3316] <2> packageInitialResourceRequest: started 16:24:34.584 [1168.3316] <2> packageInitialResourceRequest: retVal = 0 16:24:34.584 [1168.3316] <2> RequestInitialResources: setting up callback and calling requestResources 16:24:34.600 [1168.3316] <2> logResourceReq: req.versionId : 1 16:24:34.600 [1168.3316] <2> logResourceReq: req.jobId : -1430298876 16:24:34.600 [1168.3316] <2> logResourceReq: req.startedViaJobManager : true 16:24:34.600 [1168.3316] <2> logResourceReq: req.consumer : true 16:24:34.600 [1168.3316] <2> logResourceReq: InitialMediaSelect - 16:24:34.600 [1168.3316] <2> logResourceReq: reqNum : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.mediaId : QXH126 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.mediaKey : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.mediaServer : mediaserver 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.userReservationId : 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.assignedTime : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.client : 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.usageType : 6 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.mustBeNdmp : false 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.driveName : HP.ULTRIUM4-SCSI.000 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.drivePath : 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.mediaPool : 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.robotNumber : -1 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.slotNumber : -1 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.density : -1 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.ndmpControlHost : 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.failIfNoMedia : true 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.externalFile : 16:24:34.600 [1168.3316] <2> logMediaRequest: mreq.exp 16:24:34.600 [1168.3316] <2> logMediaRequest: mediaType : -1 16:24:34.600 [1168.3316] <2> logMediaRequest: mediaSubType : -1 16:24:34.600 [1168.3316] <2> logMediaRequest: exp.capabilities 16:24:34.600 [1168.3316] <2> logMediaRequest: isNdmp : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: isTirRestore : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: isFlashbackupRestore : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: isBlockMapRead : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: isCatalogBackup : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: isGcsCatalogBackup : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: preferVtlToDirectAttachedTape : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: isVMWare : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: isLifeCycle : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: useFt : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: failIfNoFt : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: isGranularExchange : 0 16:24:34.600 [1168.3316] <2> logMediaRequest: requestFlags : 0x0 16:24:34.600 [1168.3316] <2> logMediaRequest: NDMPHostName : 16:24:34.600 [1168.3316] <2> logMediaRequest: mediaServerAffinityID : 0 16:24:34.600 [1168.3316] <2> RequestInitialResources: BpxmiV->requestResourcesWithTimeout returns 0 16:24:34.600 [1168.3316] <2> resourcesAvailable: m_allocationSeq.length() == 1 16:24:34.600 [1168.3316] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 7 16:24:34.600 [1168.3316] <2> resourcesAvailable: MEDIADB 1 20988 QXH126 4002557 ------ 20 1128792038 0 2147483647 1430501991 0 999 0 0 18 0 520 1024 0 0 0 16:24:34.600 [1168.3316] <2> resourcesAvailable: VOLUME 1 QXH126 4002557 QXH126 OldMediaPool *NULL* *NULL* 24 8 0 56 0 {00000000-0000-0000-0000-000000000000} 0 16:24:34.600 [1168.3316] <2> resourcesAvailable: DRIVE 3 HP.ULTRIUM4-SCSI.000 2000023 F0A233609C {5,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0 16:24:34.600 [1168.3316] <2> resourcesAvailable: STORAGE 1 *NULL* 0 0 0 0 0 0 mediaserver mediaserver *NULL* 16:24:34.600 [1168.3316] <2> resourcesAvailable: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL* 16:24:34.600 [1168.3316] <2> resourcesAvailable: DISKVOLUME 0 6 *NULL* 6 *NULL* 0 16:24:34.600 [1168.3316] <2> resourcesAvailable: DISKMOUNTPOINT 0 6 *NULL* 16:24:34.600 [1168.3316] <2> packageInitialResourceRequestResult: totalNumberOfAllocations == 1 16:24:34.600 [1168.3316] <2> packageInitialResourceRequestResult: m_allocationSeq.length=1 16:24:34.600 [1168.3316] <2> packageInitialResourceRequestResult: found MediaAllocation : reqNum == 0 16:24:34.600 [1168.3316] <2> packageInitialResourceRequestResult: matched MediaAllocation to a initialMediaSelect 16:24:34.600 [1168.3316] <2> packageInitialResourceRequestResult: retVal = 0 16:24:34.600 [1168.3316] <2> RequestInitialResources: retVal = 0 emmStatus = 0 16:24:34.600 [1168.3316] <2> RequestInitialResources: returning 16:24:34.600 [1168.3316] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 20988 QXH126 4002557 ------ 20 1128792038 0 2147483647 1430501991 0 999 0 0 18 0 520 1024 0 0 0], length 105 16:24:34.600 [1168.3316] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 QXH126 4002557 QXH126 OldMediaPool *NULL* *NULL* 24 8 0 56 0 {00000000-0000-0000-0000-000000000000} 0], length 110 16:24:34.600 [1168.3316] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 3 HP.ULTRIUM4-SCSI.000 2000023 F0A233609C {5,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0], length 122 16:24:34.600 [1168.3316] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 1 *NULL* 0 0 0 0 0 0 mediaserver mediaserver *NULL*], length 57 16:24:34.600 [1168.3316] <2> populateBptmOpaqueStrings: packaging bptm string [DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*], length 38 16:24:34.600 [1168.3316] <2> populateBptmOpaqueStrings: packaging bptm string [DISKVOLUME 0 6 *NULL* 6 *NULL* 0], length 32 16:24:34.600 [1168.3316] <2> populateBptmOpaqueStrings: packaging bptm string [DISKMOUNTPOINT 0 6 *NULL*], length 25 16:24:34.600 [1168.3316] <2> populateBptmOpaqueStrings: retVal = 0 16:24:34.600 [1168.3316] <2> parse_resource_strings: MEDIADB 1 20988 QXH126 4002557 ------ 20 1128792038 0 2147483647 1430501991 0 999 0 0 18 0 520 1024 0 0 0 16:24:34.600 [1168.3316] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters 16:24:34.600 [1168.3316] <2> parse_resource_strings: VOLUME 1 QXH126 4002557 QXH126 OldMediaPool *NULL* *NULL* 24 8 0 56 0 {00000000-0000-0000-0000-000000000000} 0 16:24:34.600 [1168.3316] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters 16:24:34.600 [1168.3316] <2> parse_resource_strings: DRIVE 3 HP.ULTRIUM4-SCSI.000 2000023 F0A233609C {5,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0 16:24:34.600 [1168.3316] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters 16:24:34.600 [1168.3316] <2> parse_resource_strings: STORAGE 1 *NULL* 0 0 0 0 0 0 mediaserver mediaserver *NULL* 16:24:34.600 [1168.3316] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters 16:24:34.600 [1168.3316] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL* 16:24:34.600 [1168.3316] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters 16:24:34.600 [1168.3316] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0 16:24:34.600 [1168.3316] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters 16:24:34.600 [1168.3316] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL* 16:24:34.600 [1168.3316] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters 16:24:34.600 [1168.3316] <2> nbjm_media_request: Job control returned to BPTM 16:24:34.600 [1168.3316] <2> drivename_open: Called with Create 1, file HP.ULTRIUM4-SCSI.000 16:24:34.600 [1168.3316] <2> drivename_checklock: Called 16:24:34.600 [1168.3316] <2> drivename_lock: lock established 16:24:34.600 [1168.3316] <4> create_tpreq_file: {5,0,0,0} 16:24:34.600 [1168.3316] <2> drivename_write: Called with mode 2 16:24:34.600 [1168.3316] <2> drivename_unlock: unlocked 16:24:34.600 [1168.3316] <2> drivename_checklock: Called 16:24:34.600 [1168.3316] <2> drivename_lock: lock established 16:24:34.600 [1168.3316] <2> openNTDevice: config_path: {5,0,0,0}, serial_num: F0A233609C 16:24:34.600 [1168.3316] <2> get_drive_path: SCSI coordinates {5,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi#5&2eb07dfa&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b} 16:24:34.615 [1168.3316] <2> check_serial_num: serial number match for drive with SCSI coordinates {5,0,0,0}, dos_path \\.\Tape0, drive serial number F0A233609C, expected serial number F0A233609C 16:24:34.631 [1168.3316] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release) 16:24:34.631 [1168.3316] <2> really_tpunmount: tpunmount'ing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.000 16:24:35.036 [1168.3316] <2> tapelib: wait_for_ltid, UnMount, timeout 2400 16:24:40.809 [5624.5348] <2> initialize: fd values STDOUTSOCK=244 STDERRSOCK=508 16:24:40.824 [5624.5348] <2> bptm: instance - 549746758 16:24:40.824 [5624.5348] <2> bptm: INITIATING (VERBOSE = 5): -unload -dn HP.ULTRIUM4-SCSI.002 -dp {5,0,2,0} -dk 2000025 -m VAB456 -mk 4002446 -mds 0 -alocid 20984 -jobid -1430298877 -jm 16:24:40.824 [5624.5348] <2> bptm: Event Global\NetBackup Terminate Event, pid: 5624 created. 16:24:40.824 [5624.5348] <2> bptm: PORT_STATUS = 0x00000000 16:24:40.824 [5624.5348] <8> vnet_same_host_and_update: [vnet_addrinfo.c:2829] name2 is empty 0 0x0 16:24:40.824 [5624.5348] <4> bptm: emmserver_name = masterserver 16:24:40.824 [5624.5348] <4> bptm: emmserver_port = 1556 16:24:40.840 [5624.5348] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:604) 16:24:40.840 [5624.5348] <2> Orb::init: initializing ORB EMMlib_Orb with: bptm -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:842) 16:24:40.840 [5624.5348] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:857) 16:24:40.840 [5624.5348] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1498) 16:24:40.840 [5624.5348] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1507) 16:24:40.840 [5624.5348] <2> send_brm_msg: PID of bpxm = 5624 16:24:40.840 [5624.5348] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD/6 16:24:40.840 [5624.5348] <2> nbjm_media_request: old_media_id = NULL, media_id = VAB456 16:24:40.840 [5624.5348] <2> RequestInitialResources: starting 16:24:40.840 [5624.5348] <2> RequestInitialResources: started 16:24:40.840 [5624.5348] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:604) 16:24:40.840 [5624.5348] <2> Orb::init: Created anon service name: NB_5624_26120677(Orb.cpp:714) 16:24:40.840 [5624.5348] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_5624_26120677(Orb.cpp:731) 16:24:40.840 [5624.5348] <2> Orb::init: initializing ORB Default_DAEMON_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_5624_26120677 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:842) 16:24:40.840 [5624.5348] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:857) 16:24:40.855 [5624.5348] <2> packageInitialResourceRequest: started 16:24:40.855 [5624.5348] <2> packageInitialResourceRequest: retVal = 0 16:24:40.855 [5624.5348] <2> RequestInitialResources: setting up callback and calling requestResources 16:24:40.855 [5624.5348] <2> logResourceReq: req.versionId : 1 16:24:40.855 [5624.5348] <2> logResourceReq: req.jobId : -1430298877 16:24:40.855 [5624.5348] <2> logResourceReq: req.startedViaJobManager : true 16:24:40.855 [5624.5348] <2> logResourceReq: req.consumer : true 16:24:40.855 [5624.5348] <2> logResourceReq: InitialMediaSelect - 16:24:40.855 [5624.5348] <2> logResourceReq: reqNum : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.mediaId : VAB456 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.mediaKey : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.mediaServer : mediaserver 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.userReservationId : 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.assignedTime : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.client : 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.usageType : 6 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.mustBeNdmp : false 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.driveName : HP.ULTRIUM4-SCSI.002 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.drivePath : 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.mediaPool : 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.robotNumber : -1 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.slotNumber : -1 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.density : -1 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.ndmpControlHost : 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.failIfNoMedia : true 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.externalFile : 16:24:40.855 [5624.5348] <2> logMediaRequest: mreq.exp 16:24:40.855 [5624.5348] <2> logMediaRequest: mediaType : -1 16:24:40.855 [5624.5348] <2> logMediaRequest: mediaSubType : -1 16:24:40.855 [5624.5348] <2> logMediaRequest: exp.capabilities 16:24:40.855 [5624.5348] <2> logMediaRequest: isNdmp : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: isTirRestore : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: isFlashbackupRestore : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: isBlockMapRead : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: isCatalogBackup : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: isGcsCatalogBackup : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: preferVtlToDirectAttachedTape : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: isVMWare : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: isLifeCycle : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: useFt : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: failIfNoFt : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: isGranularExchange : 0 16:24:40.855 [5624.5348] <2> logMediaRequest: requestFlags : 0x0 16:24:40.855 [5624.5348] <2> logMediaRequest: NDMPHostName : 16:24:40.855 [5624.5348] <2> logMediaRequest: mediaServerAffinityID : 0 16:24:40.855 [5624.5348] <2> RequestInitialResources: BpxmiV->requestResourcesWithTimeout returns 0 16:24:40.855 [5624.5348] <2> resourcesAvailable: m_allocationSeq.length() == 1 16:24:40.855 [5624.5348] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 7 16:24:40.855 [5624.5348] <2> resourcesAvailable: MEDIADB 1 20984 VAB456 4002446 ------ 20 1430805241 1430809988 2147483647 0 376492701 12 12 11 23 0 0 1024 0 5882731 0 16:24:40.855 [5624.5348] <2> resourcesAvailable: VOLUME 1 VAB456 4002446 VAB456 onsite_hcart3 FUJIFILM J18VEEWGWC 24 8 0 61 0 {00000000-0000-0000-0000-000000000000} 0 16:24:40.855 [5624.5348] <2> resourcesAvailable: DRIVE 3 HP.ULTRIUM4-SCSI.002 2000025 F0A2336094 {5,0,2,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0 16:24:40.855 [5624.5348] <2> resourcesAvailable: STORAGE 1 mediaserver-hcart3-robot-tld-2-singledrive 20 1048576 2 1 0 0 mediaserver mediaserver *NULL* 16:24:40.855 [5624.5348] <2> resourcesAvailable: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL* 16:24:40.855 [5624.5348] <2> resourcesAvailable: DISKVOLUME 0 6 *NULL* 6 *NULL* 0 16:24:40.855 [5624.5348] <2> resourcesAvailable: DISKMOUNTPOINT 0 6 *NULL* 16:24:40.855 [5624.5348] <2> packageInitialResourceRequestResult: totalNumberOfAllocations == 1 16:24:40.855 [5624.5348] <2> packageInitialResourceRequestResult: m_allocationSeq.length=1 16:24:40.855 [5624.5348] <2> packageInitialResourceRequestResult: found MediaAllocation : reqNum == 0 16:24:40.855 [5624.5348] <2> packageInitialResourceRequestResult: matched MediaAllocation to a initialMediaSelect 16:24:40.855 [5624.5348] <2> packageInitialResourceRequestResult: retVal = 0 16:24:40.855 [5624.5348] <2> RequestInitialResources: retVal = 0 emmStatus = 0 16:24:40.855 [5624.5348] <2> RequestInitialResources: returning 16:24:40.855 [5624.5348] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 20984 VAB456 4002446 ------ 20 1430805241 1430809988 2147483647 0 376492701 12 12 11 23 0 0 1024 0 5882731 0], length 118 16:24:40.855 [5624.5348] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 VAB456 4002446 VAB456 onsite_hcart3 FUJIFILM J18VEEWGWC 24 8 0 61 0 {00000000-0000-0000-0000-000000000000} 0], length 117 16:24:40.855 [5624.5348] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 3 HP.ULTRIUM4-SCSI.002 2000025 F0A2336094 {5,0,2,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0], length 121 16:24:40.855 [5624.5348] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 1 mediaserver-hcart3-robot-tld-2-singledrive 20 1048576 2 1 0 0 mediaserver mediaserver *NULL*], length 99 16:24:40.855 [5624.5348] <2> populateBptmOpaqueStrings: packaging bptm string [DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*], length 38 16:24:40.855 [5624.5348] <2> populateBptmOpaqueStrings: packaging bptm string [DISKVOLUME 0 6 *NULL* 6 *NULL* 0], length 32 16:24:40.855 [5624.5348] <2> populateBptmOpaqueStrings: packaging bptm string [DISKMOUNTPOINT 0 6 *NULL*], length 25 16:24:40.855 [5624.5348] <2> populateBptmOpaqueStrings: retVal = 0 16:24:40.855 [5624.5348] <2> parse_resource_strings: MEDIADB 1 20984 VAB456 4002446 ------ 20 1430805241 1430809988 2147483647 0 376492701 12 12 11 23 0 0 1024 0 5882731 0 16:24:40.855 [5624.5348] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters 16:24:40.855 [5624.5348] <2> parse_resource_strings: VOLUME 1 VAB456 4002446 VAB456 onsite_hcart3 FUJIFILM J18VEEWGWC 24 8 0 61 0 {00000000-0000-0000-0000-000000000000} 0 16:24:40.855 [5624.5348] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters 16:24:40.855 [5624.5348] <2> parse_resource_strings: DRIVE 3 HP.ULTRIUM4-SCSI.002 2000025 F0A2336094 {5,0,2,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0 16:24:40.855 [5624.5348] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters 16:24:40.855 [5624.5348] <2> parse_resource_strings: STORAGE 1 mediaserver-hcart3-robot-tld-2-singledrive 20 1048576 2 1 0 0 mediaserver mediaserver *NULL* 16:24:40.855 [5624.5348] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters 16:24:40.855 [5624.5348] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL* 16:24:40.855 [5624.5348] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters 16:24:40.855 [5624.5348] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0 16:24:40.855 [5624.5348] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters 16:24:40.855 [5624.5348] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL* 16:24:40.855 [5624.5348] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters 16:24:40.855 [5624.5348] <2> nbjm_media_request: Job control returned to BPTM 16:24:40.855 [5624.5348] <2> drivename_open: Called with Create 1, file HP.ULTRIUM4-SCSI.002 16:24:40.855 [5624.5348] <2> drivename_checklock: Called 16:24:40.855 [5624.5348] <2> drivename_lock: lock established 16:24:40.855 [5624.5348] <4> create_tpreq_file: {5,0,2,0} 16:24:40.855 [5624.5348] <2> drivename_write: Called with mode 2 16:24:40.855 [5624.5348] <2> drivename_unlock: unlocked 16:24:40.855 [5624.5348] <2> drivename_checklock: Called 16:24:40.855 [5624.5348] <2> drivename_lock: lock established 16:24:40.855 [5624.5348] <2> openNTDevice: config_path: {5,0,2,0}, serial_num: F0A2336094 16:24:40.855 [5624.5348] <2> get_drive_path: SCSI coordinates {5,0,2,0}, dos_path \\.\Tape2, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi#5&2eb07dfa&0&000200#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b} 16:24:40.871 [5624.5348] <2> check_serial_num: serial number match for drive with SCSI coordinates {5,0,2,0}, dos_path \\.\Tape2, drive serial number F0A2336094, expected serial number F0A2336094 16:24:41.027 [5624.5348] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release) 16:24:41.027 [5624.5348] <2> really_tpunmount: tpunmount'ing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.002 16:24:42.244 [5624.5348] <2> tapelib: wait_for_ltid, UnMount, timeout 2400 16:25:28.062 [1168.3316] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:25:28.078 [1168.3316] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:25:28.078 [1168.3316] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54423 TO xxx.10.212.239.1556 fd = 1132 16:25:28.078 [1168.3316] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:25:28.125 [1168.3316] <2> db_end: Need to collect reply 16:25:28.140 [1168.3316] <4> report_resource_done: VBRD 1 1168 0 HP.ULTRIUM4-SCSI.000 QXH126 16:25:28.140 [1168.3316] <2> openNTDevice: config_path: {5,0,0,0}, serial_num: F0A233609C 16:25:28.140 [1168.3316] <2> get_drive_path: SCSI coordinates {5,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi#5&2eb07dfa&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b} 16:25:28.156 [1168.3316] <2> check_serial_num: serial number match for drive with SCSI coordinates {5,0,0,0}, dos_path \\.\Tape0, drive serial number F0A233609C, expected serial number F0A233609C 16:25:28.249 [1168.3316] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release) 16:25:28.281 [1168.3316] <2> tapealert_and_release: report_attr, fl1 0x00000001, fl2 0x00000000 16:25:28.296 [1168.3316] <2> tapealert_and_release: SCSI RELEASE 16:25:28.296 [1168.3316] <2> drivename_unlock: unlocked 16:25:28.296 [1168.3316] <2> drivename_close: Called for file HP.ULTRIUM4-SCSI.000 16:25:28.296 [1168.3316] <2> drivename_remove: Called 16:25:28.296 [1168.3316] <2> main: Sending [EXIT STATUS 0] to NBJM 16:25:28.296 [1168.3316] <2> bptm: EXITING with status 0 <---------- 16:25:28.296 [1168.3316] <2> bptm: Global\NetBackup Terminate Event, pid: 1168 closed. 16:26:59.184 [5624.5348] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1 16:26:59.200 [5624.5348] <2> vnet_pbxConnect: pbxConnectEx Succeeded 16:26:59.200 [5624.5348] <2> logconnections: BPDBM CONNECT FROM xxx.10.212.226.54425 TO xxx.10.212.239.1556 fd = 1136 16:26:59.200 [5624.5348] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 16:26:59.231 [5624.5348] <2> db_end: Need to collect reply 16:26:59.247 [5624.5348] <4> report_resource_done: VBRD 1 5624 0 HP.ULTRIUM4-SCSI.002 VAB456 16:26:59.247 [5624.5348] <2> openNTDevice: config_path: {5,0,2,0}, serial_num: F0A2336094 16:26:59.247 [5624.5348] <2> get_drive_path: SCSI coordinates {5,0,2,0}, dos_path \\.\Tape2, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi#5&2eb07dfa&0&000200#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b} 16:26:59.262 [5624.5348] <2> check_serial_num: serial number match for drive with SCSI coordinates {5,0,2,0}, dos_path \\.\Tape2, drive serial number F0A2336094, expected serial number F0A2336094 16:26:59.262 [5624.5348] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release) 16:26:59.293 [5624.5348] <2> tapealert_and_release: report_attr, fl1 0x00000001, fl2 0x00000000 16:26:59.309 [5624.5348] <2> tapealert_and_release: SCSI RELEASE 16:26:59.309 [5624.5348] <2> drivename_unlock: unlocked 16:26:59.309 [5624.5348] <2> drivename_close: Called for file HP.ULTRIUM4-SCSI.002 16:26:59.309 [5624.5348] <2> drivename_remove: Called 16:26:59.309 [5624.5348] <2> main: Sending [EXIT STATUS 0] to NBJM 16:26:59.309 [5624.5348] <2> bptm: EXITING with status 0 <---------- 16:26:59.309 [5624.5348] <2> bptm: Global\NetBackup Terminate Event, pid: 5624 closed. 16:34:12.470 [2196.2192] <2> initialize: fd values STDOUTSOCK=244 STDERRSOCK=512 16:34:12.485 [2196.2192] <2> bptm: instance - 550318408 16:34:12.485 [2196.2192] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1430298879 -jm 16:34:12.485 [2196.2192] <2> bptm: Event Global\NetBackup Terminate Event, pid: 2196 created. 16:34:12.485 [2196.2192] <2> bptm: PORT_STATUS = 0x00000000 16:34:12.485 [2196.2192] <2> main: Sending [EXIT STATUS 0] to NBJM 16:34:12.485 [2196.2192] <2> bptm: EXITING with status 0 <---------- 16:34:12.485 [2196.2192] <2> bptm: Global\NetBackup Terminate Event, pid: 2196 closed. 16:44:12.835 [664.5268] <2> initialize: fd values STDOUTSOCK=244 STDERRSOCK=508 16:44:12.851 [664.5268] <2> bptm: instance - 550918747 16:44:12.851 [664.5268] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1430298881 -jm 16:44:12.851 [664.5268] <2> bptm: Event Global\NetBackup Terminate Event, pid: 664 created. 16:44:12.851 [664.5268] <2> bptm: PORT_STATUS = 0x00000000 16:44:12.851 [664.5268] <2> main: Sending [EXIT STATUS 0] to NBJM 16:44:12.851 [664.5268] <2> bptm: EXITING with status 0 <---------- 16:44:12.851 [664.5268] <2> bptm: Global\NetBackup Terminate Event, pid: 664 closed. 16:54:12.437 [656.5592] <2> initialize: fd values STDOUTSOCK=244 STDERRSOCK=508 16:54:12.437 [656.5592] <2> bptm: instance - 551518415 16:54:12.437 [656.5592] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1430298883 -jm 16:54:12.437 [656.5592] <2> bptm: Event Global\NetBackup Terminate Event, pid: 656 created. 16:54:12.437 [656.5592] <2> bptm: PORT_STATUS = 0x00000000 16:54:12.437 [656.5592] <2> main: Sending [EXIT STATUS 0] to NBJM 16:54:12.437 [656.5592] <2> bptm: EXITING with status 0 <---------- 16:54:12.437 [656.5592] <2> bptm: Global\NetBackup Terminate Event, pid: 656 closed. 17:04:13.128 [6120.4952] <2> initialize: fd values STDOUTSOCK=244 STDERRSOCK=508 17:04:13.128 [6120.4952] <2> bptm: instance - 552119112 17:04:13.128 [6120.4952] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1430298885 -jm 17:04:13.128 [6120.4952] <2> bptm: Event Global\NetBackup Terminate Event, pid: 6120 created. 17:04:13.128 [6120.4952] <2> bptm: PORT_STATUS = 0x00000000 17:04:13.128 [6120.4952] <2> main: Sending [EXIT STATUS 0] to NBJM 17:04:13.128 [6120.4952] <2> bptm: EXITING with status 0 <---------- 17:04:13.128 [6120.4952] <2> bptm: Global\NetBackup Terminate Event, pid: 6120 closed. 17:14:12.166 [4564.3768] <2> initialize: fd values STDOUTSOCK=244 STDERRSOCK=508 17:14:12.181 [4564.3768] <2> bptm: instance - 552718156 17:14:12.181 [4564.3768] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1430298887 -jm 17:14:12.181 [4564.3768] <2> bptm: Event Global\NetBackup Terminate Event, pid: 4564 created. 17:14:12.181 [4564.3768] <2> bptm: PORT_STATUS = 0x00000000 17:14:12.181 [4564.3768] <2> main: Sending [EXIT STATUS 0] to NBJM 17:14:12.181 [4564.3768] <2> bptm: EXITING with status 0 <---------- 17:14:12.181 [4564.3768] <2> bptm: Global\NetBackup Terminate Event, pid: 4564 closed. 17:24:12.469 [5704.2420] <2> initialize: fd values STDOUTSOCK=244 STDERRSOCK=508 17:24:12.485 [5704.2420] <2> bptm: instance - 553318448 17:24:12.485 [5704.2420] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1430298889 -jm 17:24:12.485 [5704.2420] <2> bptm: Event Global\NetBackup Terminate Event, pid: 5704 created. 17:24:12.485 [5704.2420] <2> bptm: PORT_STATUS = 0x00000000 17:24:12.485 [5704.2420] <2> main: Sending [EXIT STATUS 0] to NBJM 17:24:12.485 [5704.2420] <2> bptm: EXITING with status 0 <---------- 17:24:12.485 [5704.2420] <2> bptm: Global\NetBackup Terminate Event, pid: 5704 closed.