14:56:28.410 [3078] <2> bpbrm main: INITIATING (VERBOSE = 0): version NetBackup 6.5 2010042404
14:56:28.410 [3078] <2> logparams: -backup -S atlbackupmaster -c romepres-sol10-bu -ct 4 -ru root -cl iwhprod_restore -sched Full -bt 1518206187 -dt 0 -st 0 -b romepres-sol10-bu_1518206187 -mediasvr virt-hooey-bu -jobid 3782179 -jobgrpid 3782179 -masterversion 650000 -maxfrag 0 -p 0 -use_ofb -use_otm -jm -secure 1 -kl 4 -rg root -fso -hodb -connect_options 16974338 
14:56:28.444 [3078] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:56:28.444 [3078] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
14:56:28.492 [3078] <2> logconnections: BPDBM CONNECT FROM 10.10.37.92.37074 TO 10.10.36.33.13724
14:56:28.702 [3078] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:56:28.702 [3078] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
14:56:28.703 [3078] <2> logconnections: BPCD CONNECT FROM 10.10.37.92.64095 TO 10.10.36.24.13724
14:56:28.704 [3078] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.50215 TO 10.10.36.24.13724 fd = 8
14:56:28.735 [3078] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:56:28.736 [3078] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-03080518206188735735000000000-_Yaabg
14:56:28.754 [3078] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 7
14:56:28.755 [3078] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 8
14:56:28.792 [3078] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:56:28.792 [3078] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
14:56:28.793 [3078] <2> logconnections: BPCD CONNECT FROM 10.10.37.92.60209 TO 10.10.36.24.13724
14:56:28.794 [3078] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.55016 TO 10.10.36.24.13724 fd = 8
14:56:28.824 [3078] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:56:28.826 [3078] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-03084518206188825110000000000-z0aGbg
14:56:28.837 [3078] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 7
14:56:28.837 [3078] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 8
14:56:28.837 [3078] <2> bpbrm main: received bpcd success message
14:56:28.894 [3078] <2> bpbrm main: from client romepres-sol10-bu: read client start message
14:56:28.894 [3078] <2> bpbrm write_continue_backup: wrote CONTINUE BACKUP on COMM_SOCK <7>
14:56:28.894 [3078] <2> write_file_names: buffering file name '/usr/openv/netbackup/scripts/nbu-restore.sh' for output
14:56:28.894 [3078] <2> write_file_names: successfully wrote buffer to COMM_SOCK
14:56:28.895 [3078] <2> bpbrm main: wrote CONTINUE on COMM_SOCK
14:56:28.895 [3078] <2> bpbrm main: closing COMM_SOCK
14:57:07.465 [3130] <2> bpbrm main: INITIATING (VERBOSE = 0): version NetBackup 6.5 2010042404
14:57:07.466 [3130] <2> logparams: -restore -mpx_restore -S atlbackupmaster -mt 2 -to 0 -mud 180 -mediasvr virt-hooey-bu -masterversion 650000 
14:57:07.468 [3130] <2> bpbrm send_parent_msg: PID of bpbrm = 3130

