14:24:05.638 [2408] <2> bpbrm main: INITIATING (VERBOSE = 0): version NetBackup 6.5 2010042404
14:24:05.638 [2408] <2> logparams: -backup -S atlbackupmaster -c romepres-sol10-bu -ct 4 -ru root -cl iwhprod_restore -sched Full -bt 1518204244 -dt 0 -st 0 -b romepres-sol10-bu_1518204244 -mediasvr virt-hooey-bu -jobid 3782173 -jobgrpid 3782173 -masterversion 650000 -maxfrag 0 -p 0 -use_ofb -use_otm -jm -secure 1 -kl 4 -rg root -fso -hodb -connect_options 16974338 
14:24:05.675 [2408] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:24:05.675 [2408] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
14:24:05.717 [2408] <2> logconnections: BPDBM CONNECT FROM 10.10.37.92.43817 TO 10.10.36.33.13724
14:24:05.932 [2408] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:24:05.932 [2408] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
14:24:05.932 [2408] <2> logconnections: BPCD CONNECT FROM 10.10.37.92.46668 TO 10.10.36.24.13724
14:24:05.933 [2408] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.59800 TO 10.10.36.24.13724 fd = 8
14:24:05.965 [2408] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:24:05.966 [2408] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-02410518204245965438000000000-nFaqTe
14:24:05.982 [2408] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 7
14:24:05.982 [2408] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 8
14:24:06.020 [2408] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:24:06.020 [2408] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
14:24:06.021 [2408] <2> logconnections: BPCD CONNECT FROM 10.10.37.92.49198 TO 10.10.36.24.13724
14:24:06.021 [2408] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.56441 TO 10.10.36.24.13724 fd = 8
14:24:06.052 [2408] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:24:06.054 [2408] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-02414518204246052894000000000-KGaWTe
14:24:06.066 [2408] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 7
14:24:06.066 [2408] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 8
14:24:06.066 [2408] <2> bpbrm main: received bpcd success message
14:24:06.123 [2408] <2> bpbrm main: from client romepres-sol10-bu: read client start message
14:24:06.124 [2408] <2> bpbrm write_continue_backup: wrote CONTINUE BACKUP on COMM_SOCK <7>
14:24:06.124 [2408] <2> write_file_names: buffering file name '/usr/openv/netbackup/scripts/nbu-restore.sh' for output
14:24:06.124 [2408] <2> write_file_names: successfully wrote buffer to COMM_SOCK
14:24:06.124 [2408] <2> bpbrm main: wrote CONTINUE on COMM_SOCK
14:24:06.124 [2408] <2> bpbrm main: closing COMM_SOCK
14:24:43.761 [2461] <2> bpbrm main: INITIATING (VERBOSE = 0): version NetBackup 6.5 2010042404
14:24:43.761 [2461] <2> logparams: -restore -mpx_restore -S atlbackupmaster -mt 2 -to 0 -mud 180 -mediasvr virt-hooey-bu -masterversion 650000 
14:24:43.763 [2461] <2> bpbrm send_parent_msg: PID of bpbrm = 2461

