00:00:46.276 [6952.5556] <2> send_MDS_msg: KBYTES_WRITTEN 0 {E504547B-1413-48C4-A285-21445EDE6384} 1478300 1 240005120 743289 00:00:46.276 [6952.5556] <2> JobInst::sendIrmMsg: starting 00:00:46.291 [6952.5556] <2> JobInst::sendIrmMsg: returning 00:01:37.130 [6952.5556] <2> send_MDS_msg: KBYTES_WRITTEN 0 {E504547B-1413-48C4-A285-21445EDE6384} 1478300 1 243005184 743289 00:01:37.130 [6952.5556] <2> JobInst::sendIrmMsg: starting 00:01:37.149 [6952.5556] <2> JobInst::sendIrmMsg: returning 00:01:46.866 [6936.816] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mymasterserver.mydomain.dom, query type 70 00:01:46.866 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:46.866 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:46.866 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:46.866 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:46.866 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:46.866 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:46.866 [6936.816] <2> async_connect: [vnet_connect.c:1508] connect in progress 1 0x1 00:01:46.929 [6936.816] <2> vnet_pbxConnect: pbxConnectEx Succeeded 00:01:46.929 [6936.816] <2> do_pbx_service: [vnet_connect.c:2194] via PBX bpdbm CONNECT FROM 192.168.2.200.63042 TO 192.168.1.100.1556 fd = 1500 00:01:46.929 [6936.816] <2> async_connect: [vnet_connect.c:1700] connect async CONNECT FROM 192.168.2.200.63042 TO 192.168.1.100.1556 fd = 1500 00:01:46.929 [6936.816] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mymasterserver.mydomain.dom 192.168.1.100 bpdbm VIA pbx 00:01:46.929 [6936.816] <2> logconnections: BPDBM CONNECT FROM 192.168.2.200.63042 TO 192.168.1.100.1556 fd = 1500 00:01:46.929 [6936.816] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:1115] Ignoring VxSS authentication 2 0x2 00:01:47.101 [6936.816] <2> db_end: Need to collect reply 00:01:47.179 [6936.816] <2> replace_disk_frag: replaced disk fragment for backupid VM001__1503953585, copy 1, fragment 1, kbytes 20341906 00:01:47.179 [6936.816] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mymasterserver.mydomain.dom, query type 1 00:01:47.179 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:47.179 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:47.195 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:47.195 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:47.195 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:47.195 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:47.195 [6936.816] <2> async_connect: [vnet_connect.c:1508] connect in progress 1 0x1 00:01:47.241 [6936.816] <2> vnet_pbxConnect: pbxConnectEx Succeeded 00:01:47.241 [6936.816] <2> do_pbx_service: [vnet_connect.c:2194] via PBX bpdbm CONNECT FROM 192.168.2.200.63043 TO 192.168.1.100.1556 fd = 1500 00:01:47.241 [6936.816] <2> async_connect: [vnet_connect.c:1700] connect async CONNECT FROM 192.168.2.200.63043 TO 192.168.1.100.1556 fd = 1500 00:01:47.241 [6936.816] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mymasterserver.mydomain.dom 192.168.1.100 bpdbm VIA pbx 00:01:47.241 [6936.816] <2> logconnections: BPDBM CONNECT FROM 192.168.2.200.63043 TO 192.168.1.100.1556 fd = 1500 00:01:47.241 [6936.816] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:1115] Ignoring VxSS authentication 2 0x2 00:01:47.413 [6936.816] <2> db_end: Need to collect reply 00:01:47.445 [6936.816] <4> write_backup: successfully wrote backup id VM001__1503953585, copy 1, fragment 1, 20341906 Kbytes at 41541.902 Kbytes/sec 00:01:47.445 [6936.816] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mymasterserver.mydomain.dom, query type 60 00:01:47.445 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:47.445 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:47.445 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:47.445 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:47.445 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:47.445 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:47.445 [6936.816] <2> async_connect: [vnet_connect.c:1508] connect in progress 1 0x1 00:01:47.507 [6936.816] <2> vnet_pbxConnect: pbxConnectEx Succeeded 00:01:47.507 [6936.816] <2> do_pbx_service: [vnet_connect.c:2194] via PBX bpdbm CONNECT FROM 192.168.2.200.63044 TO 192.168.1.100.1556 fd = 1500 00:01:47.507 [6936.816] <2> async_connect: [vnet_connect.c:1700] connect async CONNECT FROM 192.168.2.200.63044 TO 192.168.1.100.1556 fd = 1500 00:01:47.507 [6936.816] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mymasterserver.mydomain.dom 192.168.1.100 bpdbm VIA pbx 00:01:47.507 [6936.816] <2> logconnections: BPDBM CONNECT FROM 192.168.2.200.63044 TO 192.168.1.100.1556 fd = 1500 00:01:47.507 [6936.816] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:1115] Ignoring VxSS authentication 2 0x2 00:01:47.805 [6936.816] <2> setup_tir_or_im_read: string received from bpdbm is (0 555994 0) 00:01:47.805 [6936.816] <2> setup_tir_or_im_read: successfully connected to bpdbm to read TIR file, size is 555994 bytes + 0 GB 00:01:47.805 [6936.816] <2> construct_sts_isid: master_server mymasterserver.mydomain.dom, client VM001_, backup_time 1503953585, copy_number 1, stream_number 1378, fragment_number -1, resume_number 0, spl_name NULL 00:01:47.805 [6936.816] <2> bp_sts_open_image: STH set to STS_SA_IMAGE 00:01:47.805 [6936.816] <2> bp_sts_open_image: STSBasicDisk:myMEDIA.mydomain.domF:\NBU_07\ VM001__1503953585_C1_TIR 1 1 1 sth 0 2 8 LSU 0x7 0x1 0x2 saveas 0x4, stream_type 0x4 fscp 0 00:01:47.805 [6936.816] <2> 743408:bptm:6936:myMEDIA.mydomain.dom: entering stspi_create_image(4) 00:01:48.696 [6936.816] <2> io_open_disk: file VM001__1503953.ru585_C1_TIR successfully opened 00:01:48.696 [6936.816] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mymasterserver.mydomain.dom, query type 77 00:01:48.696 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:48.696 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:48.696 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:48.696 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:48.696 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:48.696 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:48.696 [6936.816] <2> async_connect: [vnet_connect.c:1508] connect in progress 1 0x1 00:01:48.743 [6936.816] <2> vnet_pbxConnect: pbxConnectEx Succeeded 00:01:48.743 [6936.816] <2> do_pbx_service: [vnet_connect.c:2194] via PBX bpdbm CONNECT FROM 192.168.2.200.63045 TO 192.168.1.100.1556 fd = 1544 00:01:48.743 [6936.816] <2> async_connect: [vnet_connect.c:1700] connect async CONNECT FROM 192.168.2.200.63045 TO 192.168.1.100.1556 fd = 1544 00:01:48.743 [6936.816] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mymasterserver.mydomain.dom 192.168.1.100 bpdbm VIA pbx 00:01:48.743 [6936.816] <2> logconnections: BPDBM CONNECT FROM 192.168.2.200.63045 TO 192.168.1.100.1556 fd = 1544 00:01:48.743 [6936.816] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:1115] Ignoring VxSS authentication 2 0x2 00:01:48.922 [6936.816] <2> db_end: Need to collect reply 00:01:49.001 [6936.816] <2> add_disk_frag: added disk fragment for backupid VM001__1503953585, copy 1, fragment -1 mediaid F:\NBU_07\\VM001__1503953585_C1_TIR input id is NONE 00:01:49.001 [6936.816] <2> add_disk_frag: media type = 0, media_subtype = 1 00:01:49.001 [6936.816] <2> bp_sts_make_tar_header: writing LF_END_U_LEN_FILE, GB = 0, bytes = 0, total_bytes = 0, total_expected GB = 0, total_expected_bytes = 555994, tir_hdr_pad_size = 0 00:01:49.001 [6936.816] <2> bp_sts_seek_image: seeking to offset 0 00:01:49.001 [6936.816] <2> ndmp_setup_for_write: CINDEX 0, TWIN_INDEX 0, IS_NDMP 0, is_tir 1 00:01:49.038 [6936.816] <2> write_data_tir: writing first TIR block to media, bytes = 262144 00:01:49.210 [6936.816] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mymasterserver.mydomain.dom, query type 1 00:01:49.210 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:49.210 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:49.210 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:49.210 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:49.210 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:49.210 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:49.210 [6936.816] <2> async_connect: [vnet_connect.c:1508] connect in progress 1 0x1 00:01:49.257 [6936.816] <2> vnet_pbxConnect: pbxConnectEx Succeeded 00:01:49.257 [6936.816] <2> do_pbx_service: [vnet_connect.c:2194] via PBX bpdbm CONNECT FROM 192.168.2.200.63046 TO 192.168.1.100.1556 fd = 1500 00:01:49.257 [6936.816] <2> async_connect: [vnet_connect.c:1700] connect async CONNECT FROM 192.168.2.200.63046 TO 192.168.1.100.1556 fd = 1500 00:01:49.257 [6936.816] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mymasterserver.mydomain.dom 192.168.1.100 bpdbm VIA pbx 00:01:49.257 [6936.816] <2> logconnections: BPDBM CONNECT FROM 192.168.2.200.63046 TO 192.168.1.100.1556 fd = 1500 00:01:49.257 [6936.816] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:1115] Ignoring VxSS authentication 2 0x2 00:01:49.444 [6936.816] <2> db_end: Need to collect reply 00:01:49.475 [6936.816] <4> report_throughput: VBRT 2 6936 7 1 F:\NBU_07\ @aaaa1 0 1 0 542 542 351609 16 351765 16 0 0 15 3 30 (../bptm.c.26945) 00:01:49.475 [6936.816] <2> bp_sts_close_image: 0000000003B87870 0 1 4 0 1 1 0 complete flag (4)(M_NOT_COMPLETE ), close type (0)(STS_CLOSEF_IH_INCOMPLETE ) 11 00:01:53.786 [6936.816] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mymasterserver.mydomain.dom, query type 70 00:01:53.786 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:53.786 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:53.786 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:53.786 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:53.786 [6936.816] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:01:53.786 [6936.816] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:01:53.786 [6936.816] <2> async_connect: [vnet_connect.c:1508] connect in progress 1 0x1 00:01:53.833 [6936.816] <2> vnet_pbxConnect: pbxConnectEx Succeeded 00:01:53.833 [6936.816] <2> do_pbx_service: [vnet_connect.c:2194] via PBX bpdbm CONNECT FROM 192.168.2.200.63047 TO 192.168.1.100.1556 fd = 1500 00:01:53.833 [6936.816] <2> async_connect: [vnet_connect.c:1700] connect async CONNECT FROM 192.168.2.200.63047 TO 192.168.1.100.1556 fd = 1500 00:01:53.833 [6936.816] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mymasterserver.mydomain.dom 192.168.1.100 bpdbm VIA pbx 00:01:53.833 [6936.816] <2> logconnections: BPDBM CONNECT FROM 192.168.2.200.63047 TO 192.168.1.100.1556 fd = 1500 00:01:53.833 [6936.816] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:1115] Ignoring VxSS authentication 2 0x2 00:01:54.008 [6936.816] <2> db_end: Need to collect reply 00:01:54.086 [6936.816] <2> replace_disk_frag: replaced disk fragment for backupid VM001__1503953585, copy 1, fragment -1, kbytes 542 00:01:54.086 [6936.816] <2> construct_sts_isid: master_server mymasterserver.mydomain.dom, client VM001_, backup_time 1503953585, copy_number 1, stream_number 1378, fragment_number -1, resume_number 0, spl_name NULL 00:01:54.086 [6936.816] <2> bp_sts_open_image: STH set to STS_SA_IMAGE 00:01:54.086 [6936.816] <2> bp_sts_open_image: STSBasicDisk:myMEDIA.mydomain.domF:\NBU_07\ VM001__1503953585_C1_TIR 1 0 1 sth 0 2 8 LSU 0x7 0x1 0x2 saveas 0x4, stream_type 0x4 fscp 0 00:01:54.168 [6936.816] <2> io_open_disk: file VM001__1503953585_C1_TIR successfully opened 00:01:54.168 [6936.816] <2> bp_sts_make_tar_header: writing LF_END_U_LEN_FILE, GB = 0, bytes = 555994, total_bytes = 555994, total_expected GB = 0, total_expected_bytes = 555994, tir_hdr_pad_size = 0 00:01:54.168 [6936.816] <2> bp_sts_seek_image: seeking to offset 0 00:01:54.168 [6936.816] <2> bp_sts_close_image: 0000000003B87D70 0 1 4 1 1 1 0 complete flag (64)(M_BACKUP_COMPLETE ), close type (1)(STS_CLOSEF_IH_COMPLETE ) 11 00:01:54.590 [6936.816] <2> notify: executing - C:\Program Files\Veritas\NetBackup\bin\backup_notify.cmd bptm F:\NBU_07\/VM001__1503953585 00:01:54.684 [6936.816] <2> updateEMM_freespace: updateEMM_freespace() (1 0) 00:01:54.684 [6936.816] <2> updateEMM_freespace: 0, Media01-NTFS-MSDD (1 1 0 1) 00:01:54.684 [6936.816] <4> db_getSTUNIT: EMM interface already initialized (using cached master name mymasterserver.mydomain.dom). 00:01:54.809 [6936.816] <4> 743408:bptm:6936:myMEDIA.mydomain.dom: STSBasicDisk: LSU is Basic Disk 00:01:54.809 [6936.816] <4> 743408:bptm:6936:myMEDIA.mydomain.dom: STSBasicDisk: LSU is Basic Disk 00:01:54.809 [6936.816] <4> 743408:bptm:6936:myMEDIA.mydomain.dom: STSBasicDisk: LSU is Basic Disk 00:01:54.809 [6936.816] <2> bptm: free space = 1227690311680, total space = 18511171649536 00:01:54.809 [6936.816] <4> db_modifySTUNIT: EMM interface already initialized (using cached master name mymasterserver.mydomain.dom). 00:01:54.887 [6936.816] <2> db_modifySTUNIT: 00:01:54.887 [6936.816] <2> bptm: EXITING with status 0 <---------- 00:01:54.887 [6936.816] <2> set_job_details: Tfile (743408): LOG 1503954114 4 bptm 6936 EXITING with status 0 <---------- 00:01:54.887 [6936.816] <2> send_job_file: job ID 743408, ftype = 3 msg len = 61, msg = LOG 1503954114 4 bptm 6936 EXITING with status 0 <---------- 00:01:54.887 [6936.816] <2> cleanup: Detached from BPBRM shared memory 00:02:30.071 [6952.5556] <2> send_MDS_msg: KBYTES_WRITTEN 0 {E504547B-1413-48C4-A285-21445EDE6384} 1478300 1 246005248 743289 00:02:30.071 [6952.5556] <2> JobInst::sendIrmMsg: starting 00:02:30.086 [6952.5556] <2> JobInst::sendIrmMsg: returning 00:02:46.363 [5300.6508] <2> initialize: fd values STDOUTSOCK=512 STDERRSOCK=608 00:02:46.378 [5300.6508] <2> bptm: instance - 48606859 00:02:46.378 [5300.6508] <2> bptm: INITIATING (VERBOSE = 5): -w -pid 7920 -c vm01 -dpath F:\NBU_07\ -stunit Media01-NTFS-MSDD -cl Policy01 -bt 1503954160 -b vm01_1503954160 -st 1 -cj 1 -reqid -1503927022 -vm 2 -jm -brm -hostname vm01 -ru root -rclnt vm01 -rclnthostname vm01 -rl 2 -rp 604800 -sl Diff -ct 40 -maxfrag 524288 -eari 0 -mediasvr myMEDIA.mydomain.dom-ifr -no_callback -connect_options 0x01010100 -jobid 743468 -jobgrpid 743460 -masterversion 800000 -bpbrm_shm_id Global\NetBackup_BPBRM_SHM_Path_48606250_7920_7040 -blks_per_buffer 512 00:02:46.378 [5300.6508] <2> main: ../bptm.c.1527: maximum fragment size is 524288000 Kbytes 00:02:46.378 [5300.6508] <2> bptm: PORT_STATUS = 0x01010100 00:02:46.378 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:46.378 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:46.378 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:46.378 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:46.378 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:46.378 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:46.378 [5300.6508] <2> async_connect: [vnet_connect.c:1508] connect in progress 1 0x1 00:02:46.425 [5300.6508] <2> vnet_pbxConnect: pbxConnectEx Succeeded 00:02:46.425 [5300.6508] <2> do_pbx_service: [vnet_connect.c:2194] via PBX bpjobd CONNECT FROM 192.168.2.200.63124 TO 192.168.1.100.1556 fd = 816 00:02:46.425 [5300.6508] <2> async_connect: [vnet_connect.c:1700] connect async CONNECT FROM 192.168.2.200.63124 TO 192.168.1.100.1556 fd = 816 00:02:46.425 [5300.6508] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mymasterserver.mydomain.dom 192.168.1.100 bpjobd VIA pbx 00:02:46.425 [5300.6508] <2> job_connect: SO_KEEPALIVE set on socket 816 for client mymasterserver.mydomain.dom 00:02:46.425 [5300.6508] <2> logconnections: BPJOBD CONNECT FROM 192.168.2.200.63124 TO 192.168.1.100.1556 fd = 816 00:02:46.425 [5300.6508] <2> job_authenticate_connection: VxSS authentication check for now... 00:02:46.425 [5300.6508] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:1115] Ignoring VxSS authentication 2 0x2 00:02:46.456 [5300.6508] <2> job_connect: Connected to the host mymasterserver.mydomain.dom contype 53 jobid <743468> socket <816> 00:02:46.456 [5300.6508] <2> job_connect: Connected on port 63124 00:02:46.456 [5300.6508] <2> set_job_details: Tfile (743468): LOG 1503954166 4 bptm 5300 start 00:02:46.456 [5300.6508] <2> send_job_file: job ID 743468, ftype = 3 msg len = 33, msg = LOG 1503954166 4 bptm 5300 start 00:02:46.456 [5300.6508] <2> __tl_initdir__: name:, result:<1> 00:02:46.456 [5300.6508] <2> _tl_opendir_: name:, result:<1> 00:02:46.456 [5300.6508] <4> bptm: emmserver_name = mymasterserver 00:02:46.456 [5300.6508] <4> bptm: emmserver_port = 1556 00:02:46.456 [5300.6508] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:797) 00:02:46.456 [5300.6508] <2> Orb::init: initializing ORB EMMlib_Orb with: [bptm] [-ORBSvcConfDirective] [-ORBDottedDecimalAddresses 0] [-ORBSvcConfDirective] [static Resource_Factory '-ORBNativeCharCodeSet UTF-8'] [-ORBSvcConfDirective] [static PBXIOP_Factory '-enable_keepalive'] [-ORBSvcConfDirective] [static EndpointSelectorFactory ''] [-ORBSvcConfDirective] [static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'] [-ORBSvcConfDirective] [static Resource_Factory '-ORBProtocolFactory IIOP_Factory'] [-ORBDefaultInitRef] [] [-ORBSvcConfDirective] [static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'] [-ORBSvcConfDirective] [static Resource_Factory '-ORBConnectionCacheMax 1024'] [-ORBSvcConf] [nul] [-ORBSvcConfDirective] [static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'](Orb.cpp:1003) 00:02:46.456 [5300.6508] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:1017) 00:02:46.456 [5300.6508] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1368) 00:02:46.456 [5300.6508] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1377) 00:02:46.456 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:46.613 [5300.6508] <2> nbjm_media_request: Passing job control to NBJM, type WRITE/1 00:02:46.613 [5300.6508] <2> nbjm_media_request: old_media_id = , media_id = NULL 00:02:46.613 [5300.6508] <2> RequestInitialResources: starting 00:02:46.613 [5300.6508] <2> RequestInitialResources: started 00:02:46.613 [5300.6508] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:797) 00:02:46.613 [5300.6508] <2> Orb::init: Created anon service name: NB_5300_867858460(Orb.cpp:876) 00:02:46.613 [5300.6508] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_5300_867858460(Orb.cpp:886) 00:02:46.613 [5300.6508] <2> Orb::init: initializing ORB Default_DAEMON_Orb with: [Unknown] [-ORBSvcConfDirective] [-ORBDottedDecimalAddresses 0] [-ORBSvcConfDirective] [static Resource_Factory '-ORBNativeCharCodeSet UTF-8'] [-ORBSvcConfDirective] [static PBXIOP_Factory '-enable_keepalive'] [-ORBSvcConfDirective] [static EndpointSelectorFactory ''] [-ORBSvcConfDirective] [static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'] [-ORBSvcConfDirective] [static Resource_Factory '-ORBProtocolFactory IIOP_Factory'] [-ORBDefaultInitRef] [] [-ORBSvcConfDirective] [static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'] [-ORBSvcConfDirective] [static Resource_Factory '-ORBConnectionCacheMax 1024'] [-ORBEndpoint] [pbxiop://1556:NB_5300_867858460] [-ORBSvcConf] [nul] [-ORBSvcConfDirective] [static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'](Orb.cpp:1003) 00:02:46.613 [5300.6508] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:1017) 00:02:55.924 [5300.6508] <2> vnet_dnsquery_filter: [vnet_addrinfo.c:2252] About to DnsQuery() for host myMEDIA.mydomain.dom 00:02:55.924 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:55.924 [5300.6508] <2> vnet_cached_getaddrinfo_and_update: [vnet_addrinfo.c:1704] file cache has expired NAME=mymasterserver.mydomain.dom SVC=NULL 00:02:55.924 [5300.6508] <2> vnet_cached_getaddrinfo_and_update: [vnet_addrinfo.c:1780] found via getaddrinfo NAME=mymasterserver.mydomain.dom SVC=NULL 00:02:55.924 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:56.065 [5300.6508] <2> packageInitialResourceRequest: started 00:02:56.065 [5300.6508] <2> packageInitialResourceRequest: retVal = 0 00:02:56.065 [5300.6508] <2> RequestInitialResources: setting up callback and calling requestResources 00:02:56.065 [5300.6508] <2> logResourceReq: req.versionId : 1 00:02:56.065 [5300.6508] <2> logResourceReq: req.jobId : -1503927022 00:02:56.065 [5300.6508] <2> logResourceReq: req.startedViaJobManager : true 00:02:56.065 [5300.6508] <2> logResourceReq: req.consumer : true 00:02:56.065 [5300.6508] <2> logResourceReq: InitialSTUSelect - 00:02:56.065 [5300.6508] <2> logResourceReq: reqNum : 0 00:02:56.065 [5300.6508] <2> logResourceReq: preferredMediaServer : 00:02:56.065 [5300.6508] <2> logResourceReq: requiredMediaServer : myMEDIA.mydomain.dom 00:02:56.065 [5300.6508] <2> logResourceReq: storageUnit : Media01-NTFS-MSDD 00:02:56.065 [5300.6508] <2> logResourceReq: mustBeNdmp : false 00:02:56.065 [5300.6508] <2> logResourceReq: getMaxFreeSpace : false 00:02:56.065 [5300.6508] <2> logResourceReq: mediaPool : 00:02:56.065 [5300.6508] <2> logResourceReq: shareGroup : 00:02:56.065 [5300.6508] <2> logResourceReq: requestFlags : 0x0 00:02:56.065 [5300.6508] <2> logResourceReq: NDMPHostName : 00:02:56.065 [5300.6508] <2> logResourceReq: changePathOnly : 0 00:02:56.065 [5300.6508] <2> logResourceReq: NDMP cDOT affinity count : 0 00:02:56.065 [5300.6508] <2> logResourceReq: retentionLevel : 2 00:02:56.065 [5300.6508] <2> logResourceReq: mustUseLocalMediaServer : false 00:02:56.065 [5300.6508] <2> logResourceReq: failOnError : false 00:02:56.065 [5300.6508] <2> logResourceReq: mpxRequired : false 00:02:56.065 [5300.6508] <2> logResourceReq: client : vm01 00:02:56.065 [5300.6508] <2> logResourceReq: usageType : 1 00:02:56.096 [5300.6508] <2> RequestInitialResources: BpxmiV->requestResourcesWithTimeout returns 0 00:02:56.127 [5300.6508] <2> vnet_pcache_init_table: [vnet_private.c:214] starting cache size 200 0xc8 00:02:56.127 [5300.6508] <2> vnet_cached_getnameinfo: [vnet_addrinfo.c:2065] found via getnameinfo OUR_HOST=mymasterserver.mydomain.dom IPSTR=192.168.1.100 00:02:56.205 [5300.6508] <2> resourcesAvailable: m_allocationSeq.length() == 1 00:02:56.205 [5300.6508] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 7 00:02:56.205 [5300.6508] <2> resourcesAvailable: MEDIADB 1 1478884 *NULL* 0 *NULL* 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 00:02:56.205 [5300.6508] <2> resourcesAvailable: VOLUME 1 *NULL* 0 *NULL* *NULL* *NULL* *NULL* 0 0 0 0 0 {00000000-0000-0000-0000-000000000000} 0 00:02:56.205 [5300.6508] <2> resourcesAvailable: DRIVE 4 *NULL* 0 *NULL* *NULL* 0 0 0 0 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 0 0 0 1 0 0 00:02:56.205 [5300.6508] <2> resourcesAvailable: STORAGE 1 Media01-NTFS-MSDD 0 524288 0 1 0 0 myMEDIA.mydomain.dommyMEDIA.mydomain.dom*NULL* 00:02:56.205 [5300.6508] <2> resourcesAvailable: DISKGROUP 0 9 BasicDisk 26 myMEDIA.mydomain.dom18 Media01-NTFS-MSDD 00:02:56.205 [5300.6508] <2> resourcesAvailable: DISKVOLUME 0 6 @aaaa1 11 Internal_16 0 00:02:56.205 [5300.6508] <2> resourcesAvailable: DISKMOUNTPOINT 0 10 F:\NBU_07\ 00:02:56.236 [5300.6508] <2> packageInitialResourceRequestResult: totalNumberOfAllocations == 1 00:02:56.236 [5300.6508] <2> packageInitialResourceRequestResult: m_allocationSeq.length=1 00:02:56.236 [5300.6508] <2> packageInitialResourceRequestResult: found MediaAllocation : reqNum == 0 00:02:56.236 [5300.6508] <2> packageInitialResourceRequestResult: matched MediaAllocation to an initialStuReq 00:02:56.236 [5300.6508] <2> packageInitialResourceRequestResult: retVal = 0 00:02:56.236 [5300.6508] <2> RequestInitialResources: retVal = 0 emmStatus = 0 00:02:56.236 [5300.6508] <2> RequestInitialResources: returning 00:02:56.236 [5300.6508] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 1478884 *NULL* 0 *NULL* 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0], length 65 00:02:56.236 [5300.6508] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 *NULL* 0 *NULL* *NULL* *NULL* *NULL* 0 0 0 0 0 {00000000-0000-0000-0000-000000000000} 0], length 96 00:02:56.236 [5300.6508] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 4 *NULL* 0 *NULL* *NULL* 0 0 0 0 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 0 0 0 1 0 0], length 87 00:02:56.236 [5300.6508] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 1 Media01-NTFS-MSDD 0 524288 0 1 0 0 myMEDIA.mydomain.dommyMEDIA.mydomain.dom*NULL*], length 106 00:02:56.236 [5300.6508] <2> populateBptmOpaqueStrings: packaging bptm string [DISKGROUP 0 9 BasicDisk 26 myMEDIA.mydomain.dom18 Media01-NTFS-MSDD], length 75 00:02:56.236 [5300.6508] <2> populateBptmOpaqueStrings: packaging bptm string [DISKVOLUME 0 6 @aaaa1 11 Internal_16 0], length 38 00:02:56.236 [5300.6508] <2> populateBptmOpaqueStrings: packaging bptm string [DISKMOUNTPOINT 0 10 F:\NBU_07\], length 30 00:02:56.236 [5300.6508] <2> populateBptmOpaqueStrings: retVal = 0 00:02:56.236 [5300.6508] <2> parse_resource_strings: MEDIADB 1 1478884 *NULL* 0 *NULL* 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 00:02:56.236 [5300.6508] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters 00:02:56.236 [5300.6508] <2> parse_resource_strings: VOLUME 1 *NULL* 0 *NULL* *NULL* *NULL* *NULL* 0 0 0 0 0 {00000000-0000-0000-0000-000000000000} 0 00:02:56.236 [5300.6508] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters 00:02:56.236 [5300.6508] <2> parse_resource_strings: DRIVE 4 *NULL* 0 *NULL* *NULL* 0 0 0 0 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 0 0 0 1 0 0 00:02:56.236 [5300.6508] <2> parse_resource_strings: Parsed message type 17, version 4, 23 parameters 00:02:56.236 [5300.6508] <2> parse_resource_strings: STORAGE 1 Media01-NTFS-MSDD 0 524288 0 1 0 0 myMEDIA.mydomain.dommyMEDIA.mydomain.dom*NULL* 00:02:56.236 [5300.6508] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters 00:02:56.236 [5300.6508] <2> parse_resource_strings: DISKGROUP 0 9 BasicDisk 26 myMEDIA.mydomain.dom18 Media01-NTFS-MSDD 00:02:56.236 [5300.6508] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters 00:02:56.236 [5300.6508] <2> parse_resource_strings: DISKVOLUME 0 6 @aaaa1 11 Internal_16 0 00:02:56.236 [5300.6508] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters 00:02:56.236 [5300.6508] <2> parse_resource_strings: DISKMOUNTPOINT 0 10 F:\NBU_07\ 00:02:56.236 [5300.6508] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters 00:02:56.236 [5300.6508] <2> nbjm_media_request: Job control returned to BPTM 00:02:56.236 [5300.6508] <2> setup_twin_parameters: ../bptm.c.3896: maximum fragment size is 524288000 Kbytes 00:02:56.236 [5300.6508] <2> validate_parameters: ../common.c.5658: maximum fragment size is 524288000 Kbytes 00:02:56.236 [5300.6508] <2> _open_brm_shmem: bpbrm_handle = 1280, buffer address = 0x2840000 00:02:56.236 [5300.6508] <2> _open_brm_shmem: found index: 0 00:02:56.236 [5300.6508] <2> io_init: using 262144 data buffer size 00:02:56.236 [5300.6508] <2> set_job_details: Tfile (743468): LOG 1503954176 4 bptm 5300 using 262144 data buffer size 00:02:56.236 [5300.6508] <2> send_job_file: job ID 743468, ftype = 3 msg len = 57, msg = LOG 1503954176 4 bptm 5300 using 262144 data buffer size 00:02:56.236 [5300.6508] <2> io_init: CINDEX 0, sched Kbytes for monitoring = 200000 00:02:56.236 [5300.6508] <2> io_set_recvbuf: setting receive network buffer to 1049600 bytes 00:02:56.236 [5300.6508] <2> set_job_details: Tfile (743468): LOG 1503954176 4 bptm 5300 setting receive network buffer to 1049600 bytes 00:02:56.236 [5300.6508] <2> send_job_file: job ID 743468, ftype = 3 msg len = 75, msg = LOG 1503954176 4 bptm 5300 setting receive network buffer to 1049600 bytes 00:02:56.236 [5300.6508] <2> io_set_recvbuf: receive network buffer is 1049600 bytes 00:02:56.236 [5300.6508] <2> io_init: using 30 data buffers 00:02:56.236 [5300.6508] <2> set_job_details: Tfile (743468): LOG 1503954176 4 bptm 5300 using 30 data buffers 00:02:56.236 [5300.6508] <2> send_job_file: job ID 743468, ftype = 3 msg len = 49, msg = LOG 1503954176 4 bptm 5300 using 30 data buffers 00:02:56.236 [5300.6508] <2> io_init: child delay = 10, parent delay = 15 (milliseconds) 00:02:56.236 [5300.6508] <2> create_shared_memory: Created "Global\NetBackup Media Manager SHM Path 48606859 5300" shared memory file. 00:02:56.236 [5300.6508] <2> create_shared_memory: shm_size = 7865048, buffer address = 0x0000000003DA0000, buf control = 0x0000000004520000, ready ptr = 0x00000000045202D0 00:02:56.236 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts load_plugins() 17/08/29 00:02:56: opening plugin directory C:\Program Files\Veritas\NetBackup\bin\ 00:02:56.236 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\libstspibasicdisk.dll 00:02:56.236 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\libstspicorba.dll 00:02:56.236 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\libstspicp.dll 00:02:56.236 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\libstspinearstore.dll 00:02:56.236 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\libstspishmem.dll 00:02:56.236 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts load_plugins() 17/08/29 00:02:56: opening plugin directory C:\Program Files\Veritas\NetBackup\bin\\ost-plugins 00:02:56.236 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspiamazon.dll 00:02:56.236 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspiatt.dll 00:02:56.236 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspiazure.dll 00:02:56.236 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspicompress.dll 00:02:56.252 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspiemc_celerra.dll 00:02:56.252 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspiencrypt.dll 00:02:56.252 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspigateway.dll 00:02:56.252 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspimetering.dll 00:02:56.252 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspipd.dll 00:02:56.252 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspirackspace.dll 00:02:56.252 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspisoapwrapper.dll 00:02:56.252 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspiswift.dll 00:02:56.252 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspithrottling.dll 00:02:56.252 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts openp() 17/08/29 00:02:56: opening module C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspizapi.dll 00:02:56.252 [5300.6508] <2> get_plugin_version: libstspibasicdisk.dll (STSBasicDisk:==STSBasicDisk:) build=11.2 operating=11 vendor <800000 NetBackup_8.0> 00:02:56.252 [5300.6508] <2> bp_sts_open_server: plugin version = 11 00:02:56.252 [5300.6508] <4> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts setupp() 17/08/29 00:02:56: STSBasicDisk:myMEDIA.mydomain.domclaimed by C:\Program Files\Veritas\NetBackup\bin\\libstspibasicdisk.dll 00:02:56.252 [5300.6508] <4> 743468:bptm:5300:myMEDIA.mydomain.dom: libsts setupp() 17/08/29 00:02:56: STSBasicDisk:myMEDIA.mydomain.domclaimed by C:\Program Files\Veritas\NetBackup\bin\\libstspibasicdisk.dll 00:02:56.252 [5300.6508] <2> bptm: STS attach host is myMEDIA.mydomain.dom 00:02:56.252 [5300.6508] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mymasterserver.mydomain.dom, query type 21 00:02:56.252 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:56.252 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:56.252 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:56.252 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:56.252 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:56.252 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:56.252 [5300.6508] <2> async_connect: [vnet_connect.c:1508] connect in progress 1 0x1 00:02:56.315 [5300.6508] <2> vnet_pbxConnect: pbxConnectEx Succeeded 00:02:56.315 [5300.6508] <2> do_pbx_service: [vnet_connect.c:2194] via PBX bpdbm CONNECT FROM 192.168.2.200.63134 TO 192.168.1.100.1556 fd = 1288 00:02:56.315 [5300.6508] <2> async_connect: [vnet_connect.c:1700] connect async CONNECT FROM 192.168.2.200.63134 TO 192.168.1.100.1556 fd = 1288 00:02:56.315 [5300.6508] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mymasterserver.mydomain.dom 192.168.1.100 bpdbm VIA pbx 00:02:56.315 [5300.6508] <2> logconnections: BPDBM CONNECT FROM 192.168.2.200.63134 TO 192.168.1.100.1556 fd = 1288 00:02:56.315 [5300.6508] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:1115] Ignoring VxSS authentication 2 0x2 00:02:56.533 [5300.6508] <2> db_end: Need to collect reply 00:02:56.549 [5300.6508] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mymasterserver.mydomain.dom, query type 1 00:02:56.549 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:56.549 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:56.549 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:56.549 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:56.549 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:56.549 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:56.549 [5300.6508] <2> async_connect: [vnet_connect.c:1508] connect in progress 1 0x1 00:02:56.596 [5300.6508] <2> vnet_pbxConnect: pbxConnectEx Succeeded 00:02:56.596 [5300.6508] <2> do_pbx_service: [vnet_connect.c:2194] via PBX bpdbm CONNECT FROM 192.168.2.200.63135 TO 192.168.1.100.1556 fd = 1288 00:02:56.596 [5300.6508] <2> async_connect: [vnet_connect.c:1700] connect async CONNECT FROM 192.168.2.200.63135 TO 192.168.1.100.1556 fd = 1288 00:02:56.596 [5300.6508] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mymasterserver.mydomain.dom 192.168.1.100 bpdbm VIA pbx 00:02:56.596 [5300.6508] <2> logconnections: BPDBM CONNECT FROM 192.168.2.200.63135 TO 192.168.1.100.1556 fd = 1288 00:02:56.596 [5300.6508] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:1115] Ignoring VxSS authentication 2 0x2 00:02:56.768 [5300.6508] <2> db_end: Need to collect reply 00:02:56.803 [5300.6508] <4> report_client: VBRC 3 5300 1 vm01_1503954160 40 Policy01 1 Diff 0 1 1 00:02:56.803 [5300.6508] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mymasterserver.mydomain.dom, query type 81 00:02:56.803 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:56.803 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:56.803 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:56.803 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:56.803 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:56.803 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:56.803 [5300.6508] <2> async_connect: [vnet_connect.c:1508] connect in progress 1 0x1 00:02:56.865 [5300.6508] <2> vnet_pbxConnect: pbxConnectEx Succeeded 00:02:56.865 [5300.6508] <2> do_pbx_service: [vnet_connect.c:2194] via PBX bpdbm CONNECT FROM 192.168.2.200.63136 TO 192.168.1.100.1556 fd = 1288 00:02:56.865 [5300.6508] <2> async_connect: [vnet_connect.c:1700] connect async CONNECT FROM 192.168.2.200.63136 TO 192.168.1.100.1556 fd = 1288 00:02:56.865 [5300.6508] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mymasterserver.mydomain.dom 192.168.1.100 bpdbm VIA pbx 00:02:56.865 [5300.6508] <2> logconnections: BPDBM CONNECT FROM 192.168.2.200.63136 TO 192.168.1.100.1556 fd = 1288 00:02:56.865 [5300.6508] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:1115] Ignoring VxSS authentication 2 0x2 00:02:57.099 [5300.6508] <2> db_end: Need to collect reply 00:02:57.131 [5300.6508] <2> setup_back_header: setup vm_type = 2 00:02:57.131 [5300.6508] <2> set_job_details: Tfile (743468): LOG 1503954177 4 bptm 5300 start backup 00:02:57.131 [5300.6508] <2> send_job_file: job ID 743468, ftype = 3 msg len = 40, msg = LOG 1503954177 4 bptm 5300 start backup 00:02:57.131 [5300.6508] <2> stu_name_to_monitor: job_id = 743468 00:02:57.131 [5300.6508] <2> stu_name_to_monitor: stuName = 'Media01-NTFS-MSDD' 00:02:57.131 [5300.6508] <2> set_job_details: jobData (743468) 00:02:57.131 [5300.6508] <2> send_structure_data: Index 26 Field m_szDstStorage_unit Value 00:02:57.131 [5300.6508] <2> create_basicdisk_lsu: entry F:\NBU_07\ 0 00000000028005F0 00:02:57.131 [5300.6508] <2> path_on_root: LSU F:\NBU_07\ is not a network share, continue processing 00:02:57.131 [5300.6508] <2> path_on_root: windows system volume is \\?\Volume{70ffd21f-1564-4234-98d8-a9133a122f14}\ 00:02:57.131 [5300.6508] <2> path_on_root: LSU F:\NBU_07\ volume name is \\?\Volume{6e10d6a0-ba0c-4a7c-9ca3-5c6ca8d84bc5}\ 00:02:57.131 [5300.6508] <2> bp_sts_get_lsu: entry F:\NBU_07\ 00:02:57.131 [5300.6508] <4> 743468:bptm:5300:myMEDIA.mydomain.dom: STSBasicDisk: LSU is Basic Disk 00:02:57.131 [5300.6508] <4> 743468:bptm:5300:myMEDIA.mydomain.dom: STSBasicDisk: LSU is Basic Disk 00:02:57.131 [5300.6508] <4> 743468:bptm:5300:myMEDIA.mydomain.dom: STSBasicDisk: LSU is Basic Disk 00:02:57.131 [5300.6508] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mymasterserver.mydomain.dom, query type 81 00:02:57.131 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:57.131 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:57.131 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:57.131 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:57.131 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:57.131 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:57.131 [5300.6508] <2> async_connect: [vnet_connect.c:1508] connect in progress 1 0x1 00:02:57.178 [5300.6508] <2> vnet_pbxConnect: pbxConnectEx Succeeded 00:02:57.178 [5300.6508] <2> do_pbx_service: [vnet_connect.c:2194] via PBX bpdbm CONNECT FROM 192.168.2.200.63137 TO 192.168.1.100.1556 fd = 1484 00:02:57.178 [5300.6508] <2> async_connect: [vnet_connect.c:1700] connect async CONNECT FROM 192.168.2.200.63137 TO 192.168.1.100.1556 fd = 1484 00:02:57.178 [5300.6508] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mymasterserver.mydomain.dom 192.168.1.100 bpdbm VIA pbx 00:02:57.178 [5300.6508] <2> logconnections: BPDBM CONNECT FROM 192.168.2.200.63137 TO 192.168.1.100.1556 fd = 1484 00:02:57.178 [5300.6508] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:1115] Ignoring VxSS authentication 2 0x2 00:02:57.416 [5300.6508] <2> db_end: Need to collect reply 00:02:57.416 [5300.6508] <4> write_disk_header: Data Classification & Storage Lifecycle action 5 00:02:57.416 [5300.6508] <2> construct_sts_isid: master_server mymasterserver.mydomain.dom, client vm01, backup_time 1503954160, copy_number 1, stream_number 1104, fragment_number 0, resume_number 0, spl_name NULL 00:02:57.416 [5300.6508] <2> bp_sts_open_image: STH set to STS_SA_IMAGE 00:02:57.416 [5300.6508] <2> bp_sts_open_image: STSBasicDisk:myMEDIA.mydomain.domF:\NBU_07\ vm01_1503954160_C1_HDR 1 1 1 sth 0 2 8 LSU 0x7 0x1 0x2 saveas 0x4, stream_type 0x4 fscp 0 00:02:57.416 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: entering stspi_create_image(4) 00:02:57.447 [5300.6508] <2> bp_sts_close_image: 0000000003BAD550 0 1 4 1 1 1 0 complete flag (64)(M_BACKUP_COMPLETE ), close type (1)(STS_CLOSEF_IH_COMPLETE ) 11 00:02:57.494 [5300.6508] <2> construct_sts_isid: master_server mymasterserver.mydomain.dom, client vm01, backup_time 1503954160, copy_number 1, stream_number 1104, fragment_number 1, resume_number 0, spl_name NULL 00:02:57.494 [5300.6508] <2> bp_sts_open_image: STH set to STS_SA_IMAGE 00:02:57.494 [5300.6508] <2> bp_sts_open_image: STSBasicDisk:myMEDIA.mydomain.domF:\NBU_07\ vm01_1503954160_C1_F1 1 1 1 sth 0 2 8 LSU 0x7 0x1 0x2 saveas 0x4, stream_type 0x4 fscp 0 00:02:57.494 [5300.6508] <2> 743468:bptm:5300:myMEDIA.mydomain.dom: entering stspi_create_image(4) 00:02:57.525 [5300.6508] <2> io_open_disk: file vm01_1503954160_C1_F1 successfully opened 00:02:57.525 [5300.6508] <2> bp_sts_is_filesystem_exported: Storage host myMEDIA.mydomain.domis not a nearstore 00:02:57.525 [5300.6508] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mymasterserver.mydomain.dom, query type 77 00:02:57.525 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:57.525 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:57.525 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:57.525 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:57.525 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:57.525 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:57.525 [5300.6508] <2> async_connect: [vnet_connect.c:1508] connect in progress 1 0x1 00:02:57.572 [5300.6508] <2> vnet_pbxConnect: pbxConnectEx Succeeded 00:02:57.572 [5300.6508] <2> do_pbx_service: [vnet_connect.c:2194] via PBX bpdbm CONNECT FROM 192.168.2.200.63138 TO 192.168.1.100.1556 fd = 1480 00:02:57.572 [5300.6508] <2> async_connect: [vnet_connect.c:1700] connect async CONNECT FROM 192.168.2.200.63138 TO 192.168.1.100.1556 fd = 1480 00:02:57.572 [5300.6508] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mymasterserver.mydomain.dom 192.168.1.100 bpdbm VIA pbx 00:02:57.572 [5300.6508] <2> logconnections: BPDBM CONNECT FROM 192.168.2.200.63138 TO 192.168.1.100.1556 fd = 1480 00:02:57.572 [5300.6508] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:1115] Ignoring VxSS authentication 2 0x2 00:02:57.760 [5300.6508] <2> db_end: Need to collect reply 00:02:57.823 [5300.6508] <2> add_disk_frag: added disk fragment for backupid vm01_1503954160, copy 1, fragment 1 mediaid F:\NBU_07\\vm01_1503954160_C1_F1 input id is NONE 00:02:57.823 [5300.6508] <2> add_disk_frag: media type = 0, media_subtype = 1 00:02:57.823 [5300.6508] <2> write_backup: backup child process is pid 4596.2092 00:02:57.823 [5300.6508] <2> set_job_details: Tfile (743468): LOG 1503954177 4 bptm 5300 backup child process is pid 4596.2092 00:02:57.823 [5300.6508] <2> send_job_file: job ID 743468, ftype = 3 msg len = 65, msg = LOG 1503954177 4 bptm 5300 backup child process is pid 4596.2092 00:02:57.823 [5300.6508] <2> ConnectionCache::connectAndCache: Acquiring new connection for host mymasterserver.mydomain.dom, query type 1 00:02:57.823 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:57.823 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:57.823 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:57.823 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:57.823 [5300.6508] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:57.823 [5300.6508] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:57.823 [5300.6508] <2> async_connect: [vnet_connect.c:1508] connect in progress 1 0x1 00:02:57.855 [4596.2092] <2> initialize: fd values STDOUTSOCK=512 STDERRSOCK=608 00:02:57.855 [4596.2092] <2> bptm: instance - 48618343 00:02:57.855 [4596.2092] <2> bptm: INITIATING (VERBOSE = 5): -w -pid 7920 -c vm01 -dpath F:\NBU_07\ -stunit Media01-NTFS-MSDD -cl Policy01 -bt 1503954160 -b vm01_1503954160 -st 1 -cj 1 -reqid -1503927022 -vm 2 -jm -brm -hostname vm01 -ru root -rclnt vm01 -rclnthostname vm01 -rl 2 -rp 604800 -sl Diff -ct 40 -maxfrag 524288 -eari 0 -mediasvr myMEDIA.mydomain.dom-ifr -no_callback -connect_options 0x01010100 -jobid 743468 -jobgrpid 743460 -masterversion 800000 -bpbrm_shm_id Global\NetBackup_BPBRM_SHM_Path_48606250_7920_7040 -blks_per_buffer 512 -mmfill 5300 0 262144 30 10 48606859 0 1503954160 1 Policy01 vm01 vm01_1503954160 00:02:57.855 [4596.2092] <2> main: ../bptm.c.1527: maximum fragment size is 524288000 Kbytes 00:02:57.855 [4596.2092] <2> bptm: PORT_STATUS = 0x01010100 00:02:57.855 [4596.2092] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:57.855 [4596.2092] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:57.855 [4596.2092] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:57.855 [4596.2092] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:57.855 [4596.2092] <2> vnet_sortaddrs: [vnet_addrinfo.c:4008] sorted addrs: 1 0x1 00:02:57.855 [4596.2092] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:57.855 [4596.2092] <2> async_connect: [vnet_connect.c:1508] connect in progress 1 0x1 00:02:57.886 [5300.6508] <2> vnet_pbxConnect: pbxConnectEx Succeeded 00:02:57.886 [5300.6508] <2> do_pbx_service: [vnet_connect.c:2194] via PBX bpdbm CONNECT FROM 192.168.2.200.63139 TO 192.168.1.100.1556 fd = 736 00:02:57.886 [5300.6508] <2> async_connect: [vnet_connect.c:1700] connect async CONNECT FROM 192.168.2.200.63139 TO 192.168.1.100.1556 fd = 736 00:02:57.886 [5300.6508] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mymasterserver.mydomain.dom 192.168.1.100 bpdbm VIA pbx 00:02:57.886 [5300.6508] <2> logconnections: BPDBM CONNECT FROM 192.168.2.200.63139 TO 192.168.1.100.1556 fd = 736 00:02:57.886 [5300.6508] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:1115] Ignoring VxSS authentication 2 0x2 00:02:57.917 [4596.2092] <2> vnet_pbxConnect: pbxConnectEx Succeeded 00:02:57.917 [4596.2092] <2> do_pbx_service: [vnet_connect.c:2194] via PBX bpjobd CONNECT FROM 192.168.2.200.63140 TO 192.168.1.100.1556 fd = 864 00:02:57.917 [4596.2092] <2> async_connect: [vnet_connect.c:1700] connect async CONNECT FROM 192.168.2.200.63140 TO 192.168.1.100.1556 fd = 864 00:02:57.917 [4596.2092] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO mymasterserver.mydomain.dom 192.168.1.100 bpjobd VIA pbx 00:02:57.917 [4596.2092] <2> job_connect: SO_KEEPALIVE set on socket 864 for client mymasterserver.mydomain.dom 00:02:57.917 [4596.2092] <2> logconnections: BPJOBD CONNECT FROM 192.168.2.200.63140 TO 192.168.1.100.1556 fd = 864 00:02:57.917 [4596.2092] <2> job_authenticate_connection: VxSS authentication check for now... 00:02:57.917 [4596.2092] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:1115] Ignoring VxSS authentication 2 0x2 00:02:57.948 [4596.2092] <2> job_connect: Connected to the host mymasterserver.mydomain.dom contype 53 jobid <743468> socket <864> 00:02:57.948 [4596.2092] <2> job_connect: Connected on port 63140 00:02:57.948 [4596.2092] <2> set_job_details: Tfile (743468): LOG 1503954177 4 bptm 4596 start 00:02:57.948 [4596.2092] <2> send_job_file: job ID 743468, ftype = 3 msg len = 33, msg = LOG 1503954177 4 bptm 4596 start 00:02:57.948 [4596.2092] <2> __tl_initdir__: name:, result:<1> 00:02:57.948 [4596.2092] <2> _tl_opendir_: name:, result:<1> 00:02:57.948 [4596.2092] <4> bptm: emmserver_name = mymasterserver 00:02:57.948 [4596.2092] <4> bptm: emmserver_port = 1556 00:02:57.964 [4596.2092] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:797) 00:02:57.964 [4596.2092] <2> Orb::init: initializing ORB EMMlib_Orb with: [bptm] [-ORBSvcConfDirective] [-ORBDottedDecimalAddresses 0] [-ORBSvcConfDirective] [static Resource_Factory '-ORBNativeCharCodeSet UTF-8'] [-ORBSvcConfDirective] [static PBXIOP_Factory '-enable_keepalive'] [-ORBSvcConfDirective] [static EndpointSelectorFactory ''] [-ORBSvcConfDirective] [static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'] [-ORBSvcConfDirective] [static Resource_Factory '-ORBProtocolFactory IIOP_Factory'] [-ORBDefaultInitRef] [] [-ORBSvcConfDirective] [static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'] [-ORBSvcConfDirective] [static Resource_Factory '-ORBConnectionCacheMax 1024'] [-ORBSvcConf] [nul] [-ORBSvcConfDirective] [static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'](Orb.cpp:1003) 00:02:57.964 [4596.2092] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:1017) 00:02:57.964 [4596.2092] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1368) 00:02:57.964 [4596.2092] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1377) 00:02:57.964 [4596.2092] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4965] using interface ANY 00:02:58.073 [5300.6508] <2> db_end: Need to collect reply 00:02:58.105 [5300.6508] <4> write_backup: begin writing backup id vm01_1503954160, copy 1, fragment 1, destination path F:\NBU_07\ 00:02:58.105 [5300.6508] <2> signal_parent: set bpbrm media ready event (pid = 7920) 00:02:58.105 [5300.6508] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 1 delay_brm: 0 00:02:58.105 [5300.6508] <2> ndmp_setup_for_write: CINDEX 0, TWIN_INDEX 0, IS_NDMP 0, is_tir 0 00:02:58.105 [4596.2092] <2> allocate_local_mpx_control: ../mpx.c.401: VNETD_STRING: 00:02:58.120 [4596.2092] <2> setup_mm_child: [5300] child using 30 data buffers 00:02:58.120 [4596.2092] <2> setup_mm_child: [5300] child buffer size is 262144 00:02:58.120 [4596.2092] <2> setup_mm_child: [5300] buffer address = 0x3d90000, buf control = 0x4510000 00:04:07.236 [5300.6508] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 0 finished_buff: 0 00:04:07.236 [5300.6508] <2> write_data: received first buffer (262144 bytes), begin writing data 00:04:07.236 [5300.6508] <2> send_media_kbytes_written_establish_threshold: CINDEX 0, RB Kbytes for monitoring = 3000000