18:55:54.019 [5200.1132] <2> bptm: INITIATING (VERBOSE = 0): -pid 416 -mpx_restore -S archivo1 -mud 180 
18:55:54.019 [5200.1132] <4> bptm: emmserver_name = archivo1
18:55:54.019 [5200.1132] <4> bptm: emmserver_port = 1556
18:55:54.035 [5200.1132] <2> Orb::init: initializing ORB EMMlib_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -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:739)
18:55:54.035 [5200.1132] <2> send_brm_msg: PID of bpxm = 5200
18:55:54.035 [5200.1132] <2> process_mpx_protocol: wait for initial START RESTORE message from bpbrm
18:55:55.050 [5200.1132] <2> read_brm_msg: START RESTORE -b Storage05_1249079206 -bt 1249079206 -c storage05 -cl Enero -st 0 -ct 0 -firstblk 69579223 -flport 0 -flipc 55791 -restoreid 1666.001 -cn 1 -hostname storage05 -rclnt archivo1 -rclnthostname archivo1 -L /C/Program??Files/Veritas/NetBackup/logs/user_ops/coop/logs/NBWIN127 -ru root -lcmsg ESS -lctime ESS -no_callback -connect_options 0x01010100 -jobid 1666
18:55:55.081 [5200.1132] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
18:55:55.081 [5200.1132] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
18:55:55.081 [5200.1132] <2> logconnections: BPDBM CONNECT FROM 192.168.73.16.55809 TO 192.168.73.16.13724
18:55:55.128 [5200.1132] <2> mpx_read_init: image is not multiplexed
18:55:55.128 [5200.1132] <2> mpx_read_init: media id 0024L3, copy 1, fragment 1 (398389952 Kbytes) filenum 1 being considered for restore
18:55:55.128 [5200.1132] <2> mpx_compute_skip_info: will skip to block 543587 of fragment 1 to start restore, remain = 87, bytes_to_skip = 44544
18:55:55.128 [5200.1132] <2> mpx_compute_skip_info: changed Kbytes_left to 363600384
18:55:55.128 [5200.1132] <2> mpx_read_init: filenumber for new restore is 1, Mpx_Filenum is -1
18:55:55.128 [5200.1132] <4> report_client: VBRC 2 5200 0 Storage05_1249079206 0 Enero 0 *NULL* 0 1 1 
18:55:55.128 [5200.1132] <2> mpx_setup_restore_shm: using 30 data buffers, buffer size is 65536
18:55:55.128 [5200.1132] <2> mpx_setup_restore_shm: child delay = 10, parent delay = 15 (milliseconds)
18:55:55.128 [5200.1132] <2> mpx_setup_restore_shm: shm_size = 1968600, buffer address = 0x2ad0000, buf control = 0x2cb0000, ready ptr = 0x2cb02d0, res_cntl = 0x2cb02d8
18:55:55.128 [5200.1132] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 192.168.73.16.55813 TO 192.168.73.54.13724 fd = 1180
18:55:55.144 [5200.1132] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
18:55:55.347 [5200.1132] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: 49393
18:55:55.425 [5200.1132] <2> mpx_start_child: backup child for Storage05_1249079206 is pid 5640.9080, CINDEX = 0
18:55:55.425 [5200.1132] <2> send_brm_msg: NCB_DATASOCKET Storage05_1249079206 49393;d1435705a34fbcb2c9537de3918a11d5;4;300
18:55:55.425 [5200.1132] <2> LOCAL CLASS_ATT_DEFS: Product ID = 6
18:55:55.472 [5200.1132] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
18:55:55.472 [5200.1132] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
18:55:55.472 [5200.1132] <2> logconnections: BPCD CONNECT FROM 192.168.73.16.55814 TO 192.168.73.16.13724
18:55:55.472 [5200.1132] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 192.168.73.16.55815 TO 192.168.73.16.13724 fd = 1188
18:55:55.472 [5640.9080] <2> bptm: INITIATING (VERBOSE = 0): -pid 416 -mpx_restore -S archivo1 -mud 180 -den 20 -b Storage05_1249079206 -restoreid 1666.001 -cl Enero -c storage05 -hostname storage05 -L /C/Program??Files/Veritas/NetBackup/logs/user_ops/coop/logs/NBWIN127 -ru root -rclnt archivo1 -rclnthostname archivo1 -flipc 55791 -mmflush 5200 0 65536 30 10 0 44544 0 0 22998734 0 0 
18:55:55.472 [5640.9080] <4> bptm: emmserver_name = archivo1
18:55:55.472 [5640.9080] <4> bptm: emmserver_port = 1556
18:55:55.488 [5640.9080] <2> Orb::init: initializing ORB EMMlib_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -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:739)
18:55:55.503 [5640.9080] <2> setup_mm_child: [5200] child using 30 data buffers
18:55:55.503 [5640.9080] <2> setup_mm_child: [5200] child buffer size is 65536
18:55:55.503 [5640.9080] <2> setup_mm_child: [5200] buffer address = 0x2b30000, buf control = 0x2d10000, ready ptr = 0x2d102d0, res_cntl = 0x2d102d8
18:55:55.503 [5200.1132] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
18:55:55.503 [5200.1132] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: 55824
18:55:55.503 [5200.1132] <2> nbjm_media_request: Passing job control to NBJM, type READ/2
18:55:55.503 [5200.1132] <2> nbjm_media_request: old_media_id = , media_id = 0024L3
18:55:55.503 [5200.1132] <2> Orb::init: Created anon service name: NB_5200_1924394281(Orb.cpp:610)
18:55:55.503 [5200.1132] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_5200_1924394281(Orb.cpp:628)
18:55:55.503 [5200.1132] <2> Orb::init: initializing ORB Default_CLIENT_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_CLIENT_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_5200_1924394281 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:739)
18:55:57.535 [5200.1132] <2> Media_signal_poll: Read bpbrm message (MultiResReq.cpp:2244)
18:55:57.535 [5200.1132] <2> process_brm_msg: no pending message from bpbrm
18:55:57.535 [5200.1132] <2> RequestInitialResources: returning
18:55:57.535 [5200.1132] <2> parse_resource_strings: MEDIADB 1 1358 0024L3 4000024 ------ 20 1354560372 0 2147483647 1558993576 0 999 0 0 1 2 1 1024 0 0 0
18:55:57.535 [5200.1132] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
18:55:57.535 [5200.1132] <2> parse_resource_strings: VOLUME 1 0024L3 4000024 -------- NetBackup *NULL* *NULL* 24 0 0 0 0 {00000000-0000-0000-0000-000000000000} 0
18:55:57.535 [5200.1132] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
18:55:57.535 [5200.1132] <2> parse_resource_strings: DRIVE 3 HPULTRIUM5 2000003 HU1139JP8T {1,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 17 0 1 0 0
18:55:57.535 [5200.1132] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
18:55:57.535 [5200.1132] <2> parse_resource_strings: STORAGE 1 *NULL* 0 0 0 0 0 0 archivo1 archivo1 *NULL*
18:55:57.535 [5200.1132] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
18:55:57.535 [5200.1132] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
18:55:57.535 [5200.1132] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
18:55:57.535 [5200.1132] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
18:55:57.535 [5200.1132] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
18:55:57.535 [5200.1132] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
18:55:57.535 [5200.1132] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
18:55:57.535 [5200.1132] <2> nbjm_media_request: Job control returned to BPTM
18:55:57.535 [5200.1132] <2> drivename_open: Called with Create 1, file HPULTRIUM5
18:55:57.535 [5200.1132] <2> drivename_checklock: Called
18:55:57.535 [5200.1132] <2> drivename_lock: lock established
18:55:57.535 [5200.1132] <2> drivename_write: Called with mode 0
18:55:57.535 [5200.1132] <2> drivename_unlock: unlocked
18:55:57.535 [5200.1132] <2> drivename_checklock: Called
18:55:57.535 [5200.1132] <2> drivename_lock: lock established
18:55:57.535 [5200.1132] <2> mount_open_media: Waiting for mount of media id 0024L3 (copy 1) on server archivo1.
18:55:57.566 [5200.1132] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
18:55:57.566 [5200.1132] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpjobd
18:55:57.566 [5200.1132] <2> job_connect: SO_KEEPALIVE set on socket 1332 for client archivo1
18:55:57.566 [5200.1132] <2> logconnections: BPJOBD CONNECT FROM 192.168.73.16.55844 TO 192.168.73.16.13724
18:55:57.566 [5200.1132] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
18:55:57.566 [5200.1132] <2> job_connect: Connected to the host archivo1 contype 10 jobid <1666> socket <1332>
18:55:57.566 [5200.1132] <2> job_connect: Connected on port 55844
18:55:57.597 [5200.1132] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
18:55:57.597 [5200.1132] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
18:55:57.597 [5200.1132] <2> logconnections: BPCD CONNECT FROM 192.168.73.16.55846 TO 192.168.73.16.13724
18:55:57.597 [5200.1132] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 192.168.73.16.55847 TO 192.168.73.16.13724 fd = 1340
18:55:57.644 [5200.1132] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
18:55:57.644 [5200.1132] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: 55849
18:55:57.644 [5200.1132] <2> openNTDevice: config_path: {1,0,0,0}, serial_num: HU1139JP8T
18:55:57.659 [5200.1132] <2> get_drive_path: SCSI coordinates {1,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_5-scsi#5&95213a4&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
18:55:57.659 [5200.1132] <2> check_serial_num: serial number match for drive with SCSI coordinates {1,0,0,0}, dos_path \\.\Tape0, drive serial number HU1139JP8T, expected serial number HU1139JP8T
18:55:57.659 [5200.1132] <2> manage_scsi_reserve: SCSI RESERVE
18:55:58.675 [5200.1132] <2> tapelib: wait_for_ltid, Mount, timeout 0
18:55:58.706 [5640.9080] <2> io_set_sendbuf: setting send network buffer to 132096 bytes
18:55:58.706 [5640.9080] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 192.168.73.16.55853 TO 192.168.73.16.13724 fd = 496
18:55:58.738 [5640.9080] <2> vnet_vnetd_daemon_socket: vnet_vnetd.c.473: VN_REQUEST_DAEMON_SOCKET: 2 0x00000002
18:55:58.738 [5640.9080] <2> vnet_vnetd_daemon_socket: vnet_vnetd.c.487: ipc_string: 55791
18:55:58.738 [5640.9080] <2> connect_bprd_socket: [5200] data socket to bprd is connected port = 0,  fd = 496, DATAPORT=0, duping to stdin
18:55:59.706 [5200.1132] <2> openTpreqFile: tpreq_file: C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HPULTRIUM5, serial_num: HU1139JP8T
18:55:59.706 [5200.1132] <2> get_drive_path: SCSI coordinates {1,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_5-scsi#5&95213a4&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
18:55:59.706 [5200.1132] <2> check_serial_num: serial number match for drive with SCSI coordinates {1,0,0,0}, dos_path \\.\Tape0, drive serial number HU1139JP8T, expected serial number HU1139JP8T
18:55:59.706 [5200.1132] <2> init_tape: \\.\Tape0 (SCSI coordinates {1,0,0,0}) configured with blocksize 0
18:55:59.722 [5200.1132] <2> init_tape: \\.\Tape0 (SCSI coordinates {1,0,0,0}) has compression enabled
18:55:59.722 [5200.1132] <2> io_open: SCSI RESERVE (C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HPULTRIUM5)
18:56:00.081 [5200.1132] <2> manage_drive_attributes: report_attr, fl1 0x00010429, fl2 0x0000000c
18:56:00.081 [5200.1132] <2> manage_drive_attributes: Reported medium manufacturer [HP], sn [E74TO0J752]
18:56:00.081 [5200.1132] <2> manage_drive_attributes: Host Attributes: Vendor [SYMANTEC], Name [NetBackup BPTM], Version [6.5]
18:56:00.081 [5200.1132] <2> manage_drive_attributes: DateLabeled [200907312226], Barcode [000024L3], Owninghost [storage01]
18:56:00.081 [5200.1132] <2> manage_drive_attributes: MediaPool [Marzo2], MediaLabel [MEDIA=0024L3;]
18:56:00.081 [5200.1132] <2> openTpreqFile: tpreq_file: C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HPULTRIUM5, serial_num: HU1139JP8T
18:56:00.081 [5200.1132] <2> get_drive_path: SCSI coordinates {1,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_5-scsi#5&95213a4&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
18:56:00.081 [5200.1132] <2> check_serial_num: serial number match for drive with SCSI coordinates {1,0,0,0}, dos_path \\.\Tape0, drive serial number HU1139JP8T, expected serial number HU1139JP8T
18:56:00.113 [5200.1132] <2> init_tape: \\.\Tape0 (SCSI coordinates {1,0,0,0}) configured with blocksize 0
18:56:00.113 [5200.1132] <2> io_open: file C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HPULTRIUM5 successfully opened (mode 0)
18:56:00.113 [5200.1132] <2> io_read_media_header: drive index 0, reading media header, buflen = 65536, buff = 0x2d3eed0, copy 1
18:56:00.113 [5200.1132] <2> io_ioctl: command (5)MTREW 1 from (bptm.c.8175) on drive index 0
18:56:03.550 [5200.1132] <2> io_ioctl: command (1)MTFSF 1 from (bptm.c.8432) on drive index 0
18:56:03.597 [5200.1132] <2> bptm media_id_to_monitor: job_id = 1666
18:56:03.597 [5200.1132] <2> bptm media_id_to_monitor: pSrcMediaId = 0024L3
18:56:03.597 [5200.1132] <2> read_backup_mount_media: media id 0024L3 mounted on drive index 0
18:56:03.597 [5200.1132] <2> send_MDS_msg: MEDIADB 1 1358 0024L3 4000024 *NULL* 20 1354560372 0 2147483647 1558994163 0 999 0 0 1 3 1 1024 0 0 0
18:56:03.659 [5200.1132] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
18:56:03.659 [5200.1132] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
18:56:03.659 [5200.1132] <2> logconnections: BPCD CONNECT FROM 192.168.73.16.55855 TO 192.168.73.16.13724
18:56:03.659 [5200.1132] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 192.168.73.16.55856 TO 192.168.73.16.13724 fd = 656
18:56:03.769 [5200.1132] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
18:56:03.769 [5200.1132] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: 55858
18:56:03.784 [5200.1132] <2> io_position_for_read: positioning 0024L3 to file number 1
18:56:03.784 [5200.1132] <2> io_read_back_header: drive index 0, reading backup header
18:56:03.800 [5200.1132] <2> io_position_for_read: successfully positioned 0024L3 to file number 1
18:56:03.800 [5200.1132] <2> read_backup_fsr: current position of tape is 3, locating to 543590
18:56:41.455 [5200.1132] <2> read_backup_fsr: locate block is done
18:56:41.502 [5200.1132] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
18:56:41.502 [5200.1132] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
18:56:41.502 [5200.1132] <2> logconnections: BPCD CONNECT FROM 192.168.73.16.55860 TO 192.168.73.16.13724
18:56:41.502 [5200.1132] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 192.168.73.16.55861 TO 192.168.73.16.13724 fd = 1376
18:56:41.549 [5200.1132] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
18:56:41.564 [5200.1132] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: 55862
18:56:41.564 [5200.1132] <4> mpx_issue_begin_msg: begin reading backup id Storage05_1249079206 (restore), copy 1, fragment 1, from media id 0024L3 on drive HPULTRIUM5 (index 0)
18:56:41.564 [5200.1132] <2> send_brm_msg: CURRENT POSITION 0024L3 1
18:56:41.564 [5200.1132] <2> process_brm_msg: no pending message from bpbrm
18:56:42.580 [5200.1132] <2> read_brm_msg: CONTINUE RESTORE
18:56:42.580 [5200.1132] <2> send_brm_msg: MEDIA READY
18:56:42.580 [5200.1132] <2> mpx_read_data: begin reading data from media id 0024L3, file num 1
18:56:42.580 [5200.1132] <2> mpx_read_data: Total Kbytes transferred 0
18:56:42.580 [5200.1132] <2> read_position: read position on drive index 0, is LBA 543590
18:56:42.611 [5640.9080] <2> filter_image: [5200] Min_records before frag switch is 90000, locate available = 1
18:56:57.032 [5640.9080] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
18:56:57.032 [5640.9080] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpjobd
18:56:57.048 [5640.9080] <2> job_connect: SO_KEEPALIVE set on socket 1076 for client archivo1
18:56:57.048 [5640.9080] <2> logconnections: BPJOBD CONNECT FROM 192.168.73.16.55866 TO 192.168.73.16.13724
18:56:57.048 [5640.9080] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
18:56:57.048 [5640.9080] <2> job_connect: Connected to the host archivo1 contype 10 jobid <1666> socket <1076>
18:56:57.048 [5640.9080] <2> job_connect: Connected on port 55866
18:56:57.048 [5640.9080] <2> get_long: (2) premature end of file (byte 1)
18:56:57.048 [5640.9080] <2> job_monitoring_exex: Failed to get frame type
18:56:57.048 [5640.9080] <2> job_disconnect: Disconnected
18:56:57.048 [5640.9080] <16> write_to_out: cannot write data to socket, 10054
18:56:57.095 [5640.9080] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
18:56:57.095 [5640.9080] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
18:56:57.095 [5640.9080] <2> logconnections: BPCD CONNECT FROM 192.168.73.16.55870 TO 192.168.73.16.13724
18:56:57.095 [5640.9080] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 192.168.73.16.55874 TO 192.168.73.16.13724 fd = 1208
18:56:57.142 [5640.9080] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
18:56:57.142 [5640.9080] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: 55875
18:56:57.157 [5200.1132] <2> read_brm_msg: STOP RESTORE Storage05_1249079206
18:56:57.157 [5200.1132] <2> notify: executing - C:\Program Files\Veritas\NetBackup\bin\restore_notify.cmd bptm Storage05_1249079206 restore
18:56:57.282 [5640.9080] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
18:56:57.282 [5640.9080] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpjobd
18:56:57.282 [5640.9080] <2> job_connect: SO_KEEPALIVE set on socket 736 for client archivo1
18:56:57.282 [5640.9080] <2> logconnections: BPJOBD CONNECT FROM 192.168.73.16.55878 TO 192.168.73.16.13724
18:56:57.282 [5640.9080] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
18:56:57.282 [5640.9080] <2> job_connect: Connected to the host archivo1 contype 10 jobid <1666> socket <736>
18:56:57.282 [5640.9080] <2> job_connect: Connected on port 55878
18:56:57.282 [5640.9080] <2> get_long: (2) premature end of file (byte 1)
18:56:57.282 [5640.9080] <2> job_monitoring_exex: Failed to get frame type
18:56:57.282 [5640.9080] <2> job_disconnect: Disconnected
18:56:57.282 [5640.9080] <16> write_pl_messages: The following files/folders were not restored:

18:56:57.329 [5640.9080] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
18:56:57.329 [5640.9080] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpjobd
18:56:57.329 [5640.9080] <2> job_connect: SO_KEEPALIVE set on socket 948 for client archivo1
18:56:57.329 [5640.9080] <2> logconnections: BPJOBD CONNECT FROM 192.168.73.16.55880 TO 192.168.73.16.13724
18:56:57.329 [5640.9080] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
18:56:57.329 [5640.9080] <2> job_connect: Connected to the host archivo1 contype 10 jobid <1666> socket <948>
18:56:57.329 [5640.9080] <2> job_connect: Connected on port 55880
18:56:57.329 [5640.9080] <2> get_long: (2) premature end of file (byte 1)
18:56:57.329 [5640.9080] <2> job_monitoring_exex: Failed to get frame type
18:56:57.329 [5640.9080] <2> job_disconnect: Disconnected
18:56:57.329 [5640.9080] <16> write_pl_messages: UTF - /tvfiles/2009/1/CH002_0107_2026.mpg
18:56:57.329 [5640.9080] <2> get_next_file: [5200] received string: (EXIT STATUS 0)
18:56:57.329 [5640.9080] <2> write_pl_messages: beginning close/disconnect of bpcd socket for progress logging
18:56:57.439 [5200.1132] <2> mm_child_done: SIGCHLD: exit=24, pid=5640
18:56:57.439 [5200.1132] <2> send_brm_msg: EXIT Storage05_1249079206 150
18:56:57.439 [5200.1132] <2> bct_clear_active: Set BCTable entry 0 to inactive, ACTIVE_GC count decremented to 0
18:56:57.454 [5200.1132] <4> report_throughput: VBRT 1 5200 4 1 HPULTRIUM5 0024L3 0 0  1140800 (mpxrestore.c.1294)
18:56:57.454 [5200.1132] <2> mpx_read_data: waited for empty buffer 35 times, delayed 45 times
18:56:57.454 [5200.1132] <2> send_brm_msg: MEDIA NOT READY
18:56:57.454 [5200.1132] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HPULTRIUM5, from mpxrestore.c.2734
18:56:57.454 [5200.1132] <2> mpx_waiting_term: waiting for TERMINATE or another START RESTORE
18:56:58.470 [5200.1132] <2> mpx_check_msg_pending: could not open msg pending event, El sistema no puede encontrar el archivo especificado. 
18:56:58.470 [5200.1132] <2> read_brm_msg: TERMINATE
18:56:58.470 [5200.1132] <2> openTpreqFile: tpreq_file: C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HPULTRIUM5, serial_num: HU1139JP8T
18:56:58.470 [5200.1132] <2> get_drive_path: SCSI coordinates {1,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_5-scsi#5&95213a4&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
18:56:58.470 [5200.1132] <2> check_serial_num: serial number match for drive with SCSI coordinates {1,0,0,0}, dos_path \\.\Tape0, drive serial number HU1139JP8T, expected serial number HU1139JP8T
18:56:58.485 [5200.1132] <2> init_tape: \\.\Tape0 (SCSI coordinates {1,0,0,0}) configured with blocksize 0
18:56:58.485 [5200.1132] <2> init_tape: \\.\Tape0 (SCSI coordinates {1,0,0,0}) has compression enabled
18:56:58.485 [5200.1132] <2> io_open: SCSI RESERVE
18:56:58.485 [5200.1132] <2> io_open: file C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HPULTRIUM5 successfully opened (mode 2)
18:56:58.501 [5200.1132] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tpunmount)
18:56:58.501 [5200.1132] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HPULTRIUM5, from bptm.c.18943
18:56:58.501 [5200.1132] <2> drivename_write: Called with mode 1
18:56:58.501 [5200.1132] <2> drivename_unlock: unlocked
18:56:58.501 [5200.1132] <2> drivename_checklock: Called
18:56:58.501 [5200.1132] <2> drivename_lock: lock established
18:56:58.501 [5200.1132] <2> drivename_unlock: unlocked
18:56:58.501 [5200.1132] <2> drivename_close: Called for file HPULTRIUM5
18:56:58.501 [5200.1132] <2> tpunmount: NOP: MEDIA_DONE 0 0 0 0024L3 4000024 180 {29861F82-898D-4634-80A9-42C7B19150AB}
18:56:58.501 [5200.1132] <4> mpx_read_backup: successfully restored 0 of 1 requests, read total of 1140800 Kbytes at 76692.437 Kbytes/sec
18:56:58.501 [5200.1132] <2> get_long: (2) premature end of file (byte 1)
18:56:58.501 [5200.1132] <2> job_monitoring_exex: Failed to get frame type
18:56:58.501 [5200.1132] <2> job_disconnect: Disconnected
18:56:58.501 [5200.1132] <2> bptm: Calling tpunmount for media 0024L3
18:56:58.501 [5200.1132] <2> send_MDS_msg: MEDIA_DONE 0 1666 0 0024L3 4000024 180 {29861F82-898D-4634-80A9-42C7B19150AB}
18:56:58.501 [5200.1132] <2> packageBptmResourceDoneMsg: msg (MEDIA_DONE 0 1666 0 0024L3 4000024 180 {29861F82-898D-4634-80A9-42C7B19150AB})
18:56:58.501 [5200.1132] <2> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid 1666 copyNum 0 mediaId 0024L3 mediaKey 4000024 unloadDelay 180 allocId {29861F82-898D-4634-80A9-42C7B19150AB}
18:56:58.501 [5200.1132] <2> packageBptmResourceDoneMsg: returns 0
18:56:58.517 [5200.1132] <2> JobInst::sendIrmMsg: returning
18:56:58.517 [5200.1132] <2> bptm: EXITING with status 0 <----------