14:57:07.492 [3130] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:57:07.492 [3130] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
14:57:07.541 [3130] <2> logconnections: BPDBM CONNECT FROM 10.10.37.92.58078 TO 10.10.36.33.13724
14:57:07.701 [3130] <2> db_getCLIENT: db_CLIENTreceive: no entity was found 227
14:57:07.736 [3130] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:57:07.736 [3130] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
14:57:07.737 [3130] <2> logconnections: BPCD CONNECT FROM 10.10.37.92.41886 TO 10.10.37.92.13724
14:57:07.737 [3130] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.41515 TO 10.10.37.92.13724 fd = 8
14:57:07.771 [3130] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:57:07.772 [3130] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-03136518206227771584000000000-7uaaig
14:57:07.774 [3130] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 7
14:57:07.774 [3130] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 8
14:57:07.774 [3130] <2> bpbrm multiplexed_restore: Started media manager using bpcd successfully.
14:57:07.775 [3130] <2> bpbrm multiplexed_restore: calling read_media_msg for media manager PID.
14:57:07.975 [3130] <2> bpbrm read_media_msg: read from media manager: PID of bpxm = 3137
14:57:07.975 [3130] <2> bpbrm read_parent_msg: read from parent START RESTORE -k 0 -c romepres-sol10-bu -hostname romepres-sol10-bu -rclnt romepres-sol10-bu -rclnthostname romepres-sol10-bu -browse_clnt rome_pres-bu -ru oracle -firstblk 0 -cl rome_pres_oracle_iwh -bt 1516498928 -st 2 -secure 1 -b rome_pres-bu_1516498928 -cn 1 -rst 1518206220 -ct 4 -flport 0 -flipc /tmp/vnet-06480518206227537013000000002-rraaQm -restoreid 3782180.001 -jobid 3782180 -job_total 1 -m AL6608 -rg dba -cv -L /usr/openv/netbackup/logs/user_ops/dbext/logs/3108.0.1518206220 -hodb -cfc -clnt_lc_messages C -clnt_lc_time C -clnt_lc_ctype C -clnt_lc_collate C -clnt_lc_numeric C
14:57:07.975 [3130] <2> bpbrm process_start_restore_msg: processing START RESTORE message.
14:57:08.010 [3130] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:57:08.010 [3130] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
14:57:08.011 [3130] <2> logconnections: BPCD CONNECT FROM 10.10.37.92.57337 TO 10.10.36.24.13724
14:57:08.011 [3130] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.34311 TO 10.10.36.24.13724 fd = 10
14:57:08.043 [3130] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:57:08.044 [3130] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-03139518206228043271000000000-lzayig
14:57:08.052 [3130] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 9
14:57:08.052 [3130] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 10
14:57:08.053 [3130] <2> allocate_ft_media: Request FT resources with 1
14:57:08.061 [3130] <2> Orb::init: initializing ORB EMMlib_Orb with: bpbrm -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 /dev/null -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:739)
14:57:08.096 [3130] <2> shouldWeAllocateFT: client romepres-sol10-bu is not a SAN client (2000000)
14:57:08.096 [3130] <2> bpbrm tell_mm_to_start_restore: telling media manager to start.
14:57:08.096 [3130] <2> bpbrm multiplexed_restore: calling read_media_msg for DATASOCKET.
14:57:08.597 [3130] <2> bpbrm read_media_msg: read from media manager: NCB_DATASOCKET rome_pres-bu_1516498928 /tmp/vnet-03142518206228508946000000000-DGaWig;357ac635237c034b5afc84a249c59f84;4;300
14:57:08.597 [3130] <2> bpbrm multiplexed_restore: DATASOCKET = 0 for backup_id rome_pres-bu_1516498928
14:57:08.597 [3130] <2> bpbrm spawn_brm_child: spawning child
14:57:08.600 [3144] <2> bpbrm listen_for_client: HOT_ORACLE_DB_RESTORE
14:57:08.602 [3144] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.43653 TO 10.10.36.24.13724 fd = 9
14:57:08.633 [3144] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:57:08.635 [3144] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-03145518206228633913000000000-zIaijg
14:57:08.636 [3144] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.49833 TO 10.10.36.24.13724 fd = 10
14:57:08.670 [3144] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:57:08.672 [3144] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-03146518206228670892000000000-.Iaqjg
14:57:08.705 [3144] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:57:08.705 [3144] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
14:57:08.706 [3144] <2> logconnections: BPCD CONNECT FROM 10.10.37.92.61669 TO 10.10.36.24.13724
14:57:08.707 [3144] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.59051 TO 10.10.36.24.13724 fd = 12
14:57:08.738 [3144] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:57:08.740 [3144] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-03148518206228739048000000000-dKaGjg
14:57:08.748 [3144] <2> bpbrm send_info_via_progress_file: CLIENT_CMD_SOCK from bpcr = 11
14:57:08.748 [3144] <2> bpbrm send_info_via_progress_file: CLIENT_STAT_SOCK from bpcr = 12
14:57:08.749 [3144] <16> common_signal: Invalid parameters.
14:57:08.753 [3144] <2> bpcr_get_peername_rqst: Server peername length = 25455
14:57:08.799 [3130] <2> bpbrm spawn_brm_child: bpbrm child pid = 3144
14:58:56.182 [3130] <2> bpbrm read_media_msg: read from media manager: CURRENT POSITION AL6608 22
14:58:56.182 [3130] <2> bpbrm send_parent_msg: CURRENT POSITION AL6608 22
14:58:56.182 [3144] <2> bpcr_get_peername_rqst: bpcr couldn't read data from socket
14:58:56.184 [3144] <16> bpbrm send_info_via_progress_file: cannot get server's peername on client romepres-sol10-bu
14:58:56.210 [3144] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:58:56.210 [3144] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpjobd
14:58:56.232 [3130] <2> bpbrm read_parent_msg: read from parent CONTINUE RESTORE
14:58:56.232 [3130] <2> bpbrm tell_mm: sending media manager msg: CONTINUE RESTORE
14:58:56.262 [3144] <2> job_connect: SO_KEEPALIVE set on socket 11 for client atlbackupmaster
14:58:56.262 [3144] <2> logconnections: BPJOBD CONNECT FROM 10.10.37.92.58099 TO 10.10.36.33.13724
14:58:56.262 [3144] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
14:58:56.262 [3144] <2> job_connect: Connected to the host atlbackupmaster contype 10 jobid <3782180> socket <11>
14:58:56.262 [3144] <2> job_connect: Connected on port 58099
14:58:56.311 [3144] <2> get_long: (2) premature end of file (byte 1)
14:58:56.311 [3144] <2> job_monitoring_exex: Failed to get frame type
14:58:56.311 [3144] <2> job_disconnect: Disconnected
14:58:56.335 [3144] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:58:56.335 [3144] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
14:58:56.381 [3144] <2> logconnections: BPDBM CONNECT FROM 10.10.37.92.61841 TO 10.10.36.33.13724
14:58:56.554 [3144] <2> put_short: (10) network write() error: Bad file number (9); socket = 11
14:58:56.554 [3144] <2> bpcr_disconnect_rqst: bpcr protocol error - couldn't send request type
14:58:56.554 [3144] <2> bpbrm send_info_via_progress_file: could not disconnect from bpcd on romepres-sol10-bu
14:58:56.554 [3144] <2> bpbrm send_info_via_progress_file: could not close CLIENT_CMD_SOCK, %s (9)
14:58:56.554 [3144] <16> bpbrm listen_for_client: listen for client protocol error - couldn't write necessary information on /usr/openv/netbackup/logs/user_ops/dbext/logs/3108.0.1518206220
14:58:56.578 [3144] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:58:56.578 [3144] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpjobd
14:58:56.622 [3144] <2> job_connect: SO_KEEPALIVE set on socket 11 for client atlbackupmaster
14:58:56.622 [3144] <2> logconnections: BPJOBD CONNECT FROM 10.10.37.92.52902 TO 10.10.36.33.13724
14:58:56.622 [3144] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
14:58:56.622 [3144] <2> job_connect: Connected to the host atlbackupmaster contype 10 jobid <3782180> socket <11>
14:58:56.622 [3144] <2> job_connect: Connected on port 52902
14:58:56.671 [3144] <2> get_long: (2) premature end of file (byte 1)
14:58:56.671 [3144] <2> job_monitoring_exex: Failed to get frame type
14:58:56.671 [3144] <2> job_disconnect: Disconnected
14:58:56.695 [3144] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:58:56.695 [3144] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
14:58:56.741 [3144] <2> logconnections: BPDBM CONNECT FROM 10.10.37.92.36455 TO 10.10.36.33.13724
14:58:56.929 [3130] <2> bpbrm brm_sigcld: SIGCLD caught by bpbrm
14:58:56.930 [3130] <2> bpbrm brm_sigcld: bpbrm child 3144 exit_status = 25, signal_status = 0
14:58:56.930 [3130] <2> bpbrm brm_sigcld: child 3144 exited with status 25: cannot connect on socket
14:58:56.930 [3130] <2> bpbrm send_status_to_parent: bpbrm child is done, but the media manager child is not.
14:58:56.930 [3130] <2> bpbrm tell_mm: sending media manager msg: STOP RESTORE rome_pres-bu_1516498928
14:58:57.431 [3130] <2> bpbrm read_media_msg: read from media manager: MEDIA READY
14:59:08.932 [3130] <2> bpbrm read_media_msg: read from media manager: MEDIA NOT READY
14:59:08.933 [3130] <2> bpbrm read_media_msg: read from media manager: EXIT rome_pres-bu_1516498928 25
14:59:08.933 [3130] <2> bpbrm process_media_msg: media manager for backup id rome_pres-bu_1516498928 exited with status 25: cannot connect on socket
14:59:08.933 [3130] <2> bpbrm send_status_to_parent: EXIT rome_pres-bu_1516498928 25 sent to parent process.
14:59:08.983 [3130] <2> bpbrm read_parent_msg: read from parent TERMINATE
14:59:08.983 [3130] <2> bpbrm tell_mm: sending media manager msg: TERMINATE
15:09:53.032 [3078] <2> bpbrm check_for_terminate: process killed by signal 1
15:09:53.032 [3078] <2> bpbrm kill_child_process: start
15:09:53.033 [3078] <2> bpbrm Exit: attempting to send mail to root on romepres-sol10-bu
15:09:53.079 [3078] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
15:09:53.079 [3078] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
15:09:53.081 [3078] <2> logconnections: BPCD CONNECT FROM 10.10.37.92.47761 TO 10.10.36.24.13724
15:09:53.081 [3078] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.49874 TO 10.10.36.24.13724 fd = 9
15:09:53.116 [3078] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
15:09:53.117 [3078] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-03440518206993116285000000000-ClaaUg
15:09:53.125 [3078] <2> bpbrm Exit: OUT_SOCK from bpcr = 7
15:09:53.125 [3078] <2> bpbrm Exit: IN_SOCK from bpcr = 9
15:09:53.125 [3078] <2> bpcr_get_version_rqst: bpcd version: 06540000
15:09:53.125 [3078] <2> bpcr_get_version_rqst: bpcd version: 06540000
15:09:53.132 [3078] <2> bpcr_get_version_rqst: bpcd version: 06540000
15:09:53.138 [3078] <2> bpbrm Exit: client backup EXIT STATUS 150: termination requested by administrator