14:21:37.354 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.357 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:37.357 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.360 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:37.360 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.363 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:37.363 [23747] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1 14:21:37.364 [23747] <2> vnet_pbxConnect: pbxConnectEx Succeeded 14:21:37.364 [23747] <2> do_pbx_service: [vnet_connect.c:2116] via PBX bprd CONNECT FROM 172.20.22.232.34586 TO 172.20.22.231.1556 fd = 4 14:21:37.364 [23747] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 172.20.22.232.34586 TO 172.20.22.231.1556 fd = 4 14:21:37.364 [23747] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mstr-nbkp-srv 172.20.22.231 bprd VIA pbx 14:21:37.365 [23747] <2> logconnections: BPRD CONNECT FROM 172.20.22.232.34586 TO 172.20.22.231.1556 fd = 4 14:21:37.365 [23747] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 14:21:37.408 [23747] <2> brm_update_local_resiliency: changed = 0 14:21:37.414 [23747] <2> bpbrm send_parent_msg: PID of bpbrm = 23747 14:21:37.414 [23747] <2> bpbrm start_bpcd_stat: bpbrm.c.21911: bpcd_client: media-nbkp-srv1 14:21:37.415 [23747] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mstr-nbkp-srv, query type 223 14:21:37.415 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.418 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:37.418 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.421 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:37.421 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.424 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:37.424 [23747] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1 14:21:37.425 [23747] <2> vnet_pbxConnect: pbxConnectEx Succeeded 14:21:37.425 [23747] <2> do_pbx_service: [vnet_connect.c:2116] via PBX bpdbm CONNECT FROM 172.20.22.232.49035 TO 172.20.22.231.1556 fd = 4 14:21:37.425 [23747] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 172.20.22.232.49035 TO 172.20.22.231.1556 fd = 4 14:21:37.425 [23747] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mstr-nbkp-srv 172.20.22.231 bpdbm VIA pbx 14:21:37.425 [23747] <2> logconnections: BPDBM CONNECT FROM 172.20.22.232.49035 TO 172.20.22.231.1556 fd = 4 14:21:37.425 [23747] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 14:21:37.429 [23747] <2> db_CLIENTsend: reset client protocol version from 0 to 8 14:21:37.429 [23747] <2> db_CLIENTsend: prec->offline=0 14:21:37.429 [23747] <2> db_CLIENTsend: prec->online_at=0 14:21:37.429 [23747] <2> db_CLIENTsend: prec->offline_at=0 14:21:37.429 [23747] <2> db_CLIENTsend: sending 56 bytes 14:21:37.469 [23747] <2> db_getCLIENT: db_CLIENTreceive: no entity was found 227 14:21:37.469 [23747] <2> ConnectToBPCD: db_getCLIENT(media-nbkp-srv1) failed: 227 14:21:37.470 [23747] <2> local_bpcr_connect: bpcr.c.278: connect_opts = 0x01030202 connect_opts2 = 0x01020001 14:21:37.470 [23747] <2> local_bpcr_connect: bpcr.c.285: connect_opts = 0x01020001 14:21:37.470 [23747] <2> local_bpcr_connect: bpcr.c.324: daemon_port_type = 2 14:21:37.470 [23747] <2> vnet_in_resilient_network: [vnet_addrinfo.c:8740] ignoring local host 0 0x0 14:21:37.470 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.470 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4776] Local [strong] check, using interface ANY 14:21:37.470 [23747] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1 14:21:37.470 [23747] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 127.0.0.1.45695 TO 127.0.0.1.13782 fd = 4 14:21:37.471 [23747] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO media-nbkp-srv1 127.0.0.1 bpcd 14:21:37.472 [23747] <2> logconnections: BPCD CONNECT FROM 127.0.0.1.45695 TO 127.0.0.1.13782 fd = 4 14:21:37.473 [23747] <2> vnet_in_resilient_network: [vnet_addrinfo.c:8740] ignoring local host 0 0x0 14:21:37.488 [23747] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 4 14:21:37.488 [23747] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 7 14:21:37.488 [23747] <2> bpbrm multiplexed_restore: Started media manager using bpcd successfully. 14:21:37.489 [23747] <2> bpbrm multiplexed_restore: calling read_media_msg for media manager PID. 14:21:37.789 [23747] <2> bpbrm read_media_msg: read from media manager: PID of bpxm = 23751 14:21:37.790 [23747] <2> bpbrm process_start_restore_msg: processing START RESTORE message. 14:21:37.790 [23747] <2> verify_client: bpbrm.c.37610: *connect_opts: 16974338 16974338 0x01030202 14:21:37.790 [23747] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mstr-nbkp-srv, query type 223 14:21:37.791 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.794 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:37.794 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.797 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:37.797 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.800 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:37.800 [23747] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1 14:21:37.801 [23747] <2> vnet_pbxConnect: pbxConnectEx Succeeded 14:21:37.801 [23747] <2> do_pbx_service: [vnet_connect.c:2116] via PBX bpdbm CONNECT FROM 172.20.22.232.46126 TO 172.20.22.231.1556 fd = 5 14:21:37.801 [23747] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 172.20.22.232.46126 TO 172.20.22.231.1556 fd = 5 14:21:37.801 [23747] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mstr-nbkp-srv 172.20.22.231 bpdbm VIA pbx 14:21:37.802 [23747] <2> logconnections: BPDBM CONNECT FROM 172.20.22.232.46126 TO 172.20.22.231.1556 fd = 5 14:21:37.802 [23747] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 14:21:37.804 [23747] <2> db_CLIENTsend: reset client protocol version from 0 to 8 14:21:37.804 [23747] <2> db_CLIENTsend: prec->offline=0 14:21:37.804 [23747] <2> db_CLIENTsend: prec->online_at=0 14:21:37.804 [23747] <2> db_CLIENTsend: prec->offline_at=0 14:21:37.804 [23747] <2> db_CLIENTsend: sending 49 bytes 14:21:37.845 [23747] <2> db_CLIENTreceive: clientrec_protocol_version=8 14:21:37.845 [23747] <2> db_CLIENTreceive: num_fi_info=0 14:21:37.845 [23747] <2> db_CLIENTreceive: num_exdb_info=0 14:21:37.845 [23747] <2> db_CLIENTreceive: offline=0 14:21:37.845 [23747] <2> db_CLIENTreceive: online_at=0 14:21:37.845 [23747] <2> db_CLIENTreceive: offline_at=0 14:21:37.845 [23747] <2> db_end: Need to collect reply 14:21:37.845 [23747] <2> db_freeSEC_INFO: pinfo is NULL 14:21:37.845 [23747] <2> db_freeEXDB_INFO: ? 14:21:37.845 [23747] <2> db_freeEXDB_INFO: plist is NULL 14:21:37.846 [23747] <2> bpbrm start_bpcd_stat: bpbrm.c.21911: bpcd_client: SAPBISBX 14:21:37.846 [23747] <2> bpbrm start_bpcd_stat: bpbrm.c.21914: bpcd_client_hostname: SAPBISBX 14:21:37.846 [23747] <2> local_bpcr_connect: bpcr.c.278: connect_opts = 0x01000100 connect_opts2 = 0x01000100 14:21:37.846 [23747] <2> local_bpcr_connect: bpcr.c.285: connect_opts = 0x01000100 14:21:37.846 [23747] <2> local_bpcr_connect: bpcr.c.324: daemon_port_type = 0 14:21:37.847 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.850 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:37.850 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.853 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:37.853 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.856 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:37.856 [23747] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1 14:21:37.863 [23747] <2> vnet_pbxConnect: pbxConnectEx Succeeded 14:21:37.863 [23747] <2> do_pbx_service: [vnet_connect.c:2116] via PBX bpcd CONNECT FROM 172.20.22.232.37061 TO 172.20.44.72.1556 fd = 5 14:21:37.863 [23747] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 172.20.22.232.37061 TO 172.20.44.72.1556 fd = 5 14:21:37.863 [23747] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO SAPBISBX 172.20.44.72 bpcd VIA pbx 14:21:37.864 [23747] <2> logconnections: BPCD CONNECT FROM 172.20.22.232.37061 TO 172.20.44.72.1556 fd = 5 14:21:37.864 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.866 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:37.866 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:37.868 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:37.868 [23747] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1 14:21:37.874 [23747] <2> vnet_pbxConnect: pbxConnectEx Succeeded 14:21:37.943 [23747] <8> do_pbx_service: [vnet_connect.c:2108] via PBX VNETD CONNECT FROM 172.20.22.232.39049 TO 172.20.44.72.1556 fd = 8 14:21:37.943 [23747] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 172.20.22.232.39049 TO 172.20.44.72.1556 fd = 8 14:21:37.943 [23747] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO 172.20.44.72 172.20.44.72 vnetd VIA pbx 14:21:37.943 [23747] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:443] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa 14:21:38.002 [23747] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:460] ipc_string 50264 14:21:38.046 [23747] <2> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:471] hash_str1 ccb38f72a02af8f5121d8931b87b272b 14:21:38.103 [23747] <2> bpcr_get_hostname_rqst: Server hostname length = 8 14:21:38.104 [23747] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 5 14:21:38.104 [23747] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 8 14:21:38.104 [23747] <2> verify_client: bpbrm.c.37933: hostname: media-nbkp-srv1 14:21:38.104 [23747] <2> verify_client: bpbrm.c.37934: is_on: 0 0 0x00000000 14:21:38.107 [23747] <2> bpcr_get_version_rqst: bpcd version: 07720000 14:21:38.109 [23747] <2> verify_client: bpbrm.c.37937: bpcr_update_resiliency : 0 0 0x00000000 14:21:38.111 [23747] <2> verify_client: bpbrm.c.37960: *connect_opts: 16843008 16843008 0x01010100 14:21:38.111 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.115 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.115 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.118 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.118 [23747] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.121 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.121 [23747] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1 14:21:38.122 [23747] <2> vnet_pbxConnect: pbxConnectEx Succeeded 14:21:38.122 [23747] <2> do_pbx_service: [vnet_connect.c:2116] via PBX bpjobd CONNECT FROM 172.20.22.232.49662 TO 172.20.22.231.1556 fd = 5 14:21:38.122 [23747] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 172.20.22.232.49662 TO 172.20.22.231.1556 fd = 5 14:21:38.122 [23747] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mstr-nbkp-srv 172.20.22.231 bpjobd VIA pbx 14:21:38.122 [23747] <2> job_connect: SO_KEEPALIVE set on socket 5 for client mstr-nbkp-srv 14:21:38.122 [23747] <2> logconnections: BPJOBD CONNECT FROM 172.20.22.232.49662 TO 172.20.22.231.1556 fd = 5 14:21:38.122 [23747] <2> job_authenticate_connection: ignoring VxSS authentication check for now... 14:21:38.123 [23747] <2> job_connect: Connected to the host mstr-nbkp-srv contype 53 jobid <670158> socket <5> 14:21:38.123 [23747] <2> job_connect: Connected on port 49662 14:21:38.123 [23747] <2> set_job_details: Tfile (670158): LOG 1476615098 4 bpbrm 23747 SAPBISBX is the host to restore to 14:21:38.123 [23747] <2> send_job_file: job ID 670158, ftype = 3 msg len = 64, msg = LOG 1476615098 4 bpbrm 23747 SAPBISBX is the host to restore to 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: backup_id = SAPBISBX_1476613742 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: bkup_time = 1476613742 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: job_id = 670158 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: policy = test-for-sybase-db 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: client = SAPBISBX 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: client_hostname = SAPBISBX 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: requesting_group = root 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: requesting_user = root 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: secure_clnt = 1 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: sched_type = 2 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: requesting_client = SAPBISBX 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: requesting_client_hostname = SAPBISBX 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: connect_from_client = 1 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: connect_opts = 16843008 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: clnt_lc_messages = en 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: clnt_lc_time = en 14:21:38.123 [23747] <2> bpbrm process_start_restore_msg: clnt_lc_ctype = en 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: clnt_lc_collate = en 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: clnt_lc_numeric = en 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: copy_number = 1 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: client_type = 7 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: cverbose = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: encrypted = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: first_blk_no = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: file_list_portnum = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: file_list_ipc = /usr/openv/var/tmp/vnet-13688476615051212287000001297-sMDifZ 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: hot_backtrack_db = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: hot_informix_db = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: hot_oracle_db = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: hot_sybase_db = 1 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: hot_sharepoint_db = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: hot_exchange_db = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: hot_lotus_notes_db = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: hot_sql_server_db = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: hot_ncr_teradata_db = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: hot_sap_db = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: hot_db2_db = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: hot_extensible_db = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: keep = 1 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: SAN Client = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: Client Direct = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: Client Direct Restore = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: Ignore Client Direct = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: OST Proxy = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: path = NULL 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: rename_linktos = 1 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: rename_hard_linktos = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: rename_soft_linktos = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: rest_start_time = 1476615127 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: compress = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: shm_restore = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: job_total = 1 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: commit = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: dir_byte_count = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: temp_dir = NULL 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: mount_database = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: spsredir_path = NULL 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: spsredir_webserver = NULL 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: granular_restore = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: selected_restore_file_list = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: skip_restore_to_symlink_dir = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: unlink_on_overwrite = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: ckpt_time = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: dont_restore_security = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: priority = -1 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: spsrestoreoptions = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: vhd_file_name = NONE 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: vhd_type = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: vhd_disk_size = 0 14:21:38.124 [23747] <2> bpbrm process_start_restore_msg: vhd_delete_on_failure = 0 14:21:38.124 [23747] <2> allocate_ft_media: Request FT resources with 1 14:21:38.133 [23747] <2> Orb::setDebugLevelFromVxul: Orb logging configuration level set to 0(Orb.cpp:2261) 14:21:38.133 [23747] <2> Orb::init: checking if NBAC is enabled(Orb.cpp:508) 14:21:38.133 [23747] <2> BpConfigHolder::BpConfigHolder: +++ ENTERING +++ : obj = 0x2318648 (../BpConf.cpp:34) 14:21:38.133 [23747] <2> BpConfigHolder::reload: +++ ENTERING +++ : obj = 0x2318648 (../BpConf.cpp:46) 14:21:38.136 [23747] <2> BpConfigHolder::reload: --- EXITING --- : obj = 0x2318648 (../BpConf.cpp:46) 14:21:38.136 [23747] <2> BpConfigHolder::BpConfigHolder: --- EXITING --- : obj = 0x2318648 (../BpConf.cpp:34) 14:21:38.145 [23747] <2> EndpointSelectorFactory::EndpointSelectorFactory: +++ ENTERING +++ : obj = 0x232c7b0 (../Endpoint_Selector.cpp:1758) 14:21:38.145 [23747] <2> EndpointSelector_R2::EndpointSelector_R2: +++ ENTERING +++ : obj = 0x232c810 (../Endpoint_Selector.cpp:339) 14:21:38.145 [23747] <2> EndpointSelector_R2::updateConfMembers: epsr2: bp.conf LastUpd=1476615067 bp.conf LastLook=0(Endpoint_Selector.cpp:380) 14:21:38.145 [23747] <2> EndpointSelector_R2::updateConfMembers: epsr2: bp.conf changed since last look, reloading(Endpoint_Selector.cpp:384) 14:21:38.145 [23747] <2> EndpointSelector_R2::updateConfMembers: epsr2: tardy lookup log time value set to 5 seconds(Endpoint_Selector.cpp:419) 14:21:38.145 [23747] <2> EndpointSelector_R2::updateConfMembers: epsr2: USE_VXSS = PROHIBITED(Endpoint_Selector.cpp:430) 14:21:38.145 [23747] <2> EndpointSelector_R2::EndpointSelector_R2: --- EXITING --- : obj = 0x232c810 (../Endpoint_Selector.cpp:339) 14:21:38.145 [23747] <2> EndpointSelectorFactory::EndpointSelectorFactory: Endpoint Selector model: 7.1 Flags: 0(Endpoint_Selector.cpp:1805) 14:21:38.145 [23747] <2> EndpointSelectorFactory::EndpointSelectorFactory: --- EXITING --- : obj = 0x232c7b0 (../Endpoint_Selector.cpp:1758) 14:21:38.145 [23747] <2> InsecureEndpointSelectorFactory::InsecureEndpointSelectorFactory: +++ ENTERING +++ : obj = 0x232c970 (../Endpoint_Selector.cpp:1852) 14:21:38.145 [23747] <2> EndpointSelector_R2::EndpointSelector_R2: +++ ENTERING +++ : obj = 0x232c9d0 (../Endpoint_Selector.cpp:339) 14:21:38.145 [23747] <2> EndpointSelector_R2::updateConfMembers: epsr2: bp.conf LastUpd=1476615067 bp.conf LastLook=0(Endpoint_Selector.cpp:380) 14:21:38.145 [23747] <2> EndpointSelector_R2::updateConfMembers: epsr2: bp.conf changed since last look, reloading(Endpoint_Selector.cpp:384) 14:21:38.145 [23747] <2> EndpointSelector_R2::updateConfMembers: epsr2: tardy lookup log time value set to 5 seconds(Endpoint_Selector.cpp:419) 14:21:38.145 [23747] <2> EndpointSelector_R2::updateConfMembers: epsr2: USE_VXSS = PROHIBITED(Endpoint_Selector.cpp:430) 14:21:38.145 [23747] <2> EndpointSelector_R2::EndpointSelector_R2: --- EXITING --- : obj = 0x232c9d0 (../Endpoint_Selector.cpp:339) 14:21:38.145 [23747] <2> InsecureEndpointSelectorFactory::InsecureEndpointSelectorFactory: Endpoint Selector model: 7.1 Flags: 0 [Ignoring BPCONF server list](Endpoint_Selector.cpp:1900) 14:21:38.145 [23747] <2> InsecureEndpointSelectorFactory::InsecureEndpointSelectorFactory: --- EXITING --- : obj = 0x232c970 (../Endpoint_Selector.cpp:1852) 14:21:38.145 [23747] <2> checkService: found service: UTF16_BOM_Factory(Orb.cpp:484) 14:21:38.145 [23747] <2> checkService: found service: UTF8-Latin1_Factory(Orb.cpp:484) 14:21:38.145 [23747] <2> LogMaxFileNum: current max fileno: 1024, max fileno hard limit: 1024(SetMaxFileNum.cpp:113) 14:21:38.145 [23747] <2> Orb::getConfig: found service entry: name = veritas_pbx port = 1556 proto = tcp(Orb.cpp:402) 14:21:38.145 [23747] <2> Orb::getConfig: cluster_name and required_interface not defined, using ANY(Orb.cpp:454) 14:21:38.145 [23747] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:594) 14:21:38.145 [23747] <2> Orb::init: initializing ORB with: bpbrm -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'"(Orb.cpp:640) 14:21:38.145 [23747] <2> Orb::init: added args has value of: (Orb.cpp:770) 14:21:38.147 [23747] <2> Orb::init: initializing ORB EMMlib_Orb with: bpbrm -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 /dev/null -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:825) 14:21:38.148 [23747] <2> NBEvaluatorFactory::init: +++ ENTERING +++ : obj = 0x232c3f0 (../SecureEvaluator.cpp:498) 14:21:38.148 [23747] <2> NBEvaluatorFactory::init: --- EXITING --- : obj = 0x232c3f0 (../SecureEvaluator.cpp:498) 14:21:38.149 [23747] <2> NBOrbInitializer::pre_init: +++ ENTERING +++ : obj = 0x232d000 (../NBOrbInitializer.cpp:45) 14:21:38.149 [23747] <2> NBOrbInitializer::pre_init: --- EXITING --- : obj = 0x232d000 (../NBOrbInitializer.cpp:45) 14:21:38.150 [23747] <2> NBOrbInitializer::post_init: +++ ENTERING +++ : obj = 0x232d000 (../NBOrbInitializer.cpp:53) 14:21:38.150 [23747] <2> NBOrbInitializer::post_init: Adding interceptors(NBOrbInitializer.cpp:74) 14:21:38.150 [23747] <2> NBIORInterceptor::NBIORInterceptor: Interceptor Name: EMMlib_Orb_EMMlib_Orb(NBIORInterceptor.cpp:47) 14:21:38.150 [23747] <2> NBOrbInitializer::post_init: --- EXITING --- : obj = 0x232d000 (../NBOrbInitializer.cpp:53) 14:21:38.150 [23747] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:840) 14:21:38.150 [23747] <2> Orb::setOrbTimeoutPolicy: setting ORB connection timeout policy: tv = 300000(Orb.cpp:1504) 14:21:38.150 [23747] <2> Orb::activate: +++ ENTERING +++ : obj = 0x2317f10 (../Orb.cpp:1231) 14:21:38.150 [23747] <2> Orb::activate: Client Orb called activate; Ignored(Orb.cpp:1236) 14:21:38.150 [23747] <2> Orb::activate: --- EXITING --- : obj = 0x2317f10 (../Orb.cpp:1231) 14:21:38.150 [23747] <2> Orb::setOrbTimeoutPolicy: setting ORB connection timeout policy: tv = 60(Orb.cpp:1504) 14:21:38.150 [23747] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1481) 14:21:38.150 [23747] <2> Orb::setOrbTimeoutPolicy: setting ORB request timeout policy: tv = 1800(Orb.cpp:1504) 14:21:38.151 [23747] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1490) 14:21:38.151 [23747] <2> Orb::connectToObject: Connection attempt #1 mW:60 rW:0(Orb.cpp:1167) 14:21:38.151 [23747] <2> Orb::createInsecureObjectRef: +++ ENTERING +++ : obj = 0x2317f10 (../Orb.cpp:1432) 14:21:38.151 [23747] <2> Orb::createInsecureObjectRef: corbaloc being used is: corbaloc:pbxiop:mstr-nbkp-srv:1556:EMM/EMMServer(Orb.cpp:1440) 14:21:38.151 [23747] <2> Orb::createInsecureObjectRef: --- EXITING --- : obj = 0x2317f10 (../Orb.cpp:1432) 14:21:38.151 [23747] <2> Orb::connectToObjectOnce: attempt to create insecure connection(Orb.cpp:1034) 14:21:38.151 [23747] <2> EndpointSelectorFactory::get_selector: epsr2: got 7.x EPS(Endpoint_Selector.cpp:1831) 14:21:38.151 [23747] <2> EndpointSelector_R2::select_endpoint: epsr2: EPS Honoring Server List(Endpoint_Selector.cpp:507) 14:21:38.151 [23747] <2> EndpointSelector_R2::endpoint_from_profile: epsr2: Evaluating 1 endpoints(Endpoint_Selector.cpp:608) 14:21:38.152 [23747] <2> ConnectList::search: host mstr-nbkp-srv not found in cache(ConnectList.cpp:116) 14:21:38.152 [23747] <2> VxssContext::useVxss: epsr2: Setting up useVxss=2(Endpoint_Selector.cpp:134) 14:21:38.152 [23747] <2> VxssContext::begin: epsr2: Setup context, passes. vxss=2 passes=1(Endpoint_Selector.cpp:164) 14:21:38.152 [23747] <2> VxssContext::end: epsr2: all done? passes=1 curridx=0(Endpoint_Selector.cpp:170) 14:21:38.152 [23747] <2> EndpointSelector_R2::endpoint_from_profile: epsr2: pass: 0 secure_mode:2/0(Endpoint_Selector.cpp:741) 14:21:38.152 [23747] <2> ConnectList::search: host mstr-nbkp-srv not found in cache(ConnectList.cpp:116) 14:21:38.152 [23747] <2> EndpointSelector_R2::evaluateEndpoint: epsr2: PBXIOP endpoint host: mstr-nbkp-srv(Endpoint_Selector.cpp:1417) 14:21:38.152 [23747] <2> ConnectList::search: host 172.20.22.231 not found in cache(ConnectList.cpp:116) 14:21:38.156 [23747] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.156 [23747] <2> EndpointSelector_R2::extractByAddressFamily: epsr2: address_binding: 172.20.22.231: ANY(Endpoint_Selector.cpp:1671) 14:21:38.156 [23747] <2> EndpointSelector_R2::cachedHostLookup: epsr2: Hostname mstr-nbkp-srv has 1 candidate addresses(Endpoint_Selector.cpp:1605) 14:21:38.156 [23747] <2> EndpointSelector_R2::evaluateEndpoint: epsr2: Endpoint host mstr-nbkp-srv is not checked against server list(Endpoint_Selector.cpp:1548) 14:21:38.156 [23747] <2> EndpointSelector_R2::evaluateEndpoint: epsr2: Found 1 usable IP addresses for host mstr-nbkp-srv:[172.20.22.231] (Endpoint_Selector.cpp:1557) 14:21:38.156 [23747] <2> ConnectList::search: host 172.20.22.231 not found in cache(ConnectList.cpp:116) 14:21:38.156 [23747] <2> ExternalResolver::set: Resolved host_name 172.20.22.231[172.20.22.231](ExternalResolver.cpp:56) 14:21:38.156 [23747] <2> EndpointSelector_R2::performCallUsingEndpointAndSourceBinding: epsr2: Target: 172.20.22.231, source: ANY(Endpoint_Selector.cpp:939) 14:21:38.156 [23747] <2> VxssContext::updateOnFailure: epsr2: updateOnFailure?=1 useVxss=2(Endpoint_Selector.cpp:220) 14:21:38.158 [23747] <2> EndpointSelector_R2::performCallUsingEndpoint: epsr2: insecure invocation->perform_call(...) to host 172.20.22.231 SUCCESS(Endpoint_Selector.cpp:1149) 14:21:38.158 [23747] <2> ConnectList::update: added host 172.20.22.231 (1 total) as GOOD(ConnectList.cpp:211) 14:21:38.158 [23747] <2> VxssContext::end: epsr2: all done? passes=1 curridx=1(Endpoint_Selector.cpp:170) 14:21:38.159 [23747] <2> EndpointSelector_R2::forward: epsr2: Adding 1 forward profiles(Endpoint_Selector.cpp:532) 14:21:38.159 [23747] <2> EndpointSelector_R2::select_endpoint: epsr2: EPS Honoring Server List(Endpoint_Selector.cpp:507) 14:21:38.159 [23747] <2> EndpointSelector_R2::endpoint_from_profile: epsr2: Evaluating 3 endpoints(Endpoint_Selector.cpp:608) 14:21:38.159 [23747] <2> ConnectList::search: host mstr-nbkp-srv not found in cache(ConnectList.cpp:116) 14:21:38.160 [23747] <2> ConnectList::search: host 172.20.22.231 found GOOD(ConnectList.cpp:89) 14:21:38.160 [23747] <2> EndpointSelector_R2::endpoint_from_profile: epsr2: Reusing endpoint, target: 172.20.22.231, source: ANY(Endpoint_Selector.cpp:659) 14:21:38.160 [23747] <2> VxssContext::updateOnFailure: epsr2: updateOnFailure?=0 useVxss=2(Endpoint_Selector.cpp:220) 14:21:38.160 [23747] <2> ExternalResolver::set: Resolved host_name 172.20.22.231[172.20.22.231](ExternalResolver.cpp:56) 14:21:38.160 [23747] <2> EndpointSelector_R2::performCallUsingEndpoint: epsr2: insecure invocation->perform_call(...) to host 172.20.22.231 SUCCESS(Endpoint_Selector.cpp:1149) 14:21:38.160 [23747] <2> ConnectList::update: updated host 172.20.22.231 as GOOD, used 0 of 3 retries(ConnectList.cpp:175) 14:21:38.160 [23747] <2> Orb::connectToObjectOnce: connection created(Orb.cpp:1052) 14:21:38.160 [23747] <2> EndpointSelectorFactory::get_selector: epsr2: got 7.x EPS(Endpoint_Selector.cpp:1831) 14:21:38.161 [23747] <2> EndpointSelector_R2::select_endpoint: epsr2: EPS Honoring Server List(Endpoint_Selector.cpp:507) 14:21:38.161 [23747] <2> EndpointSelector_R2::endpoint_from_profile: epsr2: Evaluating 3 endpoints(Endpoint_Selector.cpp:608) 14:21:38.161 [23747] <2> ConnectList::search: host mstr-nbkp-srv not found in cache(ConnectList.cpp:116) 14:21:38.161 [23747] <2> ConnectList::search: host 172.20.22.231 found GOOD(ConnectList.cpp:89) 14:21:38.161 [23747] <2> EndpointSelector_R2::endpoint_from_profile: epsr2: Reusing endpoint, target: 172.20.22.231, source: ANY(Endpoint_Selector.cpp:659) 14:21:38.161 [23747] <2> VxssContext::updateOnFailure: epsr2: updateOnFailure?=0 useVxss=2(Endpoint_Selector.cpp:220) 14:21:38.161 [23747] <2> EndpointSelector_R2::performCallUsingEndpoint: epsr2: insecure invocation->perform_call(...) to host 172.20.22.231 SUCCESS(Endpoint_Selector.cpp:1149) 14:21:38.161 [23747] <2> ConnectList::update: updated host 172.20.22.231 as GOOD, used 0 of 3 retries(ConnectList.cpp:175) 14:21:38.162 [23747] <2> EndpointSelectorFactory::get_selector: epsr2: got 7.x EPS(Endpoint_Selector.cpp:1831) 14:21:38.162 [23747] <2> EndpointSelector_R2::select_endpoint: epsr2: EPS Honoring Server List(Endpoint_Selector.cpp:507) 14:21:38.162 [23747] <2> EndpointSelector_R2::endpoint_from_profile: epsr2: Evaluating 3 endpoints(Endpoint_Selector.cpp:608) 14:21:38.162 [23747] <2> ConnectList::search: host mstr-nbkp-srv not found in cache(ConnectList.cpp:116) 14:21:38.162 [23747] <2> ConnectList::search: host 172.20.22.231 found GOOD(ConnectList.cpp:89) 14:21:38.162 [23747] <2> EndpointSelector_R2::endpoint_from_profile: epsr2: Reusing endpoint, target: 172.20.22.231, source: ANY(Endpoint_Selector.cpp:659) 14:21:38.162 [23747] <2> VxssContext::updateOnFailure: epsr2: updateOnFailure?=0 useVxss=2(Endpoint_Selector.cpp:220) 14:21:38.163 [23747] <2> EndpointSelector_R2::performCallUsingEndpoint: epsr2: insecure invocation->perform_call(...) to host 172.20.22.231 SUCCESS(Endpoint_Selector.cpp:1149) 14:21:38.163 [23747] <2> ConnectList::update: updated host 172.20.22.231 as GOOD, used 0 of 3 retries(ConnectList.cpp:175) 14:21:38.164 [23747] <2> EndpointSelectorFactory::get_selector: epsr2: got 7.x EPS(Endpoint_Selector.cpp:1831) 14:21:38.164 [23747] <2> EndpointSelector_R2::select_endpoint: epsr2: EPS Honoring Server List(Endpoint_Selector.cpp:507) 14:21:38.164 [23747] <2> EndpointSelector_R2::endpoint_from_profile: epsr2: Evaluating 3 endpoints(Endpoint_Selector.cpp:608) 14:21:38.164 [23747] <2> ConnectList::search: host mstr-nbkp-srv not found in cache(ConnectList.cpp:116) 14:21:38.164 [23747] <2> ConnectList::search: host 172.20.22.231 found GOOD(ConnectList.cpp:89) 14:21:38.164 [23747] <2> EndpointSelector_R2::endpoint_from_profile: epsr2: Reusing endpoint, target: 172.20.22.231, source: ANY(Endpoint_Selector.cpp:659) 14:21:38.164 [23747] <2> VxssContext::updateOnFailure: epsr2: updateOnFailure?=0 useVxss=2(Endpoint_Selector.cpp:220) 14:21:38.164 [23747] <2> ExternalResolver::set: Resolved host_name 172.20.22.231[172.20.22.231](ExternalResolver.cpp:56) 14:21:38.164 [23747] <2> EndpointSelector_R2::performCallUsingEndpoint: epsr2: insecure invocation->perform_call(...) to host 172.20.22.231 SUCCESS(Endpoint_Selector.cpp:1149) 14:21:38.164 [23747] <2> ConnectList::update: updated host 172.20.22.231 as GOOD, used 0 of 3 retries(ConnectList.cpp:175) 14:21:38.177 [23747] <2> shouldWeAllocateFT: client SAPBISBX is not a SAN client (2000000) 14:21:38.177 [23747] <2> bpbrm tell_mm_to_start_restore: telling media manager to start. 14:21:38.177 [23747] <2> set_job_details: Tfile (670158): LOG 1476615098 4 bpbrm 23747 telling media manager to start restore on client 14:21:38.177 [23747] <2> send_job_file: job ID 670158, ftype = 3 msg len = 78, msg = LOG 1476615098 4 bpbrm 23747 telling media manager to start restore on client 14:21:38.177 [23747] <2> bpbrm multiplexed_restore: calling read_media_msg for DATASOCKET. 14:21:38.578 [23747] <2> bpbrm read_media_msg: read from media manager: NCB_DATASOCKET SAPBISBX_1476613742 50266;f1c6c33ee7b52cfec918fe1c67f14190;11;300000 14:21:38.578 [23747] <2> bpbrm multiplexed_restore: bpbrm.c.17855: media_port: 0 0 0x00000000 14:21:38.578 [23747] <2> bpbrm multiplexed_restore: bpbrm.c.17856: mpx_ipc: 50266;f1c6c33ee7b52cfec918fe1c67f14190;11;300000 14:21:38.578 [23747] <2> bpbrm multiplexed_restore: DATASOCKET = 0 for backup_id SAPBISBX_1476613742 14:21:38.578 [23747] <2> bpbrm spawn_brm_child: spawning child 14:21:38.578 [23747] <2> set_job_details: Tfile (670158): LOG 1476615098 4 bpbrm 23747 spawning a brm child process 14:21:38.579 [23747] <2> send_job_file: job ID 670158, ftype = 3 msg len = 58, msg = LOG 1476615098 4 bpbrm 23747 spawning a brm child process 14:21:38.583 [23747] <2> set_job_details: Tfile (670158): LOG 1476615098 4 bpbrm 23747 child pid: 23757 14:21:38.584 [23757] <2> bpbrm handle_restore: bpbrm.c.18393: mpx_ipc: 50266;f1c6c33ee7b52cfec918fe1c67f14190;11;300000 14:21:38.584 [23747] <2> send_job_file: job ID 670158, ftype = 3 msg len = 46, msg = LOG 1476615098 4 bpbrm 23747 child pid: 23757 14:21:38.584 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.588 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.588 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.591 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.591 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.594 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.594 [23757] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1 14:21:38.595 [23757] <2> vnet_pbxConnect: pbxConnectEx Succeeded 14:21:38.595 [23757] <2> do_pbx_service: [vnet_connect.c:2116] via PBX bpjobd CONNECT FROM 172.20.22.232.41962 TO 172.20.22.231.1556 fd = 5 14:21:38.595 [23757] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 172.20.22.232.41962 TO 172.20.22.231.1556 fd = 5 14:21:38.595 [23757] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mstr-nbkp-srv 172.20.22.231 bpjobd VIA pbx 14:21:38.595 [23757] <2> job_connect: SO_KEEPALIVE set on socket 5 for client mstr-nbkp-srv 14:21:38.595 [23757] <2> logconnections: BPJOBD CONNECT FROM 172.20.22.232.41962 TO 172.20.22.231.1556 fd = 5 14:21:38.595 [23757] <2> job_authenticate_connection: ignoring VxSS authentication check for now... 14:21:38.596 [23757] <2> job_connect: Connected to the host mstr-nbkp-srv contype 53 jobid <670158> socket <5> 14:21:38.596 [23757] <2> job_connect: Connected on port 41962 14:21:38.596 [23757] <2> set_job_details: Tfile (670158): LOG 1476615098 4 bpbrm 23747 listening for client connection 14:21:38.596 [23757] <2> send_job_file: job ID 670158, ftype = 3 msg len = 61, msg = LOG 1476615098 4 bpbrm 23747 listening for client connection 14:21:38.596 [23757] <2> bpbrm listen_for_client: HOT_SYBASE_DB_RESTORE 14:21:38.596 [23757] <2> bpbrm listen_for_client: bpbrm.c.22255: vnetd connect forward: 0 0 0x00000000 14:21:38.597 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.600 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.600 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.603 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.603 [23757] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1 14:21:38.605 [23757] <2> vnet_pbxConnect: pbxConnectEx Succeeded 14:21:38.645 [23757] <8> do_pbx_service: [vnet_connect.c:2108] via PBX VNETD CONNECT FROM 172.20.22.232.58519 TO 172.20.44.72.1556 fd = 13 14:21:38.646 [23757] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 172.20.22.232.58519 TO 172.20.44.72.1556 fd = 13 14:21:38.646 [23757] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO SAPBISBX 172.20.44.72 vnetd VIA pbx 14:21:38.646 [23757] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:443] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa 14:21:38.713 [23757] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:460] ipc_string 50268 14:21:38.754 [23757] <2> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:471] hash_str1 3720d5e58550319f2c195f0600805dfb 14:21:38.754 [23757] <2> bpbrm listen_for_client: bpbrm.c.22267: data_ipc: 50268;3720d5e58550319f2c195f0600805dfb;11;300000 14:21:38.754 [23757] <2> bpbrm listen_for_client: bpbrm.c.22268: accept_socket_data: 13 13 0x0000000d 14:21:38.754 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.758 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.758 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.761 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.761 [23757] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1 14:21:38.763 [23757] <2> vnet_pbxConnect: pbxConnectEx Succeeded 14:21:38.784 [23747] <2> bpbrm spawn_brm_child: bpbrm child pid = 23757 14:21:38.803 [23757] <8> do_pbx_service: [vnet_connect.c:2108] via PBX VNETD CONNECT FROM 172.20.22.232.51184 TO 172.20.44.72.1556 fd = 14 14:21:38.803 [23757] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 172.20.22.232.51184 TO 172.20.44.72.1556 fd = 14 14:21:38.803 [23757] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO SAPBISBX 172.20.44.72 vnetd VIA pbx 14:21:38.803 [23757] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:443] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa 14:21:38.864 [23757] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:460] ipc_string 50270 14:21:38.905 [23757] <2> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:471] hash_str1 fcb9e6c4f8431c2800ab1c2ad6678c19 14:21:38.905 [23757] <2> bpbrm listen_for_client: bpbrm.c.22280: name_ipc: 50270;fcb9e6c4f8431c2800ab1c2ad6678c19;11;300000 14:21:38.905 [23757] <2> bpbrm listen_for_client: bpbrm.c.22281: accept_socket_name: 14 14 0x0000000e 14:21:38.905 [23757] <2> local_bpcr_connect: bpcr.c.278: connect_opts = 0x01010100 connect_opts2 = 0x01000100 14:21:38.905 [23757] <2> local_bpcr_connect: bpcr.c.285: connect_opts = 0x01010100 14:21:38.905 [23757] <2> local_bpcr_connect: bpcr.c.324: daemon_port_type = 1 14:21:38.905 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.909 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.909 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.912 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.912 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.915 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.915 [23757] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1 14:21:38.917 [23757] <2> vnet_pbxConnect: pbxConnectEx Succeeded 14:21:38.917 [23757] <2> do_pbx_service: [vnet_connect.c:2116] via PBX bpcd CONNECT FROM 172.20.22.232.54911 TO 172.20.44.72.1556 fd = 15 14:21:38.917 [23757] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 172.20.22.232.54911 TO 172.20.44.72.1556 fd = 15 14:21:38.917 [23757] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO SAPBISBX 172.20.44.72 bpcd VIA pbx 14:21:38.918 [23757] <2> logconnections: BPCD CONNECT FROM 172.20.22.232.54911 TO 172.20.44.72.1556 fd = 15 14:21:38.918 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.921 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.921 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:21:38.925 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:21:38.925 [23757] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1 14:21:38.928 [23757] <2> vnet_pbxConnect: pbxConnectEx Succeeded 14:21:38.960 [23757] <8> do_pbx_service: [vnet_connect.c:2108] via PBX VNETD CONNECT FROM 172.20.22.232.60493 TO 172.20.44.72.1556 fd = 16 14:21:38.961 [23757] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 172.20.22.232.60493 TO 172.20.44.72.1556 fd = 16 14:21:38.961 [23757] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO 172.20.44.72 172.20.44.72 vnetd VIA pbx 14:21:38.961 [23757] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:443] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa 14:21:39.016 [23757] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:460] ipc_string 50272 14:21:39.058 [23757] <2> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:471] hash_str1 2579d719a1b174355349385aa004a6b0 14:21:39.162 [23757] <2> bpbrm send_info_via_progress_file: CLIENT_CMD_SOCK from bpcr = 15 14:21:39.162 [23757] <2> bpbrm send_info_via_progress_file: CLIENT_STAT_SOCK from bpcr = 16 14:21:39.162 [23757] <2> bpcr_get_peername_rqst: Server peername length = 15 14:21:39.165 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Data socket = media-nbkp-srv1.IPC:50268;3720d5e58550319f2c195f0600805dfb;11;300000 14:21:39.166 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Name socket = media-nbkp-srv1.IPC:50270;fcb9e6c4f8431c2800ab1c2ad6678c19;11;300000 14:21:39.166 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Job id = 670158 14:21:39.167 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Backup id = SAPBISBX_1476613742 14:21:39.167 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Backup time = 1476613742 14:21:39.168 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Policy name = test-for-sybase-db 14:21:39.169 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Snapshot = 0 14:21:39.169 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Frozen image = 0 14:21:39.170 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Backup copy = 0 14:21:39.170 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Master server = mstr-nbkp-srv 14:21:39.171 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Media server = media-nbkp-srv1 14:21:39.171 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - New data socket = media-nbkp-srv1.IPC:50266;f1c6c33ee7b52cfec918fe1c67f14190;11;300000 14:21:39.172 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Use shared memory = 0 14:21:39.172 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Restore id = 670158.001 14:21:39.173 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Encrypt = 0 14:21:39.173 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Client read timeout = 300000 14:21:39.174 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - Media mount timeout = 0 14:21:39.174 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - client = SAPBISBX 14:21:39.175 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - requesting_client = SAPBISBX 14:21:39.175 [23757] <2> bpbrm write_msg_to_progress_file: (670158.001) INF - browse_client = sapbisbx 14:23:07.862 [23747] <2> bpbrm read_media_msg: read from media manager: CURRENT POSITION L60367 1 14:23:07.862 [23747] <2> bpbrm send_parent_msg: CURRENT POSITION L60367 1 14:23:07.962 [23747] <2> bpbrm read_parent_msg: read from parent CONTINUE RESTORE 14:23:07.962 [23747] <2> bpbrm tell_mm: sending media manager msg: CONTINUE RESTORE 14:23:08.862 [23747] <2> bpbrm read_media_msg: read from media manager: MEDIA READY 14:23:08.862 [23747] <2> bpbrm signal_bpbrm_child: sending SIGUSR1 to bpbrm child 23757 14:23:38.512 [23747] <2> bpbrm read_media_msg: read from media manager: MEDIA NOT READY 14:23:38.512 [23747] <2> bpbrm signal_bpbrm_child: sending SIGUSR1 to bpbrm child 23757 14:23:38.512 [23747] <2> bpbrm read_media_msg: read from media manager: EXIT SAPBISBX_1476613742 25 14:23:38.512 [23747] <2> bpbrm process_media_msg: media manager for backup id SAPBISBX_1476613742 exited with status 25: cannot connect on socket 14:23:38.513 [23747] <2> set_job_details: Tfile (670158): LOG 1476615218 4 bpbrm 23747 media manager for backup id SAPBISBX_1476613742 exited with status 25: cannot connect on socket 14:23:38.513 [23747] <2> send_job_file: job ID 670158, ftype = 3 msg len = 125, msg = LOG 1476615218 4 bpbrm 23747 media manager for backup id SAPBISBX_1476613742 exited with status 25: cannot connect on socket 14:23:38.513 [23747] <2> bpbrm kill_bpbrm_child: terminating bpbrm child 23757 jobid=670158 14:23:38.513 [23747] <2> set_job_details: Tfile (670158): LOG 1476615218 4 bpbrm 23747 terminating bpbrm child 23757 jobid=670158 14:23:38.513 [23747] <2> send_job_file: job ID 670158, ftype = 3 msg len = 72, msg = LOG 1476615218 4 bpbrm 23747 terminating bpbrm child 23757 jobid=670158 14:23:38.513 [23757] <2> Bpbrm_library_signal_poll: Detected terminate 14:23:38.513 [23757] <8> vnet_sock_ready: [vnet.c:1471] errno=4 sock=13 14:23:38.513 [23757] <2> vnet_sock_ready: vnet.c.1473: 0: Function failed: 10 0x0000000a 14:23:38.513 [23757] <2> vnet_pop_byte: vnet.c.1155: 0: Function failed: 10 0x0000000a 14:23:38.513 [23757] <2> vnet_pop_string: vnet.c.1250: 0: Function failed: 10 0x0000000a 14:23:38.513 [23757] <2> vnet_pop_signed: vnet.c.1293: 0: Function failed: 10 0x0000000a 14:23:38.513 [23757] <2> vnet_pop_status: vnet.c.1371: 0: Function failed: 10 0x0000000a 14:23:38.513 [23757] <8> vnet_vnetd_connect_forward_socket_end: [vnet_vnetd.c:525] status 10 0xa 14:23:38.513 [23757] <2> bpcr_vnetd_connect_forward_socket_end: vnet_vnetd_connect_forward_socket_end() failed: 10 14:23:38.513 [23757] <8> vnet_vnetd_disconnect: [vnet_vnetd.c:195] VN_REQUEST_DISCONNECT 1 0x1 14:23:38.514 [23757] <2> vnet_sock_ready: vnet.c.1412: 0: Function failed: 2 0x00000002 14:23:38.514 [23757] <2> vnet_push_string: vnet.c.1202: 0: Function failed: 2 0x00000002 14:23:38.514 [23757] <2> vnet_push_unsigned: vnet.c.1314: 0: Function failed: 2 0x00000002 14:23:38.514 [23757] <8> vnet_vnetd_disconnect: [vnet_vnetd.c:198] status 2 0x2 14:23:38.514 [23757] <2> bpbrm listen_for_client: bpbrm.c.22400: bpcr_vnetd_connect_forward_socket_end() failed: 21 21 0x00000015 14:23:38.514 [23757] <2> bpbrm listen_for_client: bpbrm.c.22403: accept_socket_data: -1 4294967295 0xffffffff 14:23:38.514 [23757] <16> bpbrm listen_for_client: listen for client timeout during accept from data listen socket after 60 seconds 14:23:38.515 [23757] <2> set_job_details: Tfile (670158): LOG 1476615218 16 bpbrm 23757 listen for client timeout during accept from data listen socket after 60 seconds 14:23:38.515 [23757] <2> send_job_file: job ID 670158, ftype = 3 msg len = 111, msg = LOG 1476615218 16 bpbrm 23757 listen for client timeout during accept from data listen socket after 60 seconds 14:23:38.515 [23757] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mstr-nbkp-srv, query type 1 14:23:38.515 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:23:38.519 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:23:38.519 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:23:38.522 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:23:38.522 [23757] <2> vnet_sortaddrs: [vnet_addrinfo.c:3945] sorted addrs: 1 0x1 14:23:38.525 [23757] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4809] using interface ANY 14:23:38.525 [23757] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1 14:23:38.525 [23757] <2> vnet_pbxConnect: pbxConnectEx Succeeded 14:23:38.526 [23757] <2> do_pbx_service: [vnet_connect.c:2116] via PBX bpdbm CONNECT FROM 172.20.22.232.49410 TO 172.20.22.231.1556 fd = 13 14:23:38.526 [23757] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 172.20.22.232.49410 TO 172.20.22.231.1556 fd = 13 14:23:38.526 [23757] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mstr-nbkp-srv 172.20.22.231 bpdbm VIA pbx 14:23:38.526 [23757] <2> logconnections: BPDBM CONNECT FROM 172.20.22.232.49410 TO 172.20.22.231.1556 fd = 13 14:23:38.526 [23757] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2 14:23:38.529 [23757] <2> db_end: Need to collect reply 14:23:38.529 [23757] <2> Bpbrm_siginfo_print: 0: delay 59 signo SIGALRM:14 code 128 pid 0 14:23:38.529 [23757] <2> Bpbrm_siginfo_print: 1: delay 31 signo SIGUSR2:12 code 0 pid 23747 14:23:38.529 [23757] <2> Bpbrm_siginfo_print: 2: delay 30 signo SIGUSR1:10 code 0 pid 23747 14:23:38.529 [23757] <2> Bpbrm_siginfo_print: 3: delay 0 signo SIGUSR1:10 code 0 pid 23747 14:23:38.529 [23757] <2> Bpbrm_siginfo_print: 4: delay 0 signo SIGHUP:1 code 0 pid 23747 14:23:38.541 [23757] <2> BpConfigHolder::~BpConfigHolder: +++ ENTERING +++ : obj = 0x2318648 (../BpConf.cpp:40) 14:23:38.541 [23757] <2> BpConfigHolder::free: +++ ENTERING +++ : obj = 0x2318648 (../BpConf.cpp:60) 14:23:38.541 [23757] <2> BpConfigHolder::free: --- EXITING --- : obj = 0x2318648 (../BpConf.cpp:60) 14:23:38.541 [23757] <2> BpConfigHolder::~BpConfigHolder: --- EXITING --- : obj = 0x2318648 (../BpConf.cpp:40) 14:23:38.542 [23757] <2> NBIORInterceptor::destroy: Destroying Interceptor: EMMlib_Orb_EMMlib_Orb(NBIORInterceptor.cpp:61) 14:23:38.543 [23757] <2> InsecureEndpointSelectorFactory::~InsecureEndpointSelectorFactory: +++ ENTERING +++ : obj = 0x232c970 (../Endpoint_Selector.cpp:1906) 14:23:38.543 [23757] <2> InsecureEndpointSelectorFactory::~InsecureEndpointSelectorFactory: --- EXITING --- : obj = 0x232c970 (../Endpoint_Selector.cpp:1906) 14:23:38.543 [23757] <2> EndpointSelectorFactory::~EndpointSelectorFactory: +++ ENTERING +++ : obj = 0x232c7b0 (../Endpoint_Selector.cpp:1811) 14:23:38.543 [23757] <2> EndpointSelectorFactory::~EndpointSelectorFactory: --- EXITING --- : obj = 0x232c7b0 (../Endpoint_Selector.cpp:1811) 14:23:38.548 [23747] <2> Bpbrm_siginfo_print: 0: delay 0 signo SIGCHLD:17 code 1 pid 23757 14:23:38.548 [23747] <2> bpbrm brm_sigcld: SIGCLD caught by bpbrm 14:23:38.548 [23747] <2> bpbrm brm_sigcld: bpbrm child 23757 exit_status = 54, signal_status = 0 14:23:38.548 [23747] <2> bpbrm brm_sigcld: child 23757 exited with status 54: timed out connecting to client 14:23:38.548 [23747] <2> bpbrm send_status_to_parent: EXIT SAPBISBX_1476613742 54 sent to parent process. 14:23:38.649 [23747] <2> bpbrm read_parent_msg: read from parent TERMINATE 14:23:38.649 [23747] <2> bpbrm tell_mm: sending media manager msg: TERMINATE 14:23:38.650 [23747] <2> vnet_close_socket_safely: [vnet.c:2029] safe close 0 0x0 14:23:38.653 [23747] <2> BpConfigHolder::~BpConfigHolder: +++ ENTERING +++ : obj = 0x2318648 (../BpConf.cpp:40) 14:23:38.653 [23747] <2> BpConfigHolder::free: +++ ENTERING +++ : obj = 0x2318648 (../BpConf.cpp:60) 14:23:38.653 [23747] <2> BpConfigHolder::free: --- EXITING --- : obj = 0x2318648 (../BpConf.cpp:60) 14:23:38.653 [23747] <2> BpConfigHolder::~BpConfigHolder: --- EXITING --- : obj = 0x2318648 (../BpConf.cpp:40) 14:23:38.653 [23747] <2> NBIORInterceptor::destroy: Destroying Interceptor: EMMlib_Orb_EMMlib_Orb(NBIORInterceptor.cpp:61) 14:23:38.653 [23747] <2> InsecureEndpointSelectorFactory::~InsecureEndpointSelectorFactory: +++ ENTERING +++ : obj = 0x232c970 (../Endpoint_Selector.cpp:1906) 14:23:38.653 [23747] <2> InsecureEndpointSelectorFactory::~InsecureEndpointSelectorFactory: --- EXITING --- : obj = 0x232c970 (../Endpoint_Selector.cpp:1906) 14:23:38.653 [23747] <2> EndpointSelectorFactory::~EndpointSelectorFactory: +++ ENTERING +++ : obj = 0x232c7b0 (../Endpoint_Selector.cpp:1811) 14:23:38.653 [23747] <2> EndpointSelectorFactory::~EndpointSelectorFactory: --- EXITING --- : obj = 0x232c7b0 (../Endpoint_Selector.cpp:1811)