14:24:43.787 [2461] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:24:43.787 [2461] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
14:24:43.837 [2461] <2> logconnections: BPDBM CONNECT FROM 10.10.37.92.58414 TO 10.10.36.33.13724
14:24:43.997 [2461] <2> db_getCLIENT: db_CLIENTreceive: no entity was found 227
14:24:44.042 [2461] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:24:44.042 [2461] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
14:24:44.043 [2461] <2> logconnections: BPCD CONNECT FROM 10.10.37.92.36352 TO 10.10.37.92.13724
14:24:44.044 [2461] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.55472 TO 10.10.37.92.13724 fd = 8
14:24:44.081 [2461] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:24:44.082 [2461] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-02467518204284081639000000000-XYay0e
14:24:44.084 [2461] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 7
14:24:44.084 [2461] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 8
14:24:44.084 [2461] <2> bpbrm multiplexed_restore: Started media manager using bpcd successfully.
14:24:44.085 [2461] <2> bpbrm multiplexed_restore: calling read_media_msg for media manager PID.
14:24:44.285 [2461] <2> bpbrm read_media_msg: read from media manager: PID of bpxm = 2468
14:24:44.285 [2461] <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 1518204277 -ct 4 -flport 0 -flipc /tmp/vnet-02067518204283837062000000002-9Uayce -restoreid 3782174.001 -jobid 3782174 -job_total 1 -m AL6608 -rg dba -cv -L /usr/openv/netbackup/logs/user_ops/dbext/logs/2440.0.1518204277 -hodb -cfc -clnt_lc_messages C -clnt_lc_time C -clnt_lc_ctype C -clnt_lc_collate C -clnt_lc_numeric C
14:24:44.285 [2461] <2> bpbrm process_start_restore_msg: processing START RESTORE message.
14:24:44.318 [2461] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:24:44.319 [2461] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
14:24:44.319 [2461] <2> logconnections: BPCD CONNECT FROM 10.10.37.92.34650 TO 10.10.36.24.13724
14:24:44.321 [2461] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.54110 TO 10.10.36.24.13724 fd = 10
14:24:44.353 [2461] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:24:44.355 [2461] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-02470518204284353933000000000-b3aW0e
14:24:44.362 [2461] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 9
14:24:44.362 [2461] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 10
14:24:44.362 [2461] <2> allocate_ft_media: Request FT resources with 1
14:24:44.370 [2461] <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:24:44.405 [2461] <2> shouldWeAllocateFT: client romepres-sol10-bu is not a SAN client (2000000)
14:24:44.405 [2461] <2> bpbrm tell_mm_to_start_restore: telling media manager to start.
14:24:44.405 [2461] <2> bpbrm multiplexed_restore: calling read_media_msg for DATASOCKET.
14:24:44.905 [2461] <2> bpbrm read_media_msg: read from media manager: NCB_DATASOCKET rome_pres-bu_1516498928 /tmp/vnet-02473518204284878662000000000-o_ai1e;708ac7c97256a4ad0ac1db80d79dbdac;4;300
14:24:44.905 [2461] <2> bpbrm multiplexed_restore: DATASOCKET = 0 for backup_id rome_pres-bu_1516498928
14:24:44.906 [2461] <2> bpbrm spawn_brm_child: spawning child
14:24:44.909 [2475] <2> bpbrm listen_for_client: HOT_ORACLE_DB_RESTORE
14:24:44.910 [2475] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.50245 TO 10.10.36.24.13724 fd = 9
14:24:44.943 [2475] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:24:44.945 [2475] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-02476518204284943834000000000-paaG1e
14:24:44.946 [2475] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.44732 TO 10.10.36.24.13724 fd = 10
14:24:44.980 [2475] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:24:44.982 [2475] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-02477518204284981175000000000-1aaO1e
14:24:45.033 [2475] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:24:45.033 [2475] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
14:24:45.034 [2475] <2> logconnections: BPCD CONNECT FROM 10.10.37.92.37113 TO 10.10.36.24.13724
14:24:45.035 [2475] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.34924 TO 10.10.36.24.13724 fd = 12
14:24:45.069 [2475] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:24:45.071 [2475] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-02479518204285070052000000000-oca41e
14:24:45.078 [2475] <2> bpbrm send_info_via_progress_file: CLIENT_CMD_SOCK from bpcr = 11
14:24:45.078 [2475] <2> bpbrm send_info_via_progress_file: CLIENT_STAT_SOCK from bpcr = 12
14:24:45.079 [2475] <16> common_signal: Invalid parameters.
14:24:45.084 [2475] <2> bpcr_get_peername_rqst: Server peername length = 25455
14:24:45.108 [2461] <2> bpbrm spawn_brm_child: bpbrm child pid = 2475
14:26:29.389 [2461] <2> bpbrm read_media_msg: read from media manager: CURRENT POSITION AL6608 22
14:26:29.389 [2461] <2> bpbrm send_parent_msg: CURRENT POSITION AL6608 22
14:26:29.389 [2475] <2> bpcr_get_peername_rqst: bpcr couldn't read data from socket
14:26:29.391 [2475] <16> bpbrm send_info_via_progress_file: cannot get server's peername on client romepres-sol10-bu
14:26:29.417 [2475] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:26:29.417 [2475] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpjobd
14:26:29.439 [2461] <2> bpbrm read_parent_msg: read from parent CONTINUE RESTORE
14:26:29.439 [2461] <2> bpbrm tell_mm: sending media manager msg: CONTINUE RESTORE
14:26:29.467 [2475] <2> job_connect: SO_KEEPALIVE set on socket 11 for client atlbackupmaster
14:26:29.467 [2475] <2> logconnections: BPJOBD CONNECT FROM 10.10.37.92.61552 TO 10.10.36.33.13724
14:26:29.468 [2475] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
14:26:29.468 [2475] <2> job_connect: Connected to the host atlbackupmaster contype 10 jobid <3782174> socket <11>
14:26:29.468 [2475] <2> job_connect: Connected on port 61552
14:26:29.516 [2475] <2> get_long: (2) premature end of file (byte 1)
14:26:29.516 [2475] <2> job_monitoring_exex: Failed to get frame type
14:26:29.516 [2475] <2> job_disconnect: Disconnected
14:26:29.540 [2475] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:26:29.540 [2475] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
14:26:29.587 [2475] <2> logconnections: BPDBM CONNECT FROM 10.10.37.92.39947 TO 10.10.36.33.13724
14:26:29.749 [2475] <2> put_short: (10) network write() error: Bad file number (9); socket = 11
14:26:29.749 [2475] <2> bpcr_disconnect_rqst: bpcr protocol error - couldn't send request type
14:26:29.749 [2475] <2> bpbrm send_info_via_progress_file: could not disconnect from bpcd on romepres-sol10-bu
14:26:29.749 [2475] <2> bpbrm send_info_via_progress_file: could not close CLIENT_CMD_SOCK, %s (9)
14:26:29.749 [2475] <16> bpbrm listen_for_client: listen for client protocol error - couldn't write necessary information on /usr/openv/netbackup/logs/user_ops/dbext/logs/2440.0.1518204277
14:26:29.774 [2475] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:26:29.774 [2475] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpjobd
14:26:29.817 [2475] <2> job_connect: SO_KEEPALIVE set on socket 11 for client atlbackupmaster
14:26:29.817 [2475] <2> logconnections: BPJOBD CONNECT FROM 10.10.37.92.47340 TO 10.10.36.33.13724
14:26:29.817 [2475] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
14:26:29.818 [2475] <2> job_connect: Connected to the host atlbackupmaster contype 10 jobid <3782174> socket <11>
14:26:29.818 [2475] <2> job_connect: Connected on port 47340
14:26:29.866 [2475] <2> get_long: (2) premature end of file (byte 1)
14:26:29.866 [2475] <2> job_monitoring_exex: Failed to get frame type
14:26:29.866 [2475] <2> job_disconnect: Disconnected
14:26:29.890 [2475] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:26:29.890 [2475] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
14:26:29.937 [2475] <2> logconnections: BPDBM CONNECT FROM 10.10.37.92.55509 TO 10.10.36.33.13724
14:26:30.115 [2461] <2> bpbrm brm_sigcld: SIGCLD caught by bpbrm
14:26:30.115 [2461] <2> bpbrm brm_sigcld: bpbrm child 2475 exit_status = 25, signal_status = 0
14:26:30.115 [2461] <2> bpbrm brm_sigcld: child 2475 exited with status 25: cannot connect on socket
14:26:30.115 [2461] <2> bpbrm send_status_to_parent: bpbrm child is done, but the media manager child is not.
14:26:30.115 [2461] <2> bpbrm tell_mm: sending media manager msg: STOP RESTORE rome_pres-bu_1516498928
14:26:30.615 [2461] <2> bpbrm read_media_msg: read from media manager: MEDIA READY
14:26:45.618 [2461] <2> bpbrm read_media_msg: read from media manager: MEDIA NOT READY
14:26:45.618 [2461] <2> bpbrm read_media_msg: read from media manager: EXIT rome_pres-bu_1516498928 25
14:26:45.618 [2461] <2> bpbrm process_media_msg: media manager for backup id rome_pres-bu_1516498928 exited with status 25: cannot connect on socket
14:26:45.618 [2461] <2> bpbrm send_status_to_parent: EXIT rome_pres-bu_1516498928 25 sent to parent process.
14:26:45.719 [2461] <2> bpbrm read_parent_msg: read from parent TERMINATE
14:26:45.719 [2461] <2> bpbrm tell_mm: sending media manager msg: TERMINATE
14:28:20.488 [2408] <2> bpbrm check_for_terminate: process killed by signal 1
14:28:20.489 [2408] <2> bpbrm kill_child_process: start
14:28:20.489 [2408] <2> bpbrm Exit: attempting to send mail to root on romepres-sol10-bu
14:28:20.521 [2408] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:28:20.521 [2408] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpcd
14:28:20.521 [2408] <2> logconnections: BPCD CONNECT FROM 10.10.37.92.46237 TO 10.10.36.24.13724
14:28:20.522 [2408] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.182: msg: VNETD CONNECT FROM 10.10.37.92.52951 TO 10.10.36.24.13724 fd = 9
14:28:20.557 [2408] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.535: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
14:28:20.559 [2408] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.552: ipc_string: /tmp/vnet-02559518204500558129000000000-oPa4_e
14:28:20.566 [2408] <2> bpbrm Exit: OUT_SOCK from bpcr = 7
14:28:20.566 [2408] <2> bpbrm Exit: IN_SOCK from bpcr = 9
14:28:20.567 [2408] <2> bpcr_get_version_rqst: bpcd version: 06540000
14:28:20.567 [2408] <2> bpcr_get_version_rqst: bpcd version: 06540000
14:28:20.573 [2408] <2> bpcr_get_version_rqst: bpcd version: 06540000
14:28:20.579 [2408] <2> bpbrm Exit: client backup EXIT STATUS 150: termination requested by administrator