00:02:23.118 [409846] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 00:02:23.130 [409846] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 00:02:23.130 [409846] <2> bptm: EXITING with status 0 <---------- 00:09:28.164 [209076] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007639 -jm 00:09:28.176 [209076] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 00:09:28.176 [209076] <2> bptm: PORT_STATUS = 0x00000000 00:09:28.176 [209076] <2> main: Sending [EXIT STATUS 0] to NBJM 00:09:28.176 [209076] <2> bptm: EXITING with status 0 <---------- 00:13:02.230 [208898] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 00:13:02.242 [208898] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 00:13:02.242 [208898] <2> bptm: EXITING with status 0 <---------- 00:19:28.343 [446656] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007643 -jm 00:19:28.356 [446656] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 00:19:28.356 [446656] <2> bptm: PORT_STATUS = 0x00000000 00:19:28.356 [446656] <2> main: Sending [EXIT STATUS 0] to NBJM 00:19:28.356 [446656] <2> bptm: EXITING with status 0 <---------- 00:23:15.864 [479266] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 00:23:15.876 [479266] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 00:23:15.876 [479266] <2> bptm: EXITING with status 0 <---------- 00:29:28.343 [479364] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007648 -jm 00:29:28.355 [479364] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 00:29:28.356 [479364] <2> bptm: PORT_STATUS = 0x00000000 00:29:28.356 [479364] <2> main: Sending [EXIT STATUS 0] to NBJM 00:29:28.356 [479364] <2> bptm: EXITING with status 0 <---------- 00:33:26.324 [409800] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 00:33:26.336 [409800] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 00:33:26.337 [409800] <2> bptm: EXITING with status 0 <---------- 00:39:28.516 [405678] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007651 -jm 00:39:28.529 [405678] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 00:39:28.529 [405678] <2> bptm: PORT_STATUS = 0x00000000 00:39:28.529 [405678] <2> main: Sending [EXIT STATUS 0] to NBJM 00:39:28.529 [405678] <2> bptm: EXITING with status 0 <---------- 00:43:40.010 [405634] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 00:43:40.022 [405634] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 00:43:40.022 [405634] <2> bptm: EXITING with status 0 <---------- 00:49:29.123 [409722] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007656 -jm 00:49:29.135 [409722] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 00:49:29.135 [409722] <2> bptm: PORT_STATUS = 0x00000000 00:49:29.136 [409722] <2> main: Sending [EXIT STATUS 0] to NBJM 00:49:29.136 [409722] <2> bptm: EXITING with status 0 <---------- 00:53:50.672 [409640] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 00:53:50.685 [409640] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 00:53:50.685 [409640] <2> bptm: EXITING with status 0 <---------- 00:59:29.847 [409612] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007663 -jm 00:59:29.859 [409612] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 00:59:29.859 [409612] <2> bptm: PORT_STATUS = 0x00000000 00:59:29.860 [409612] <2> main: Sending [EXIT STATUS 0] to NBJM 00:59:29.860 [409612] <2> bptm: EXITING with status 0 <---------- 01:04:06.956 [520410] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 01:04:06.967 [520410] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 01:04:06.968 [520410] <2> bptm: EXITING with status 0 <---------- 01:09:28.249 [446488] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007668 -jm 01:09:28.261 [446488] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 01:09:28.261 [446488] <2> bptm: PORT_STATUS = 0x00000000 01:09:28.261 [446488] <2> main: Sending [EXIT STATUS 0] to NBJM 01:09:28.261 [446488] <2> bptm: EXITING with status 0 <---------- 01:14:30.746 [446634] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 01:14:30.758 [446634] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 01:14:30.758 [446634] <2> bptm: EXITING with status 0 <---------- 01:19:28.168 [520356] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007673 -jm 01:19:28.180 [520356] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 01:19:28.180 [520356] <2> bptm: PORT_STATUS = 0x00000000 01:19:28.181 [520356] <2> main: Sending [EXIT STATUS 0] to NBJM 01:19:28.181 [520356] <2> bptm: EXITING with status 0 <---------- 01:24:46.105 [483456] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 01:24:46.117 [483456] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 01:24:46.117 [483456] <2> bptm: EXITING with status 0 <---------- 01:29:28.109 [520406] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007680 -jm 01:29:28.121 [520406] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 01:29:28.122 [520406] <2> bptm: PORT_STATUS = 0x00000000 01:29:28.122 [520406] <2> main: Sending [EXIT STATUS 0] to NBJM 01:29:28.122 [520406] <2> bptm: EXITING with status 0 <---------- 01:35:04.449 [405520] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 01:35:04.461 [405520] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 01:35:04.462 [405520] <2> bptm: EXITING with status 0 <---------- 01:39:28.717 [483378] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007685 -jm 01:39:28.729 [483378] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 01:39:28.730 [483378] <2> bptm: PORT_STATUS = 0x00000000 01:39:28.730 [483378] <2> main: Sending [EXIT STATUS 0] to NBJM 01:39:28.730 [483378] <2> bptm: EXITING with status 0 <---------- 01:45:15.693 [606316] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 01:45:15.705 [606316] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 01:45:15.705 [606316] <2> bptm: EXITING with status 0 <---------- 01:49:31.640 [405684] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007690 -jm 01:49:31.652 [405684] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 01:49:31.652 [405684] <2> bptm: PORT_STATUS = 0x00000000 01:49:31.652 [405684] <2> main: Sending [EXIT STATUS 0] to NBJM 01:49:31.653 [405684] <2> bptm: EXITING with status 0 <---------- 01:55:26.437 [540744] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 01:55:26.449 [540744] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 01:55:26.449 [540744] <2> bptm: EXITING with status 0 <---------- 01:59:27.962 [540864] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007698 -jm 01:59:27.974 [540864] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 01:59:27.974 [540864] <2> bptm: PORT_STATUS = 0x00000000 01:59:27.975 [540864] <2> main: Sending [EXIT STATUS 0] to NBJM 01:59:27.975 [540864] <2> bptm: EXITING with status 0 <---------- 02:05:36.066 [540708] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 02:05:36.078 [540708] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:05:36.078 [540708] <2> bptm: EXITING with status 0 <---------- 02:09:28.505 [516154] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007703 -jm 02:09:28.517 [516154] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:09:28.517 [516154] <2> bptm: PORT_STATUS = 0x00000000 02:09:28.517 [516154] <2> main: Sending [EXIT STATUS 0] to NBJM 02:09:28.517 [516154] <2> bptm: EXITING with status 0 <---------- 02:15:56.818 [606222] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 02:15:56.830 [606222] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:15:56.830 [606222] <2> bptm: EXITING with status 0 <---------- 02:19:28.035 [446654] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007706 -jm 02:19:28.047 [446654] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:19:28.047 [446654] <2> bptm: PORT_STATUS = 0x00000000 02:19:28.047 [446654] <2> main: Sending [EXIT STATUS 0] to NBJM 02:19:28.047 [446654] <2> bptm: EXITING with status 0 <---------- 02:26:25.680 [606252] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 02:26:25.692 [606252] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:26:25.692 [606252] <2> bptm: EXITING with status 0 <---------- 02:29:27.989 [606268] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007713 -jm 02:29:28.001 [606268] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:29:28.001 [606268] <2> bptm: PORT_STATUS = 0x00000000 02:29:28.001 [606268] <2> main: Sending [EXIT STATUS 0] to NBJM 02:29:28.001 [606268] <2> bptm: EXITING with status 0 <---------- 02:36:46.259 [540678] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 02:36:46.271 [540678] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:36:46.271 [540678] <2> bptm: EXITING with status 0 <---------- 02:39:28.325 [483524] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007717 -jm 02:39:28.337 [483524] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:39:28.338 [483524] <2> bptm: PORT_STATUS = 0x00000000 02:39:28.338 [483524] <2> main: Sending [EXIT STATUS 0] to NBJM 02:39:28.338 [483524] <2> bptm: EXITING with status 0 <---------- 02:47:06.219 [409838] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 02:47:06.231 [409838] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:47:06.231 [409838] <2> bptm: EXITING with status 0 <---------- 02:49:29.667 [405702] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007721 -jm 02:49:29.680 [405702] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:49:29.680 [405702] <2> bptm: PORT_STATUS = 0x00000000 02:49:29.680 [405702] <2> main: Sending [EXIT STATUS 0] to NBJM 02:49:29.680 [405702] <2> bptm: EXITING with status 0 <---------- 02:56:24.617 [405724] <2> bptm: INITIATING (VERBOSE = 5): -pid 409754 -den 6 -rt 8 -rn 0 -cj 8 -mpx 32 -reqid -1389007725 -jm -brm -p NetBackup -stunit aixbk-hcart-robot-tld-0 -maxfrag 1048576 -v -masterversion 600000 -mediasvr aixbk -bpbrm_shm_id 42991626 -blks_per_buffer 512 02:56:24.629 [405724] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:56:24.629 [405724] <2> main: bptm.c.1622: maximum fragment size is 1048576000 Kbytes 02:56:24.629 [405724] <2> bptm: PORT_STATUS = 0x00000000 02:56:24.636 [405724] <2> hosts_equal: The second name is empty 02:56:24.648 [405724] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:56:24.648 [405724] <2> hosts_equal: Comparing hosts and 02:56:24.648 [405724] <2> hosts_equal: names are the same 02:56:24.648 [405724] <4> bptm: emmserver_name = hqmb1 02:56:24.648 [405724] <4> bptm: emmserver_port = 1556 02:56:24.662 [405724] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:56:24.706 [405724] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name 02:56:24.706 [405724] <2> VssInit: vss_auth.cpp.720: Function: VssInit. Using Cached entries FALSE 02:56:24.708 [405724] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name AIXBK 02:56:24.750 [405724] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:56:24.776 [405724] <2> hosts_equal: Comparing hosts and 02:56:24.776 [405724] <2> hosts_equal: names are the same 02:56:24.776 [405724] <4> db_getSTUNIT: EMM interface already initialized (using cached master name hqmb1). 02:56:24.826 [405724] <2> setup_twin_parameters: bptm.c.3860: maximum fragment size is 1048576000 Kbytes 02:56:24.826 [405724] <2> send_brm_msg: PID of bpxm = 405724 02:56:24.829 [405724] <2> process_mpx_protocol: wait for initial START BACKUP message from bpbrm 02:56:31.829 [405724] <2> read_brm_msg: START BACKUP -b AIXBK_1389553208 -bt 1389553208 -c AIXBK -cl AIXBK_FS_RAIL_FLASH -st 0 -rl 2 -rp 2419200 -sl Daily -ct 0 -hostname AIXBK -rclnt AIXBK -rclnthostname AIXBK -bclnt AIXBK -bclnthostname AIXBK -ru root -shm -no_callback -connect_options 0x01020100 -jobid 808076 -jobgrpid 808076 02:56:31.829 [405724] <2> validate_parameters: tmcommon.c.4449: maximum fragment size is 1048576000 Kbytes 02:56:31.829 [405724] <2> io_init: bpbrm_shm_id = 42991626, buffer address = 0x30000000 02:56:31.829 [405724] <2> io_init: found index: 0 02:56:31.829 [405724] <2> io_init: using 262144 data buffer size 02:56:31.829 [405724] <2> io_init: CINDEX 0, sched Kbytes for monitoring = 60000 02:56:31.829 [405724] <2> io_init: using 64 data buffers 02:56:31.829 [405724] <2> io_init: child delay = 20, parent delay = 30 (milliseconds) 02:56:31.843 [405724] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 02:56:31.896 [405724] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 02:56:31.896 [405724] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 02:56:32.131 [405724] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 02:56:32.131 [405724] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.34887 TO 10.2.21.10.13724 fd = 13 02:56:32.131 [405724] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.34887 TO 10.2.21.10.13724 02:56:32.131 [405724] <2> vauth_get_user_name: vauth_comm.c.726: cached_user_name: root 02:56:32.131 [405724] <2> vauth_get_user_name: vauth_comm.c.728: cached_user_name: :root 02:56:32.131 [405724] <2> vauth_get_user_name: vauth_comm.c.734: user_name: :root 02:56:32.131 [405724] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 02:56:32.131 [405724] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 02:56:32.131 [405724] <2> check_authentication: no authentication required 02:56:32.131 [405724] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 02:56:32.131 [405724] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 02:56:32.596 [405724] <2> mpx_setup_shm: buffer control shared memory address is 0x40000000, size is 49280, shmid is 20971532 02:56:32.596 [405724] <2> mpx_setup_shm: buf control for CINDEX 0 is 0x40000000 02:56:32.596 [405724] <2> mpx_setup_shm: shared memory address for group 0 is 0x50000000, size is 67108864, shmid is 34603019 02:56:32.596 [405724] <2> mpx_setup_shm: shared memory address for CINDEX 0 is 0x50000000, group 0, num_active 1 02:56:32.606 [405724] <2> setup_bpbkar_info: /usr/openv/netbackup/db/config/shm/AIXBK_1389553208 file successfully created 02:56:32.606 [405724] <2> get_data_socket: tmmpx.c.3453: port_status: 16908544 16908544 0x01020100 02:56:32.606 [405724] <2> get_data_socket: tmmpx.c.3454: shm_method: 1 1 0x00000001 02:56:32.606 [405724] <2> get_data_socket: tmmpx.c.3457: client_hostname: AIXBK 02:56:32.606 [405724] <2> nb_bind_on_port_addr: bound to port 2801 02:56:32.606 [405724] <2> get_data_socket: tmmpx.c.3522: *port: 2801 2801 0x00000af1 02:56:32.606 [405724] <2> get_data_socket: tmmpx.c.3523: mpx_ipc: 02:56:32.606 [405724] <2> mpx_start_child: tmmpx.c.1150: Calling: send_brm_msg(BRM_PORT) 02:56:32.606 [405724] <2> send_brm_msg: DATASOCKET AIXBK_1389553208 2801 02:56:32.606 [405724] <2> mpx_start_child: tmmpx.c.1155: Calling: bpcr_get_socket_rqst2 02:56:32.606 [405724] <2> mpx_start_child: tmmpx.c.1232: Calling: bpcr_get_socket_rqst4 02:56:33.800 [405724] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 02:56:33.852 [405724] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 02:56:33.852 [405724] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 02:56:34.048 [405724] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 02:56:34.048 [405724] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.34892 TO 10.2.21.10.13724 fd = 13 02:56:34.048 [405724] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.34892 TO 10.2.21.10.13724 02:56:34.048 [405724] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 02:56:34.048 [405724] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 02:56:34.048 [405724] <2> check_authentication: no authentication required 02:56:34.048 [405724] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 02:56:34.048 [405724] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 02:56:34.596 [405724] <2> nbjm_media_request: Passing job control to NBJM, type WRITE 02:56:34.596 [405724] <2> RequestMultipleResources: starting 02:56:34.596 [405724] <2> RequestMultipleResources: started 02:56:34.604 [405724] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name 02:56:34.604 [405724] <2> VssInit: vss_auth.cpp.720: Function: VssInit. Using Cached entries FALSE 02:56:34.604 [405724] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name AIXBK 02:56:34.672 [405724] <2> packageMultiResourceRequest: started 02:56:34.672 [405724] <2> packageMultiResourceRequest: retVal = 0 02:56:34.672 [405724] <2> RequestMultipleResources: setting up callback and calling requestResources 02:56:34.672 [405724] <2> logResourceReq: req.versionId : 1 02:56:34.672 [405724] <2> logResourceReq: req.jobId : -1389007725 02:56:34.672 [405724] <2> logResourceReq: req.startedViaJobManager : true 02:56:34.672 [405724] <2> logResourceReq: req.consumer : true 02:56:34.672 [405724] <2> logResourceReq: STUSelect - 02:56:34.672 [405724] <2> logResourceReq: reqNum : 0 02:56:34.672 [405724] <2> logResourceReq: mediaServer : AIXBK 02:56:34.672 [405724] <2> logResourceReq: oldMediaId : 02:56:34.672 [405724] <2> logResourceReq: previousFailed : false 02:56:34.672 [405724] <2> logResourceReq: storageUnit : aixbk-hcart-robot-tld-0 02:56:34.672 [405724] <2> logResourceReq: mustBeNdmp : false 02:56:34.672 [405724] <2> logResourceReq: getMaxFreeSpace : false 02:56:34.672 [405724] <2> logResourceReq: mediaPool : NetBackup 02:56:34.672 [405724] <2> logResourceReq: retentionLevel : 2 02:56:34.672 [405724] <2> logResourceReq: mustUseLocalMediaServer : false 02:56:34.672 [405724] <2> logResourceReq: failOnError : false 02:56:34.672 [405724] <2> logResourceReq: mpxRequired : false 02:56:34.672 [405724] <2> logResourceReq: client : AIXBK 02:56:34.672 [405724] <2> logResourceReq: usageType : 1 02:56:34.676 [405724] <2> RequestMultipleResources: BpxmiV->requestResources returns 0 02:56:34.712 [405724] <2> resourcesAvailable: m_allocationSeq.length() == 1 02:56:34.712 [405724] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 4 02:56:34.712 [405724] <2> resourcesAvailable: MEDIADB 1 932002 0120L4 4000982 ------ 6 1389468610 1389542419 1391961619 0 145924864 2 2 2 1 0 512 1024 0 570025 0 02:56:34.712 [405724] <2> resourcesAvailable: VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0 02:56:34.712 [405724] <2> resourcesAvailable: DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0 02:56:34.712 [405724] <2> resourcesAvailable: STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576 02:56:36.701 [405724] <2> packageMultiResourceRequestResult: totalNumberOfAllocations == 1 02:56:36.701 [405724] <2> packageMultiResourceRequestResult: found MediaAllocation : reqNum == 0 02:56:36.701 [405724] <2> packageMultiResourceRequestResult: matched MediaAllocation to an stuReq 02:56:36.702 [405724] <2> packageMultiResourceRequestResult: retVal = 0 02:56:36.702 [405724] <2> RequestMultipleResources: retVal = 0 emmStatus = 0 02:56:36.702 [405724] <2> RequestMultipleResources: returning 02:56:36.702 [405724] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 932002 0120L4 4000982 ------ 6 1389468610 1389542419 1391961619 0 145924864 2 2 2 1 0 512 1024 0 570025 0], length 115 02:56:36.702 [405724] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0], length 108 02:56:36.702 [405724] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0], length 110 02:56:36.702 [405724] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576], length 43 02:56:36.702 [405724] <2> populateBptmOpaqueStrings: retVal = 0 02:56:36.702 [405724] <2> parse_resource_strings: MEDIADB 1 932002 0120L4 4000982 ------ 6 1389468610 1389542419 1391961619 0 145924864 2 2 2 1 0 512 1024 0 570025 0 02:56:36.702 [405724] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters 02:56:36.702 [405724] <2> parse_resource_strings: VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0 02:56:36.702 [405724] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters 02:56:36.702 [405724] <2> parse_resource_strings: DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0 02:56:36.702 [405724] <2> parse_resource_strings: Parsed message type 17, version 2, 19 parameters 02:56:36.702 [405724] <2> parse_resource_strings: STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576 02:56:36.702 [405724] <2> parse_resource_strings: Parsed message type 18, version 0, 4 parameters 02:56:36.702 [405724] <2> nbjm_media_request: Job control returned to BPTM 02:56:36.702 [405724] <2> drivename_open: Called with Create 1, file IBM.ULT3580-TD4.003 02:56:36.710 [405724] <2> drivename_lock: lock established 02:56:36.710 [405724] <2> drivename_write: Called with mode 0 02:56:36.710 [405724] <2> bptm media_id_to_monitor: job_id = 808076 02:56:36.717 [405724] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 02:56:36.760 [405724] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 02:56:36.760 [405724] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpjobd 02:56:36.876 [405724] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 02:56:36.876 [405724] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.34899 TO 10.2.21.10.13724 fd = 20 02:56:36.876 [405724] <2> logconnections: BPJOBD CONNECT FROM 10.2.21.39.34899 TO 10.2.21.10.13724 02:56:36.876 [405724] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 02:56:36.876 [405724] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 02:56:36.876 [405724] <2> job_authenticate_connection: no authentication required 02:56:36.876 [405724] <2> job_authenticate_connection: ignoring VxSS authentication check for now... 02:56:36.879 [405724] <2> job_connect: Connected to the host hqmb1 contype 10 jobid <808076> socket <20> 02:56:36.879 [405724] <2> job_connect: Connected on port 34899 02:56:36.879 [405724] <2> bptm media_id_to_monitor: pDstMediaId = 0120L4 02:56:36.879 [405724] <2> set_job_details: Sending jobData jobid (808076) 02:56:36.879 [405724] <2> send_structure_data: Index 28 Field m_szDstMediaID Value <0120L4> 02:56:36.879 [405724] <2> set_job_details: Done 02:56:36.879 [405724] <2> mount_open_media: Waiting for mount of media id 0120L4 (copy 1) on server aixbk. 02:56:36.879 [405724] <4> create_tpreq_file: symlink to path /dev/rmt0.1 02:56:36.887 [405724] <2> manage_scsi_reserve: SCSI RESERVE 02:56:36.890 [405724] <4> expandpath: /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 02:56:37.536 [405724] <2> process_brm_msg: no pending message from bpbrm 02:57:18.809 [610356] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 02:57:18.821 [610356] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:57:18.822 [610356] <2> bptm: EXITING with status 0 <---------- 02:57:36.616 [405724] <2> io_open: report_attr, fl1 0x00000849, fl2 0x00000000 02:57:36.634 [405724] <2> io_open: SCSI RESERVE 02:57:36.637 [405724] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 02:57:36.637 [405724] <2> write_backup: media id 0120L4 mounted on drive index 0, drivepath /dev/rmt0.1, drivename IBM.ULT3580-TD4.003, copy 1 02:57:36.637 [405724] <2> io_read_media_header: drive index 0, reading media header, buflen = 65536, buff = 0x2062b018, copy 1 02:57:36.637 [405724] <2> io_ioctl: command (6)MTREW 1 from (bptm.c.7774) on drive index 0 02:57:36.648 [405724] <2> io_ioctl: command (11)MTFSF 1 from (bptm.c.8031) on drive index 0 02:57:36.669 [405724] <2> io_position_for_write: position media id 0120L4, copy 1, current number images = 2 02:57:36.669 [405724] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.6648 02:57:36.669 [405724] <2> io_position_for_write: locating to absolute block number 570025, copy 1 02:58:27.239 [405724] <2> io_position_for_write: locate block is done 02:58:27.257 [405724] <2> io_open: SCSI RESERVE 02:58:27.259 [405724] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 02:58:28.557 [405724] <2> io_position_for_write: processing empty header, filenum = 3, bid = (empty_file), copy 1 02:58:28.557 [405724] <2> io_position_for_write: empty header found on 0120L4, OK, copy 1 02:58:28.557 [405724] <2> io_ioctl: command (12)MTBSF 1 from (bptm.c.20524) on drive index 0 02:58:28.570 [405724] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.20558) on drive index 0 02:58:33.499 [405724] <2> send_MDS_msg: MEDIADB 1 932002 0120L4 4000982 *NULL* 6 1389468610 1389553208 1391972408 0 145924864 2 2 2 1 0 512 1024 0 570025 0 02:58:33.538 [405724] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 02:58:33.586 [405724] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 02:58:33.586 [405724] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 02:58:33.770 [405724] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 02:58:33.770 [405724] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.34903 TO 10.2.21.10.13724 fd = 23 02:58:33.770 [405724] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.34903 TO 10.2.21.10.13724 02:58:33.770 [405724] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 02:58:33.770 [405724] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 02:58:33.770 [405724] <2> check_authentication: no authentication required 02:58:33.770 [405724] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 02:58:33.770 [405724] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 02:58:34.223 [405724] <4> write_backup: begin writing backup id AIXBK_1389553208, copy 1, fragment 1, to media id 0120L4 on drive index 0 02:58:34.223 [405724] <2> process_brm_msg: no pending message from bpbrm 02:58:34.223 [405724] <2> write_backup: waiting 5 seconds for start of another backup 02:58:39.223 [405724] <2> send_brm_msg: MEDIA READY 02:58:39.231 [405724] <2> write_data: ndmp_dup_max_frag is set to 1073741824000 02:58:39.231 [405724] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: 0 twin_is_disk 0 delay_brm: 0 02:58:39.231 [405724] <2> io_ioctl: command (12)MTBSF 1 from (bptm.c.21169) on drive index 0 02:58:41.106 [405724] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.21176 02:58:41.110 [405724] <2> write_data: absolute block position prior to writing backup header(s) is 570025, copy 1 02:58:41.127 [405724] <2> io_open: SCSI RESERVE 02:58:41.128 [405724] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 02:58:41.128 [405724] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.21229) on drive index 0 02:58:43.679 [405724] <2> io_write_back_header: drive index 0, AIXBK_1389553208, file num = 3, mpx_headers = 1, copy 1 02:58:43.702 [405724] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1 02:58:43.702 [405724] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0 02:58:43.702 [405724] <2> write_data: received first buffer (262144 bytes), begin writing data 02:59:28.230 [516250] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007729 -jm 02:59:28.250 [516250] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 02:59:28.250 [516250] <2> bptm: PORT_STATUS = 0x00000000 02:59:28.250 [516250] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 02:59:28.250 [516250] <2> drivename_checklock: Called 02:59:28.250 [516250] <2> drivename_checklock: PID 405724 has lock 02:59:28.255 [516250] <2> report_drives: MODE = 0 02:59:28.255 [516250] <2> report_drives: TIME = 1389552996 02:59:28.255 [516250] <2> report_drives: MASTER = hqmb1 02:59:28.255 [516250] <2> report_drives: PATH = /dev/rmt0.1 02:59:28.255 [516250] <2> report_drives: MEDIA = 0120L4 02:59:28.255 [516250] <2> report_drives: REQID = -1389007725 02:59:28.255 [516250] <2> report_drives: ALOCID = 932002 02:59:28.255 [516250] <2> report_drives: RBID = {06EFC5CD-E15B-4414-BB6F-9918F40D7191 02:59:28.255 [516250] <2> report_drives: PID = 405724 02:59:28.255 [516250] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 02:59:28.255 [516250] <2> main: Sending [EXIT STATUS 0] to NBJM 02:59:28.255 [516250] <2> bptm: EXITING with status 0 <---------- 03:07:49.254 [458842] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 03:07:49.310 [458842] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:07:49.330 [458842] <2> bptm: EXITING with status 0 <---------- 03:09:30.030 [393460] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007738 -jm 03:09:30.070 [393460] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:09:30.081 [393460] <2> bptm: PORT_STATUS = 0x00000000 03:09:30.126 [393460] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 03:09:30.134 [393460] <2> drivename_checklock: Called 03:09:30.134 [393460] <2> drivename_checklock: PID 405724 has lock 03:09:30.144 [393460] <2> report_drives: MODE = 0 03:09:30.144 [393460] <2> report_drives: TIME = 1389552996 03:09:30.144 [393460] <2> report_drives: MASTER = hqmb1 03:09:30.144 [393460] <2> report_drives: PATH = /dev/rmt0.1 03:09:30.144 [393460] <2> report_drives: MEDIA = 0120L4 03:09:30.144 [393460] <2> report_drives: REQID = -1389007725 03:09:30.144 [393460] <2> report_drives: ALOCID = 932002 03:09:30.145 [393460] <2> report_drives: RBID = {06EFC5CD-E15B-4414-BB6F-9918F40D7191 03:09:30.145 [393460] <2> report_drives: PID = 405724 03:09:30.145 [393460] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 03:09:30.154 [393460] <2> main: Sending [EXIT STATUS 0] to NBJM 03:09:30.154 [393460] <2> bptm: EXITING with status 0 <---------- 03:18:02.797 [393254] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 03:18:02.818 [393254] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:18:02.824 [393254] <2> bptm: EXITING with status 0 <---------- 03:19:28.125 [475200] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007742 -jm 03:19:28.141 [475200] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:19:28.148 [475200] <2> bptm: PORT_STATUS = 0x00000000 03:19:28.164 [475200] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 03:19:28.164 [475200] <2> drivename_checklock: Called 03:19:28.164 [475200] <2> drivename_checklock: PID 405724 has lock 03:19:28.169 [475200] <2> report_drives: MODE = 0 03:19:28.169 [475200] <2> report_drives: TIME = 1389552996 03:19:28.169 [475200] <2> report_drives: MASTER = hqmb1 03:19:28.169 [475200] <2> report_drives: PATH = /dev/rmt0.1 03:19:28.169 [475200] <2> report_drives: MEDIA = 0120L4 03:19:28.169 [475200] <2> report_drives: REQID = -1389007725 03:19:28.169 [475200] <2> report_drives: ALOCID = 932002 03:19:28.169 [475200] <2> report_drives: RBID = {06EFC5CD-E15B-4414-BB6F-9918F40D7191 03:19:28.169 [475200] <2> report_drives: PID = 405724 03:19:28.169 [475200] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 03:19:28.171 [475200] <2> main: Sending [EXIT STATUS 0] to NBJM 03:19:28.171 [475200] <2> bptm: EXITING with status 0 <---------- 03:19:52.631 [405724] <2> write_data: writing block shorter than BUFF_SIZE, 162304 bytes 03:19:52.637 [405724] <2> write_data: writing short block, 162304 bytes, remainder 512 03:19:52.669 [405724] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = 0 03:19:52.678 [405724] <2> write_backup: tp.tv_sec = 1389554392, stp.tv_sec = 1389553123, tp.tv_usec = 637751, stp.tv_usec = 702255, et = 1268936, mpx_total_kbytes[TWIN_INDEX = 0] = 113196190 03:19:52.721 [405724] <2> io_terminate_tape: writing empty backup header, drive index 0, copy 1 03:19:52.731 [405724] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.8311) on drive index 0 03:19:55.501 [405724] <2> io_write_back_header: drive index 0, empty_file, file num = 4, mpx_headers = 0, copy 1 03:19:55.514 [405724] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.8429 03:19:58.013 [405724] <2> io_terminate_tape: absolute block position prior to writing empty header is 1012200, copy 1 03:19:58.013 [405724] <2> io_terminate_tape: block position check: actual 1012200, expected 1012200 03:19:58.023 [405724] <2> send_MDS_msg: MEDIADB 1 932002 0120L4 4000982 *NULL* 6 1389468610 1389553208 1391972408 0 145924864 2 2 2 1 0 512 1024 0 1012200 0 03:19:58.348 [405724] <2> io_open: SCSI RESERVE 03:19:58.348 [405724] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 0) 03:19:58.348 [405724] <2> io_ioctl: command (12)MTBSF 2 from (bptm.c.8586) on drive index 0 03:19:58.400 [405724] <2> io_ioctl: command (11)MTFSF 1 from (bptm.c.8588) on drive index 0 03:19:58.451 [405724] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.8594 03:19:58.452 [405724] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from io_terminate_tape) 03:19:58.461 [405724] <2> write_backup_update_frags: ************** Fragment 1: ******************* 03:19:58.461 [405724] <2> write_backup_update_frags: ++++ total image kbytes so far = 113196190 ++++ ` 03:19:58.461 [405724] <2> write_backup_update_frags: ++++ fragment_num = 1 ++++ 03:19:58.461 [405724] <2> write_backup_update_frags: copy_num = 1 03:19:58.461 [405724] <2> write_backup_update_frags: Kbytes = 113196190 03:19:58.461 [405724] <2> write_backup_update_frags: remainder = 512 03:19:58.461 [405724] <2> write_backup_update_frags: id = 0120L4 03:19:58.461 [405724] <2> write_backup_update_frags: file_num = 3 03:19:58.461 [405724] <2> write_backup_update_frags: block_size = 262144 03:19:58.461 [405724] <2> write_backup_update_frags: offset = 570025 03:19:58.461 [405724] <2> write_backup_update_frags: ****************************************************** 03:19:58.541 [405724] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 03:19:58.584 [405724] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 03:19:58.584 [405724] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 03:19:58.714 [405724] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 03:19:58.714 [405724] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.34972 TO 10.2.21.10.13724 fd = 22 03:19:58.714 [405724] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.34972 TO 10.2.21.10.13724 03:19:58.727 [405724] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 03:19:58.727 [405724] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 03:19:58.727 [405724] <2> check_authentication: no authentication required 03:19:58.728 [405724] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 03:19:58.728 [405724] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 03:19:59.246 [405724] <2> send_MDS_msg: MEDIADB 1 932002 0120L4 4000982 *NULL* 6 1389468610 1389553208 1391972408 0 259121054 3 3 2 1 0 512 1024 0 1012200 0 03:19:59.289 [405724] <2> send_brm_msg: MEDIA NOT READY 03:19:59.289 [405724] <2> send_brm_msg: EXIT AIXBK_1389553208 0 03:19:59.289 [405724] <2> notify: executing - /usr/openv/netbackup/bin/backup_notify bptm AIXBK_1389553208 03:19:59.417 [405724] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 03:19:59.539 [405724] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 03:19:59.539 [405724] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 03:19:59.720 [405724] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 03:19:59.720 [405724] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.34973 TO 10.2.21.10.13724 fd = 22 03:19:59.720 [405724] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.34973 TO 10.2.21.10.13724 03:19:59.720 [405724] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 03:19:59.720 [405724] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 03:19:59.720 [405724] <2> check_authentication: no authentication required 03:19:59.720 [405724] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 03:19:59.720 [405724] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 03:20:00.240 [405724] <4> write_backup: successfully wrote backup id AIXBK_1389553208, copy 1, 113196190 Kbytes 03:20:00.240 [405724] <2> bct_clear_active: removing group 0 shmid 34603019 03:20:00.307 [405724] <2> bct_clear_active: Set BCTable entry 0 to inactive, ACTIVE_GC count decremented to 0 03:20:00.313 [405724] <2> write_backup_completion_stats: waited for full buffer 6051 times, delayed 12522 times 03:20:00.313 [405724] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 03:20:00.765 [405724] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 03:20:00.765 [405724] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 03:20:00.935 [405724] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 03:20:00.935 [405724] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.34975 TO 10.2.21.10.13724 fd = 22 03:20:00.935 [405724] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.34975 TO 10.2.21.10.13724 03:20:00.935 [405724] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 03:20:00.935 [405724] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 03:20:00.935 [405724] <2> check_authentication: no authentication required 03:20:00.935 [405724] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 03:20:00.935 [405724] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 03:20:01.440 [405724] <4> write_backup_completion_stats: successfully wrote 1 of 1 multiplexed backups, total Kbytes 113196190 at 89205.594 Kbytes/sec 03:20:01.459 [405724] <2> bptm: waiting for TERMINATE from bpbrm/IRM 03:20:17.466 [405724] <2> read_brm_msg: TERMINATE 03:20:17.470 [405724] <2> updateEMM_freespace: updateEMM_freespace() (1 0) 03:20:17.470 [405724] <2> main: TWIN_INDEX = 0, STU_FLAGS = 0 03:20:17.578 [405724] <2> bptm: EXITING with status 0 <---------- 03:20:17.578 [405724] <2> cleanup: Detached from BPBRM shared memory 03:20:35.565 [483462] <2> bptm: INITIATING (VERBOSE = 5): -unload -dn IBM.ULT3580-TD4.003 -dp /dev/rmt0.1 -dk 2000371 -m 0120L4 -mk 4000982 -mds 8 -alocid 932002 -jobid -1389007743 -jm 03:20:35.577 [483462] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:20:35.582 [483462] <2> bptm: PORT_STATUS = 0x00000000 03:20:35.589 [483462] <2> hosts_equal: The second name is empty 03:20:35.601 [483462] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:20:35.601 [483462] <2> hosts_equal: Comparing hosts and 03:20:35.601 [483462] <2> hosts_equal: names are the same 03:20:35.601 [483462] <4> bptm: emmserver_name = hqmb1 03:20:35.601 [483462] <4> bptm: emmserver_port = 1556 03:20:35.614 [483462] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:20:35.701 [483462] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name 03:20:35.701 [483462] <2> VssInit: vss_auth.cpp.720: Function: VssInit. Using Cached entries FALSE 03:20:35.702 [483462] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name AIXBK 03:20:35.741 [483462] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:20:35.768 [483462] <2> send_brm_msg: PID of bpxm = 483462 03:20:35.771 [483462] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD 03:20:35.795 [483462] <2> RequestMultipleResources: starting 03:20:35.795 [483462] <2> RequestMultipleResources: started 03:20:35.806 [483462] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name 03:20:35.806 [483462] <2> VssInit: vss_auth.cpp.720: Function: VssInit. Using Cached entries FALSE 03:20:35.806 [483462] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name AIXBK 03:20:36.005 [483462] <2> packageMultiResourceRequest: started 03:20:36.014 [483462] <2> packageMultiResourceRequest: retVal = 0 03:20:36.014 [483462] <2> RequestMultipleResources: setting up callback and calling requestResources 03:20:36.016 [483462] <2> logResourceReq: req.versionId : 1 03:20:36.016 [483462] <2> logResourceReq: req.jobId : -1389007743 03:20:36.016 [483462] <2> logResourceReq: req.startedViaJobManager : true 03:20:36.016 [483462] <2> logResourceReq: req.consumer : true 03:20:36.023 [483462] <2> logResourceReq: MediaSelect - 03:20:36.023 [483462] <2> logResourceReq: reqNum : 0 03:20:36.024 [483462] <2> logResourceReq: oldMediaId : 0120L4 03:20:36.024 [483462] <2> logResourceReq: previousFailed : false 03:20:36.024 [483462] <2> logMediaRequest: mreq.mediaId : 0120L4 03:20:36.024 [483462] <2> logMediaRequest: mreq.mediaKey : 0 03:20:36.024 [483462] <2> logMediaRequest: mreq.mediaServer : AIXBK 03:20:36.024 [483462] <2> logMediaRequest: mreq.userReservationId : 03:20:36.024 [483462] <2> logMediaRequest: mreq.assignedTime : 0 03:20:36.024 [483462] <2> logMediaRequest: mreq.client : 03:20:36.024 [483462] <2> logMediaRequest: mreq.usageType : 6 03:20:36.024 [483462] <2> logMediaRequest: mreq.mustBeNdmp : false 03:20:36.024 [483462] <2> logMediaRequest: mreq.driveName : IBM.ULT3580-TD4.003 03:20:36.024 [483462] <2> logMediaRequest: mreq.drivePath : 03:20:36.024 [483462] <2> logMediaRequest: mreq.mediaPool : 03:20:36.024 [483462] <2> logMediaRequest: mreq.robotNumber : -1 03:20:36.024 [483462] <2> logMediaRequest: mreq.slotNumber : -1 03:20:36.024 [483462] <2> logMediaRequest: mreq.density : -1 03:20:36.024 [483462] <2> logMediaRequest: mreq.ndmpControlHost : 03:20:36.024 [483462] <2> logMediaRequest: mreq.failIfNoMedia : true 03:20:36.024 [483462] <2> logMediaRequest: mreq.externalFile : 03:20:36.033 [483462] <2> RequestMultipleResources: BpxmiV->requestResources returns 0 03:20:36.088 [483462] <2> resourcesAvailable: m_allocationSeq.length() == 1 03:20:36.089 [483462] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 4 03:20:36.089 [483462] <2> resourcesAvailable: MEDIADB 1 932002 0120L4 4000982 ------ 6 1389468610 1389542419 1391961619 0 145924864 2 2 2 1 0 512 1024 0 570025 0 03:20:36.089 [483462] <2> resourcesAvailable: VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0 03:20:36.089 [483462] <2> resourcesAvailable: DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0 03:20:36.089 [483462] <2> resourcesAvailable: STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576 03:20:38.052 [483462] <2> packageMultiResourceRequestResult: totalNumberOfAllocations == 1 03:20:38.052 [483462] <2> packageMultiResourceRequestResult: found MediaAllocation : reqNum == 0 03:20:38.052 [483462] <2> packageMultiResourceRequestResult: matched MediaAllocation to a mediaSelect 03:20:38.052 [483462] <2> packageMultiResourceRequestResult: retVal = 0 03:20:38.052 [483462] <2> RequestMultipleResources: retVal = 0 emmStatus = 0 03:20:38.053 [483462] <2> RequestMultipleResources: returning 03:20:38.059 [483462] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 932002 0120L4 4000982 ------ 6 1389468610 1389542419 1391961619 0 145924864 2 2 2 1 0 512 1024 0 570025 0], length 115 03:20:38.059 [483462] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0], length 108 03:20:38.059 [483462] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0], length 110 03:20:38.059 [483462] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576], length 43 03:20:38.059 [483462] <2> populateBptmOpaqueStrings: retVal = 0 03:20:38.060 [483462] <2> parse_resource_strings: MEDIADB 1 932002 0120L4 4000982 ------ 6 1389468610 1389542419 1391961619 0 145924864 2 2 2 1 0 512 1024 0 570025 0 03:20:38.060 [483462] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters 03:20:38.060 [483462] <2> parse_resource_strings: VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0 03:20:38.060 [483462] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters 03:20:38.060 [483462] <2> parse_resource_strings: DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0 03:20:38.060 [483462] <2> parse_resource_strings: Parsed message type 17, version 2, 19 parameters 03:20:38.060 [483462] <2> parse_resource_strings: STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576 03:20:38.060 [483462] <2> parse_resource_strings: Parsed message type 18, version 0, 4 parameters 03:20:38.060 [483462] <2> nbjm_media_request: Job control returned to BPTM 03:20:38.063 [483462] <2> drivename_open: Called with Create 1, file IBM.ULT3580-TD4.003 03:20:38.063 [483462] <2> drivename_lock: lock established 03:20:38.078 [483462] <4> create_tpreq_file: symlink to path /dev/rmt0.1 03:20:38.083 [483462] <2> drivename_write: Called with mode 2 03:20:38.096 [483462] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release) 03:20:38.104 [483462] <2> really_tpunmount: tpunmount'ing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 03:21:58.119 [483462] <4> create_tpreq_file: symlink to path /dev/rmt0.1 03:21:58.124 [483462] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release) 03:21:58.127 [483462] <2> tapealert_and_release: SCSI RELEASE 03:21:58.135 [483462] <2> drivename_unlock: unlocked 03:21:58.135 [483462] <2> drivename_close: Called 03:21:58.135 [483462] <2> drivename_remove: Called 03:21:58.139 [483462] <2> main: Sending [EXIT STATUS 0] to NBJM 03:21:58.139 [483462] <2> bptm: EXITING with status 0 <---------- 03:26:24.472 [405582] <2> bptm: INITIATING (VERBOSE = 5): -pid 475276 -den 6 -rt 8 -rn 0 -cj 8 -mpx 32 -reqid -1389007744 -jm -brm -p NetBackup -stunit aixbk-hcart-robot-tld-0 -maxfrag 1048576 -v -masterversion 600000 -mediasvr aixbk -bpbrm_shm_id 44040202 -blks_per_buffer 512 03:26:24.484 [405582] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:26:24.484 [405582] <2> main: bptm.c.1622: maximum fragment size is 1048576000 Kbytes 03:26:24.484 [405582] <2> bptm: PORT_STATUS = 0x00000000 03:26:24.491 [405582] <2> hosts_equal: The second name is empty 03:26:24.504 [405582] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:26:24.504 [405582] <2> hosts_equal: Comparing hosts and 03:26:24.504 [405582] <2> hosts_equal: names are the same 03:26:24.504 [405582] <4> bptm: emmserver_name = hqmb1 03:26:24.504 [405582] <4> bptm: emmserver_port = 1556 03:26:24.517 [405582] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:26:24.563 [405582] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name 03:26:24.563 [405582] <2> VssInit: vss_auth.cpp.720: Function: VssInit. Using Cached entries FALSE 03:26:24.564 [405582] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name AIXBK 03:26:25.886 [405582] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:26:25.908 [405582] <2> hosts_equal: Comparing hosts and 03:26:25.908 [405582] <2> hosts_equal: names are the same 03:26:25.909 [405582] <4> db_getSTUNIT: EMM interface already initialized (using cached master name hqmb1). 03:26:25.927 [405582] <2> setup_twin_parameters: bptm.c.3860: maximum fragment size is 1048576000 Kbytes 03:26:25.927 [405582] <2> send_brm_msg: PID of bpxm = 405582 03:26:25.929 [405582] <2> process_mpx_protocol: wait for initial START BACKUP message from bpbrm 03:26:32.034 [405582] <2> read_brm_msg: START BACKUP -b AIXBK_1389555007 -bt 1389555007 -c AIXBK -cl AIXBK_FS_SAP_FLASH -st 0 -rl 2 -rp 2419200 -sl Daily -ct 0 -hostname AIXBK -rclnt AIXBK -rclnthostname AIXBK -bclnt AIXBK -bclnthostname AIXBK -ru root -shm -no_callback -connect_options 0x01020100 -jobid 808082 -jobgrpid 808082 03:26:32.041 [405582] <2> validate_parameters: tmcommon.c.4449: maximum fragment size is 1048576000 Kbytes 03:26:32.041 [405582] <2> io_init: bpbrm_shm_id = 44040202, buffer address = 0x30000000 03:26:32.042 [405582] <2> io_init: found index: 0 03:26:32.042 [405582] <2> io_init: using 262144 data buffer size 03:26:32.042 [405582] <2> io_init: CINDEX 0, sched Kbytes for monitoring = 60000 03:26:32.053 [405582] <2> io_init: using 64 data buffers 03:26:32.056 [405582] <2> io_init: child delay = 20, parent delay = 30 (milliseconds) 03:26:32.070 [405582] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 03:26:32.107 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 03:26:32.107 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 03:26:32.233 [405582] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 03:26:32.234 [405582] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35031 TO 10.2.21.10.13724 fd = 13 03:26:32.234 [405582] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.35031 TO 10.2.21.10.13724 03:26:32.234 [405582] <2> vauth_get_user_name: vauth_comm.c.726: cached_user_name: root 03:26:32.234 [405582] <2> vauth_get_user_name: vauth_comm.c.728: cached_user_name: :root 03:26:32.234 [405582] <2> vauth_get_user_name: vauth_comm.c.734: user_name: :root 03:26:32.234 [405582] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 03:26:32.234 [405582] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 03:26:32.234 [405582] <2> check_authentication: no authentication required 03:26:32.234 [405582] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 03:26:32.234 [405582] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 03:26:32.805 [405582] <2> mpx_setup_shm: buffer control shared memory address is 0x40000000, size is 49280, shmid is 22020108 03:26:32.805 [405582] <2> mpx_setup_shm: buf control for CINDEX 0 is 0x40000000 03:26:32.805 [405582] <2> mpx_setup_shm: shared memory address for group 0 is 0x50000000, size is 67108864, shmid is 35651595 03:26:32.805 [405582] <2> mpx_setup_shm: shared memory address for CINDEX 0 is 0x50000000, group 0, num_active 1 03:26:32.818 [405582] <2> setup_bpbkar_info: /usr/openv/netbackup/db/config/shm/AIXBK_1389555007 file successfully created 03:26:32.818 [405582] <2> get_data_socket: tmmpx.c.3453: port_status: 16908544 16908544 0x01020100 03:26:32.818 [405582] <2> get_data_socket: tmmpx.c.3454: shm_method: 1 1 0x00000001 03:26:32.818 [405582] <2> get_data_socket: tmmpx.c.3457: client_hostname: AIXBK 03:26:32.818 [405582] <2> nb_bind_on_port_addr: bound to port 3738 03:26:32.818 [405582] <2> get_data_socket: tmmpx.c.3522: *port: 3738 3738 0x00000e9a 03:26:32.818 [405582] <2> get_data_socket: tmmpx.c.3523: mpx_ipc: 03:26:32.818 [405582] <2> mpx_start_child: tmmpx.c.1150: Calling: send_brm_msg(BRM_PORT) 03:26:32.818 [405582] <2> send_brm_msg: DATASOCKET AIXBK_1389555007 3738 03:26:32.818 [405582] <2> mpx_start_child: tmmpx.c.1155: Calling: bpcr_get_socket_rqst2 03:26:32.818 [405582] <2> mpx_start_child: tmmpx.c.1232: Calling: bpcr_get_socket_rqst4 03:26:34.008 [405582] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 03:26:34.051 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 03:26:34.051 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 03:26:34.241 [405582] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 03:26:34.241 [405582] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35036 TO 10.2.21.10.13724 fd = 13 03:26:34.241 [405582] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.35036 TO 10.2.21.10.13724 03:26:34.241 [405582] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 03:26:34.241 [405582] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 03:26:34.241 [405582] <2> check_authentication: no authentication required 03:26:34.241 [405582] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 03:26:34.241 [405582] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 03:26:34.812 [405582] <2> nbjm_media_request: Passing job control to NBJM, type WRITE 03:26:34.814 [405582] <2> RequestMultipleResources: starting 03:26:34.814 [405582] <2> RequestMultipleResources: started 03:26:34.822 [405582] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name 03:26:34.822 [405582] <2> VssInit: vss_auth.cpp.720: Function: VssInit. Using Cached entries FALSE 03:26:34.822 [405582] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name AIXBK 03:26:34.899 [405582] <2> packageMultiResourceRequest: started 03:26:34.899 [405582] <2> packageMultiResourceRequest: retVal = 0 03:26:34.899 [405582] <2> RequestMultipleResources: setting up callback and calling requestResources 03:26:34.899 [405582] <2> logResourceReq: req.versionId : 1 03:26:34.899 [405582] <2> logResourceReq: req.jobId : -1389007744 03:26:34.899 [405582] <2> logResourceReq: req.startedViaJobManager : true 03:26:34.899 [405582] <2> logResourceReq: req.consumer : true 03:26:34.899 [405582] <2> logResourceReq: STUSelect - 03:26:34.899 [405582] <2> logResourceReq: reqNum : 0 03:26:34.899 [405582] <2> logResourceReq: mediaServer : AIXBK 03:26:34.899 [405582] <2> logResourceReq: oldMediaId : 03:26:34.899 [405582] <2> logResourceReq: previousFailed : false 03:26:34.899 [405582] <2> logResourceReq: storageUnit : aixbk-hcart-robot-tld-0 03:26:34.899 [405582] <2> logResourceReq: mustBeNdmp : false 03:26:34.899 [405582] <2> logResourceReq: getMaxFreeSpace : false 03:26:34.899 [405582] <2> logResourceReq: mediaPool : NetBackup 03:26:34.899 [405582] <2> logResourceReq: retentionLevel : 2 03:26:34.899 [405582] <2> logResourceReq: mustUseLocalMediaServer : false 03:26:34.899 [405582] <2> logResourceReq: failOnError : false 03:26:34.899 [405582] <2> logResourceReq: mpxRequired : false 03:26:34.899 [405582] <2> logResourceReq: client : AIXBK 03:26:34.899 [405582] <2> logResourceReq: usageType : 1 03:26:34.902 [405582] <2> RequestMultipleResources: BpxmiV->requestResources returns 0 03:26:34.928 [405582] <2> resourcesAvailable: m_allocationSeq.length() == 1 03:26:34.928 [405582] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 4 03:26:34.928 [405582] <2> resourcesAvailable: MEDIADB 1 932011 0120L4 4000982 ------ 6 1389468610 1389553208 1391972408 0 259121054 3 3 2 1 0 512 1024 0 1012200 0 03:26:34.928 [405582] <2> resourcesAvailable: VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0 03:26:34.928 [405582] <2> resourcesAvailable: DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0 03:26:34.928 [405582] <2> resourcesAvailable: STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576 03:26:36.909 [405582] <2> packageMultiResourceRequestResult: totalNumberOfAllocations == 1 03:26:36.909 [405582] <2> packageMultiResourceRequestResult: found MediaAllocation : reqNum == 0 03:26:36.909 [405582] <2> packageMultiResourceRequestResult: matched MediaAllocation to an stuReq 03:26:36.909 [405582] <2> packageMultiResourceRequestResult: retVal = 0 03:26:36.909 [405582] <2> RequestMultipleResources: retVal = 0 emmStatus = 0 03:26:36.909 [405582] <2> RequestMultipleResources: returning 03:26:36.909 [405582] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 932011 0120L4 4000982 ------ 6 1389468610 1389553208 1391972408 0 259121054 3 3 2 1 0 512 1024 0 1012200 0], length 116 03:26:36.909 [405582] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0], length 108 03:26:36.909 [405582] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0], length 110 03:26:36.909 [405582] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576], length 43 03:26:36.909 [405582] <2> populateBptmOpaqueStrings: retVal = 0 03:26:36.909 [405582] <2> parse_resource_strings: MEDIADB 1 932011 0120L4 4000982 ------ 6 1389468610 1389553208 1391972408 0 259121054 3 3 2 1 0 512 1024 0 1012200 0 03:26:36.909 [405582] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters 03:26:36.909 [405582] <2> parse_resource_strings: VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0 03:26:36.909 [405582] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters 03:26:36.909 [405582] <2> parse_resource_strings: DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0 03:26:36.909 [405582] <2> parse_resource_strings: Parsed message type 17, version 2, 19 parameters 03:26:36.909 [405582] <2> parse_resource_strings: STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576 03:26:36.909 [405582] <2> parse_resource_strings: Parsed message type 18, version 0, 4 parameters 03:26:36.909 [405582] <2> nbjm_media_request: Job control returned to BPTM 03:26:36.909 [405582] <2> drivename_open: Called with Create 1, file IBM.ULT3580-TD4.003 03:26:36.915 [405582] <2> drivename_lock: lock established 03:26:36.915 [405582] <2> drivename_write: Called with mode 0 03:26:36.920 [405582] <2> bptm media_id_to_monitor: job_id = 808082 03:26:36.927 [405582] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 03:26:36.967 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 03:26:36.967 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpjobd 03:26:37.164 [405582] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 03:26:37.164 [405582] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35043 TO 10.2.21.10.13724 fd = 20 03:26:37.164 [405582] <2> logconnections: BPJOBD CONNECT FROM 10.2.21.39.35043 TO 10.2.21.10.13724 03:26:37.164 [405582] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 03:26:37.164 [405582] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 03:26:37.164 [405582] <2> job_authenticate_connection: no authentication required 03:26:37.164 [405582] <2> job_authenticate_connection: ignoring VxSS authentication check for now... 03:26:37.166 [405582] <2> job_connect: Connected to the host hqmb1 contype 10 jobid <808082> socket <20> 03:26:37.166 [405582] <2> job_connect: Connected on port 35043 03:26:37.166 [405582] <2> bptm media_id_to_monitor: pDstMediaId = 0120L4 03:26:37.166 [405582] <2> set_job_details: Sending jobData jobid (808082) 03:26:37.166 [405582] <2> send_structure_data: Index 28 Field m_szDstMediaID Value <0120L4> 03:26:37.166 [405582] <2> set_job_details: Done 03:26:37.166 [405582] <2> mount_open_media: Waiting for mount of media id 0120L4 (copy 1) on server aixbk. 03:26:37.167 [405582] <4> create_tpreq_file: symlink to path /dev/rmt0.1 03:26:37.183 [405582] <2> manage_scsi_reserve: SCSI RESERVE 03:26:37.187 [405582] <4> expandpath: /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 03:26:38.289 [405582] <2> process_brm_msg: no pending message from bpbrm 03:27:34.404 [405582] <2> io_open: report_attr, fl1 0x00000849, fl2 0x00000000 03:27:34.422 [405582] <2> io_open: SCSI RESERVE 03:27:34.425 [405582] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 03:27:34.445 [405582] <2> write_backup: media id 0120L4 mounted on drive index 0, drivepath /dev/rmt0.1, drivename IBM.ULT3580-TD4.003, copy 1 03:27:34.445 [405582] <2> io_read_media_header: drive index 0, reading media header, buflen = 65536, buff = 0x2062b018, copy 1 03:27:34.445 [405582] <2> io_ioctl: command (6)MTREW 1 from (bptm.c.7774) on drive index 0 03:27:34.461 [405582] <2> io_ioctl: command (11)MTFSF 1 from (bptm.c.8031) on drive index 0 03:27:34.485 [405582] <2> io_position_for_write: position media id 0120L4, copy 1, current number images = 3 03:27:34.485 [405582] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.6648 03:27:34.485 [405582] <2> io_position_for_write: locating to absolute block number 1012200, copy 1 03:28:21.713 [553170] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 03:28:21.726 [553170] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:28:21.727 [553170] <2> bptm: EXITING with status 0 <---------- 03:28:25.579 [405582] <2> io_position_for_write: locate block is done 03:28:25.595 [405582] <2> io_open: SCSI RESERVE 03:28:25.597 [405582] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 03:28:26.854 [405582] <2> io_position_for_write: processing empty header, filenum = 4, bid = (empty_file), copy 1 03:28:26.854 [405582] <2> io_position_for_write: empty header found on 0120L4, OK, copy 1 03:28:26.854 [405582] <2> io_ioctl: command (12)MTBSF 1 from (bptm.c.20524) on drive index 0 03:28:26.910 [405582] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.20558) on drive index 0 03:28:31.790 [405582] <2> send_MDS_msg: MEDIADB 1 932011 0120L4 4000982 *NULL* 6 1389468610 1389555007 1391974207 0 259121054 3 3 2 1 0 512 1024 0 1012200 0 03:28:31.829 [405582] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 03:28:31.872 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 03:28:31.872 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 03:28:32.112 [405582] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 03:28:32.112 [405582] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35047 TO 10.2.21.10.13724 fd = 23 03:28:32.112 [405582] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.35047 TO 10.2.21.10.13724 03:28:32.112 [405582] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 03:28:32.112 [405582] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 03:28:32.112 [405582] <2> check_authentication: no authentication required 03:28:32.112 [405582] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 03:28:32.112 [405582] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 03:28:32.863 [405582] <4> write_backup: begin writing backup id AIXBK_1389555007, copy 1, fragment 1, to media id 0120L4 on drive index 0 03:28:32.864 [405582] <2> process_brm_msg: no pending message from bpbrm 03:28:32.864 [405582] <2> write_backup: waiting 5 seconds for start of another backup 03:28:37.864 [405582] <2> send_brm_msg: MEDIA READY 03:28:37.875 [405582] <2> write_data: ndmp_dup_max_frag is set to 1073741824000 03:28:37.875 [405582] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: 0 twin_is_disk 0 delay_brm: 0 03:28:37.875 [405582] <2> io_ioctl: command (12)MTBSF 1 from (bptm.c.21169) on drive index 0 03:28:39.793 [405582] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.21176 03:28:39.795 [405582] <2> write_data: absolute block position prior to writing backup header(s) is 1012200, copy 1 03:28:39.809 [405582] <2> io_open: SCSI RESERVE 03:28:39.811 [405582] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 03:28:39.811 [405582] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.21229) on drive index 0 03:28:42.309 [405582] <2> io_write_back_header: drive index 0, AIXBK_1389555007, file num = 4, mpx_headers = 1, copy 1 03:28:42.331 [405582] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1 03:29:27.968 [553202] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007747 -jm 03:29:27.981 [553202] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:29:27.981 [553202] <2> bptm: PORT_STATUS = 0x00000000 03:29:27.982 [553202] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 03:29:27.982 [553202] <2> drivename_checklock: Called 03:29:27.982 [553202] <2> drivename_checklock: PID 405582 has lock 03:29:27.988 [553202] <2> report_drives: MODE = 0 03:29:27.988 [553202] <2> report_drives: TIME = 1389554796 03:29:27.988 [553202] <2> report_drives: MASTER = hqmb1 03:29:27.988 [553202] <2> report_drives: PATH = /dev/rmt0.1 03:29:27.988 [553202] <2> report_drives: MEDIA = 0120L4 03:29:27.988 [553202] <2> report_drives: REQID = -1389007744 03:29:27.988 [553202] <2> report_drives: ALOCID = 932011 03:29:27.988 [553202] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 03:29:27.988 [553202] <2> report_drives: PID = 405582 03:29:27.988 [553202] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 03:29:27.988 [553202] <2> main: Sending [EXIT STATUS 0] to NBJM 03:29:27.988 [553202] <2> bptm: EXITING with status 0 <---------- 03:34:10.515 [405582] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0 03:34:10.526 [405582] <2> write_data: received first buffer (262144 bytes), begin writing data 03:38:40.886 [311542] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 03:38:40.926 [311542] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:38:40.944 [311542] <2> bptm: EXITING with status 0 <---------- 03:39:29.105 [331962] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007750 -jm 03:39:29.143 [331962] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:39:29.156 [331962] <2> bptm: PORT_STATUS = 0x00000000 03:39:29.190 [331962] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 03:39:29.193 [331962] <2> drivename_checklock: Called 03:39:29.193 [331962] <2> drivename_checklock: PID 405582 has lock 03:39:29.205 [331962] <2> report_drives: MODE = 0 03:39:29.205 [331962] <2> report_drives: TIME = 1389554796 03:39:29.205 [331962] <2> report_drives: MASTER = hqmb1 03:39:29.205 [331962] <2> report_drives: PATH = /dev/rmt0.1 03:39:29.205 [331962] <2> report_drives: MEDIA = 0120L4 03:39:29.205 [331962] <2> report_drives: REQID = -1389007744 03:39:29.205 [331962] <2> report_drives: ALOCID = 932011 03:39:29.205 [331962] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 03:39:29.205 [331962] <2> report_drives: PID = 405582 03:39:29.205 [331962] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 03:39:29.212 [331962] <2> main: Sending [EXIT STATUS 0] to NBJM 03:39:29.212 [331962] <2> bptm: EXITING with status 0 <---------- 03:48:52.086 [602238] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 03:48:52.136 [602238] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:48:52.147 [602238] <2> bptm: EXITING with status 0 <---------- 03:49:29.358 [540772] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007753 -jm 03:49:29.428 [540772] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:49:29.438 [540772] <2> bptm: PORT_STATUS = 0x00000000 03:49:29.470 [540772] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 03:49:29.474 [540772] <2> drivename_checklock: Called 03:49:29.474 [540772] <2> drivename_checklock: PID 405582 has lock 03:49:29.486 [540772] <2> report_drives: MODE = 0 03:49:29.486 [540772] <2> report_drives: TIME = 1389554796 03:49:29.486 [540772] <2> report_drives: MASTER = hqmb1 03:49:29.486 [540772] <2> report_drives: PATH = /dev/rmt0.1 03:49:29.486 [540772] <2> report_drives: MEDIA = 0120L4 03:49:29.486 [540772] <2> report_drives: REQID = -1389007744 03:49:29.486 [540772] <2> report_drives: ALOCID = 932011 03:49:29.486 [540772] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 03:49:29.486 [540772] <2> report_drives: PID = 405582 03:49:29.486 [540772] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 03:49:29.497 [540772] <2> main: Sending [EXIT STATUS 0] to NBJM 03:49:29.497 [540772] <2> bptm: EXITING with status 0 <---------- 03:57:30.496 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327523406 blocks in cpr: 327541802 03:57:30.501 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327523917 blocks in cpr: 327541802 03:57:30.503 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327524428 blocks in cpr: 327541802 03:57:30.504 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327524939 blocks in cpr: 327541802 03:57:30.506 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327525450 blocks in cpr: 327541802 03:57:30.507 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327525961 blocks in cpr: 327541802 03:57:30.509 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327526472 blocks in cpr: 327541802 03:57:30.511 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327526983 blocks in cpr: 327541802 03:57:30.512 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327527494 blocks in cpr: 327541802 03:57:30.514 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327528005 blocks in cpr: 327541802 03:57:30.516 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327528516 blocks in cpr: 327541802 03:57:30.517 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327529027 blocks in cpr: 327541802 03:57:30.519 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327529538 blocks in cpr: 327541802 03:57:30.521 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327530049 blocks in cpr: 327541802 03:57:30.522 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327530560 blocks in cpr: 327541802 03:57:30.524 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327531071 blocks in cpr: 327541802 03:57:30.525 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327531582 blocks in cpr: 327541802 03:57:30.527 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327532093 blocks in cpr: 327541802 03:57:30.529 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327532604 blocks in cpr: 327541802 03:57:30.530 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327533115 blocks in cpr: 327541802 03:57:30.532 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327533626 blocks in cpr: 327541802 03:57:30.534 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327534137 blocks in cpr: 327541802 03:57:30.535 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327534648 blocks in cpr: 327541802 03:57:30.537 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327535159 blocks in cpr: 327541802 03:57:30.539 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327535670 blocks in cpr: 327541802 03:57:30.540 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327536181 blocks in cpr: 327541802 03:57:30.542 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327536692 blocks in cpr: 327541802 03:57:30.543 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327537203 blocks in cpr: 327541802 03:57:30.545 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327537714 blocks in cpr: 327541802 03:57:30.547 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327538225 blocks in cpr: 327541802 03:57:30.548 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327538736 blocks in cpr: 327541802 03:57:30.550 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327539247 blocks in cpr: 327541802 03:57:30.552 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327539758 blocks in cpr: 327541802 03:57:30.553 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327540269 blocks in cpr: 327541802 03:57:30.555 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327540780 blocks in cpr: 327541802 03:57:30.557 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327541291 blocks in cpr: 327541802 03:57:30.558 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 327541802 blocks in cpr: 327541802 03:57:30.579 [405582] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -9 03:57:30.585 [405582] <2> write_backup: tp.tv_sec = 1389556650, stp.tv_sec = 1389554922, tp.tv_usec = 558647, stp.tv_usec = 331715, et = 1728226, mpx_total_kbytes[TWIN_INDEX = 0] = 164091392 03:57:30.623 [405582] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.18563) on drive index 0 03:57:33.450 [405582] <2> write_backup: checkpoint occurred copy 1 --- Fragmenting 03:57:33.468 [405582] <2> write_backup_update_frags: ************** Fragment 1: ******************* 03:57:33.474 [405582] <2> write_backup_update_frags: ++++ total image kbytes so far = 164091392 ++++ ` 03:57:33.474 [405582] <2> write_backup_update_frags: ++++ fragment_num = 1 ++++ 03:57:33.474 [405582] <2> write_backup_update_frags: copy_num = 1 03:57:33.474 [405582] <2> write_backup_update_frags: Kbytes = 164091392 03:57:33.474 [405582] <2> write_backup_update_frags: remainder = 0 03:57:33.474 [405582] <2> write_backup_update_frags: id = 0120L4 03:57:33.474 [405582] <2> write_backup_update_frags: file_num = 4 03:57:33.474 [405582] <2> write_backup_update_frags: block_size = 262144 03:57:33.474 [405582] <2> write_backup_update_frags: offset = 1012200 03:57:33.474 [405582] <2> write_backup_update_frags: ****************************************************** 03:57:33.585 [405582] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 03:57:33.623 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 03:57:33.623 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 03:57:33.767 [405582] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 03:57:33.775 [405582] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35118 TO 10.2.21.10.13724 fd = 23 03:57:33.775 [405582] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.35118 TO 10.2.21.10.13724 03:57:33.779 [405582] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 03:57:33.779 [405582] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 03:57:33.779 [405582] <2> check_authentication: no authentication required 03:57:33.780 [405582] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 03:57:33.780 [405582] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 03:57:34.237 [405582] <2> send_MDS_msg: MEDIADB 1 932011 0120L4 4000982 *NULL* 6 1389468610 1389555007 1391974207 0 423212446 4 4 2 1 0 512 1024 0 1012200 0 03:57:34.519 [405582] <2> write_backup: Setting CPR_COMPLETE, index: 0 03:57:34.534 [405582] <2> process_brm_msg: no pending message from bpbrm 03:57:34.534 [405582] <2> write_backup: waiting 10 seconds for start of another backup 03:57:44.603 [405582] <2> write_data: ndmp_dup_max_frag is set to 1073741824000 03:57:44.603 [405582] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: 0 twin_is_disk 0 delay_brm: 0 03:57:44.614 [405582] <2> io_ioctl: command (12)MTBSF 1 from (bptm.c.21169) on drive index 0 03:57:46.542 [405582] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.21176 03:57:46.663 [405582] <2> write_data: absolute block position prior to writing backup header(s) is 1653184, copy 1 03:57:46.678 [405582] <2> io_open: SCSI RESERVE 03:57:46.683 [405582] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 03:57:46.683 [405582] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.21229) on drive index 0 03:57:49.062 [405582] <2> write_data: block position check: actual 1653184, expected 1653184 03:57:49.062 [405582] <2> io_write_back_header: drive index 0, AIXBK_1389555007, file num = 5, mpx_headers = 1, copy 1 03:57:49.083 [405582] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1 03:57:49.083 [405582] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0 03:57:49.083 [405582] <2> write_data: received first buffer (262144 bytes), begin writing data 03:59:06.689 [602314] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 03:59:06.728 [602314] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:59:06.746 [602314] <2> bptm: EXITING with status 0 <---------- 03:59:28.129 [311526] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007756 -jm 03:59:28.152 [311526] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 03:59:28.160 [311526] <2> bptm: PORT_STATUS = 0x00000000 03:59:28.226 [311526] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 03:59:28.233 [311526] <2> drivename_checklock: Called 03:59:28.233 [311526] <2> drivename_checklock: PID 405582 has lock 03:59:28.243 [311526] <2> report_drives: MODE = 0 03:59:28.243 [311526] <2> report_drives: TIME = 1389554796 03:59:28.243 [311526] <2> report_drives: MASTER = hqmb1 03:59:28.243 [311526] <2> report_drives: PATH = /dev/rmt0.1 03:59:28.243 [311526] <2> report_drives: MEDIA = 0120L4 03:59:28.243 [311526] <2> report_drives: REQID = -1389007744 03:59:28.243 [311526] <2> report_drives: ALOCID = 932011 03:59:28.243 [311526] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 03:59:28.243 [311526] <2> report_drives: PID = 405582 03:59:28.243 [311526] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 03:59:28.248 [311526] <2> main: Sending [EXIT STATUS 0] to NBJM 03:59:28.248 [311526] <2> bptm: EXITING with status 0 <---------- 04:09:25.604 [532712] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 04:09:25.649 [532712] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 04:09:25.666 [532712] <2> bptm: EXITING with status 0 <---------- 04:09:28.138 [602246] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007759 -jm 04:09:28.151 [602246] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 04:09:28.161 [602246] <2> bptm: PORT_STATUS = 0x00000000 04:09:28.255 [602246] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 04:09:28.266 [602246] <2> drivename_checklock: Called 04:09:28.266 [602246] <2> drivename_checklock: PID 405582 has lock 04:09:28.276 [602246] <2> report_drives: MODE = 0 04:09:28.276 [602246] <2> report_drives: TIME = 1389554796 04:09:28.276 [602246] <2> report_drives: MASTER = hqmb1 04:09:28.276 [602246] <2> report_drives: PATH = /dev/rmt0.1 04:09:28.276 [602246] <2> report_drives: MEDIA = 0120L4 04:09:28.276 [602246] <2> report_drives: REQID = -1389007744 04:09:28.276 [602246] <2> report_drives: ALOCID = 932011 04:09:28.276 [602246] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 04:09:28.276 [602246] <2> report_drives: PID = 405582 04:09:28.276 [602246] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 04:09:28.281 [602246] <2> main: Sending [EXIT STATUS 0] to NBJM 04:09:28.281 [602246] <2> bptm: EXITING with status 0 <---------- 04:19:31.722 [311406] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007762 -jm 04:19:31.799 [311406] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 04:19:31.871 [311406] <2> bptm: PORT_STATUS = 0x00000000 04:19:31.926 [311406] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 04:19:31.932 [311406] <2> drivename_checklock: Called 04:19:31.932 [311406] <2> drivename_checklock: PID 405582 has lock 04:19:31.939 [311406] <2> report_drives: MODE = 0 04:19:31.939 [311406] <2> report_drives: TIME = 1389554796 04:19:31.939 [311406] <2> report_drives: MASTER = hqmb1 04:19:31.939 [311406] <2> report_drives: PATH = /dev/rmt0.1 04:19:31.939 [311406] <2> report_drives: MEDIA = 0120L4 04:19:31.939 [311406] <2> report_drives: REQID = -1389007744 04:19:31.939 [311406] <2> report_drives: ALOCID = 932011 04:19:31.939 [311406] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 04:19:31.939 [311406] <2> report_drives: PID = 405582 04:19:31.939 [311406] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 04:19:31.956 [311406] <2> main: Sending [EXIT STATUS 0] to NBJM 04:19:31.956 [311406] <2> bptm: EXITING with status 0 <---------- 04:19:40.966 [532640] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 04:19:40.982 [532640] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 04:19:40.982 [532640] <2> bptm: EXITING with status 0 <---------- 04:27:58.561 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 793625413 blocks in cpr: 793625413 04:27:58.593 [405582] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -9 04:27:58.598 [405582] <2> write_backup: tp.tv_sec = 1389558478, stp.tv_sec = 1389556669, tp.tv_usec = 570352, stp.tv_usec = 83940, et = 3537712, mpx_total_kbytes[TWIN_INDEX = 0] = 397589248 04:27:58.641 [405582] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.18563) on drive index 0 04:28:02.651 [405582] <2> write_backup: checkpoint occurred copy 1 --- Fragmenting 04:28:02.676 [405582] <2> write_backup_update_frags: ************** Fragment 2: ******************* 04:28:02.688 [405582] <2> write_backup_update_frags: ++++ total image kbytes so far = 397589248 ++++ ` 04:28:02.688 [405582] <2> write_backup_update_frags: ++++ fragment_num = 2 ++++ 04:28:02.688 [405582] <2> write_backup_update_frags: copy_num = 1 04:28:02.688 [405582] <2> write_backup_update_frags: Kbytes = 233497856 04:28:02.688 [405582] <2> write_backup_update_frags: remainder = 0 04:28:02.688 [405582] <2> write_backup_update_frags: id = 0120L4 04:28:02.689 [405582] <2> write_backup_update_frags: file_num = 5 04:28:02.689 [405582] <2> write_backup_update_frags: block_size = 262144 04:28:02.689 [405582] <2> write_backup_update_frags: offset = 1653184 04:28:02.689 [405582] <2> write_backup_update_frags: ****************************************************** 04:28:02.848 [405582] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 04:28:02.882 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 04:28:02.882 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 04:28:03.065 [405582] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 04:28:03.065 [405582] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35193 TO 10.2.21.10.13724 fd = 23 04:28:03.065 [405582] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.35193 TO 10.2.21.10.13724 04:28:03.077 [405582] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 04:28:03.077 [405582] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 04:28:03.077 [405582] <2> check_authentication: no authentication required 04:28:03.077 [405582] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 04:28:03.077 [405582] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 04:28:03.673 [405582] <2> send_MDS_msg: MEDIADB 1 932011 0120L4 4000982 *NULL* 6 1389468610 1389555007 1391974207 0 656710302 5 5 2 1 0 512 1024 0 1012200 0 04:28:03.915 [405582] <2> write_backup: Setting CPR_COMPLETE, index: 0 04:28:03.930 [405582] <2> process_brm_msg: no pending message from bpbrm 04:28:03.988 [405582] <2> write_data: ndmp_dup_max_frag is set to 1073741824000 04:28:03.988 [405582] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: 0 twin_is_disk 0 delay_brm: 0 04:28:04.004 [405582] <2> io_ioctl: command (12)MTBSF 1 from (bptm.c.21169) on drive index 0 04:28:05.540 [405582] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.21176 04:28:05.668 [405582] <2> write_data: absolute block position prior to writing backup header(s) is 2565287, copy 1 04:28:05.683 [405582] <2> io_open: SCSI RESERVE 04:28:05.688 [405582] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 04:28:05.688 [405582] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.21229) on drive index 0 04:28:08.111 [405582] <2> write_data: block position check: actual 2565287, expected 2565287 04:28:08.111 [405582] <2> io_write_back_header: drive index 0, AIXBK_1389555007, file num = 6, mpx_headers = 1, copy 1 04:28:08.133 [405582] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1 04:28:08.133 [405582] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0 04:28:08.133 [405582] <2> write_data: received first buffer (262144 bytes), begin writing data 04:29:31.329 [331888] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007765 -jm 04:29:31.371 [331888] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 04:29:31.380 [331888] <2> bptm: PORT_STATUS = 0x00000000 04:29:31.409 [331888] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 04:29:31.414 [331888] <2> drivename_checklock: Called 04:29:31.414 [331888] <2> drivename_checklock: PID 405582 has lock 04:29:31.426 [331888] <2> report_drives: MODE = 0 04:29:31.426 [331888] <2> report_drives: TIME = 1389554796 04:29:31.426 [331888] <2> report_drives: MASTER = hqmb1 04:29:31.426 [331888] <2> report_drives: PATH = /dev/rmt0.1 04:29:31.426 [331888] <2> report_drives: MEDIA = 0120L4 04:29:31.426 [331888] <2> report_drives: REQID = -1389007744 04:29:31.426 [331888] <2> report_drives: ALOCID = 932011 04:29:31.426 [331888] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 04:29:31.426 [331888] <2> report_drives: PID = 405582 04:29:31.426 [331888] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 04:29:31.434 [331888] <2> main: Sending [EXIT STATUS 0] to NBJM 04:29:31.434 [331888] <2> bptm: EXITING with status 0 <---------- 04:29:49.281 [344292] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 04:29:49.302 [344292] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 04:29:49.303 [344292] <2> bptm: EXITING with status 0 <---------- 04:39:30.263 [209120] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007768 -jm 04:39:30.313 [209120] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 04:39:30.325 [209120] <2> bptm: PORT_STATUS = 0x00000000 04:39:30.359 [209120] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 04:39:30.363 [209120] <2> drivename_checklock: Called 04:39:30.363 [209120] <2> drivename_checklock: PID 405582 has lock 04:39:30.375 [209120] <2> report_drives: MODE = 0 04:39:30.375 [209120] <2> report_drives: TIME = 1389554796 04:39:30.375 [209120] <2> report_drives: MASTER = hqmb1 04:39:30.375 [209120] <2> report_drives: PATH = /dev/rmt0.1 04:39:30.375 [209120] <2> report_drives: MEDIA = 0120L4 04:39:30.375 [209120] <2> report_drives: REQID = -1389007744 04:39:30.375 [209120] <2> report_drives: ALOCID = 932011 04:39:30.375 [209120] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 04:39:30.375 [209120] <2> report_drives: PID = 405582 04:39:30.375 [209120] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 04:39:30.382 [209120] <2> main: Sending [EXIT STATUS 0] to NBJM 04:39:30.382 [209120] <2> bptm: EXITING with status 0 <---------- 04:40:08.537 [548978] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 04:40:08.580 [548978] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 04:40:08.597 [548978] <2> bptm: EXITING with status 0 <---------- 04:49:30.728 [548938] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007771 -jm 04:49:30.801 [548938] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 04:49:30.808 [548938] <2> bptm: PORT_STATUS = 0x00000000 04:49:30.888 [548938] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 04:49:30.895 [548938] <2> drivename_checklock: Called 04:49:30.895 [548938] <2> drivename_checklock: PID 405582 has lock 04:49:30.903 [548938] <2> report_drives: MODE = 0 04:49:30.903 [548938] <2> report_drives: TIME = 1389554796 04:49:30.903 [548938] <2> report_drives: MASTER = hqmb1 04:49:30.903 [548938] <2> report_drives: PATH = /dev/rmt0.1 04:49:30.903 [548938] <2> report_drives: MEDIA = 0120L4 04:49:30.903 [548938] <2> report_drives: REQID = -1389007744 04:49:30.903 [548938] <2> report_drives: ALOCID = 932011 04:49:30.903 [548938] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 04:49:30.903 [548938] <2> report_drives: PID = 405582 04:49:30.903 [548938] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 04:49:30.927 [548938] <2> main: Sending [EXIT STATUS 0] to NBJM 04:49:30.927 [548938] <2> bptm: EXITING with status 0 <---------- 04:50:27.112 [548956] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 04:50:27.130 [548956] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 04:50:27.130 [548956] <2> bptm: EXITING with status 0 <---------- 04:58:55.846 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 1267716394 blocks in cpr: 1267716394 04:58:55.871 [405582] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -9 04:58:55.879 [405582] <2> write_backup: tp.tv_sec = 1389560335, stp.tv_sec = 1389558488, tp.tv_usec = 859571, stp.tv_usec = 133177, et = 5385438, mpx_total_kbytes[TWIN_INDEX = 0] = 635098624 04:58:55.921 [405582] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.18563) on drive index 0 04:58:58.275 [405582] <2> write_backup: checkpoint occurred copy 1 --- Fragmenting 04:58:58.306 [405582] <2> write_backup_update_frags: ************** Fragment 3: ******************* 04:58:58.306 [405582] <2> write_backup_update_frags: ++++ total image kbytes so far = 635098624 ++++ ` 04:58:58.306 [405582] <2> write_backup_update_frags: ++++ fragment_num = 3 ++++ 04:58:58.306 [405582] <2> write_backup_update_frags: copy_num = 1 04:58:58.306 [405582] <2> write_backup_update_frags: Kbytes = 237509376 04:58:58.306 [405582] <2> write_backup_update_frags: remainder = 0 04:58:58.306 [405582] <2> write_backup_update_frags: id = 0120L4 04:58:58.306 [405582] <2> write_backup_update_frags: file_num = 6 04:58:58.306 [405582] <2> write_backup_update_frags: block_size = 262144 04:58:58.306 [405582] <2> write_backup_update_frags: offset = 2565287 04:58:58.306 [405582] <2> write_backup_update_frags: ****************************************************** 04:58:58.417 [405582] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 04:58:58.450 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 04:58:58.451 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 04:58:58.602 [405582] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 04:58:58.622 [405582] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35258 TO 10.2.21.10.13724 fd = 23 04:58:58.622 [405582] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.35258 TO 10.2.21.10.13724 04:58:58.626 [405582] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 04:58:58.627 [405582] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 04:58:58.627 [405582] <2> check_authentication: no authentication required 04:58:58.627 [405582] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 04:58:58.627 [405582] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 04:58:59.102 [405582] <2> send_MDS_msg: MEDIADB 1 932011 0120L4 4000982 *NULL* 6 1389468610 1389555007 1391974207 0 894219678 6 6 2 1 0 512 1024 0 1012200 0 04:58:59.393 [405582] <2> write_backup: Setting CPR_COMPLETE, index: 0 04:58:59.407 [405582] <2> process_brm_msg: no pending message from bpbrm 04:58:59.458 [405582] <2> write_data: ndmp_dup_max_frag is set to 1073741824000 04:58:59.458 [405582] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: 0 twin_is_disk 0 delay_brm: 0 04:58:59.469 [405582] <2> io_ioctl: command (12)MTBSF 1 from (bptm.c.21169) on drive index 0 04:59:01.328 [405582] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.21176 04:59:01.478 [405582] <2> write_data: absolute block position prior to writing backup header(s) is 3493060, copy 1 04:59:01.497 [405582] <2> io_open: SCSI RESERVE 04:59:01.506 [405582] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 04:59:01.506 [405582] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.21229) on drive index 0 04:59:03.832 [405582] <2> write_data: block position check: actual 3493060, expected 3493060 04:59:03.837 [405582] <2> io_write_back_header: drive index 0, AIXBK_1389555007, file num = 7, mpx_headers = 1, copy 1 04:59:03.854 [405582] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1 04:59:03.854 [405582] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0 04:59:03.854 [405582] <2> write_data: received first buffer (262144 bytes), begin writing data 04:59:29.581 [548924] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007775 -jm 04:59:29.612 [548924] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 04:59:29.612 [548924] <2> bptm: PORT_STATUS = 0x00000000 04:59:29.637 [548924] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 04:59:29.640 [548924] <2> drivename_checklock: Called 04:59:29.640 [548924] <2> drivename_checklock: PID 405582 has lock 04:59:29.650 [548924] <2> report_drives: MODE = 0 04:59:29.650 [548924] <2> report_drives: TIME = 1389554796 04:59:29.650 [548924] <2> report_drives: MASTER = hqmb1 04:59:29.650 [548924] <2> report_drives: PATH = /dev/rmt0.1 04:59:29.650 [548924] <2> report_drives: MEDIA = 0120L4 04:59:29.650 [548924] <2> report_drives: REQID = -1389007744 04:59:29.650 [548924] <2> report_drives: ALOCID = 932011 04:59:29.650 [548924] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 04:59:29.650 [548924] <2> report_drives: PID = 405582 04:59:29.650 [548924] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 04:59:29.659 [548924] <2> main: Sending [EXIT STATUS 0] to NBJM 04:59:29.659 [548924] <2> bptm: EXITING with status 0 <---------- 05:00:42.463 [602194] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 05:00:42.502 [602194] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 05:00:42.519 [602194] <2> bptm: EXITING with status 0 <---------- 05:09:30.162 [602164] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007778 -jm 05:09:30.202 [602164] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 05:09:30.212 [602164] <2> bptm: PORT_STATUS = 0x00000000 05:09:30.251 [602164] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 05:09:30.254 [602164] <2> drivename_checklock: Called 05:09:30.254 [602164] <2> drivename_checklock: PID 405582 has lock 05:09:30.266 [602164] <2> report_drives: MODE = 0 05:09:30.266 [602164] <2> report_drives: TIME = 1389554796 05:09:30.266 [602164] <2> report_drives: MASTER = hqmb1 05:09:30.266 [602164] <2> report_drives: PATH = /dev/rmt0.1 05:09:30.266 [602164] <2> report_drives: MEDIA = 0120L4 05:09:30.266 [602164] <2> report_drives: REQID = -1389007744 05:09:30.266 [602164] <2> report_drives: ALOCID = 932011 05:09:30.266 [602164] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 05:09:30.266 [602164] <2> report_drives: PID = 405582 05:09:30.266 [602164] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 05:09:30.276 [602164] <2> main: Sending [EXIT STATUS 0] to NBJM 05:09:30.276 [602164] <2> bptm: EXITING with status 0 <---------- 05:10:56.565 [295090] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 05:10:56.609 [295090] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 05:10:56.644 [295090] <2> bptm: EXITING with status 0 <---------- 05:19:29.927 [208960] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007781 -jm 05:19:29.971 [208960] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 05:19:29.991 [208960] <2> bptm: PORT_STATUS = 0x00000000 05:19:30.034 [208960] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 05:19:30.039 [208960] <2> drivename_checklock: Called 05:19:30.040 [208960] <2> drivename_checklock: PID 405582 has lock 05:19:30.051 [208960] <2> report_drives: MODE = 0 05:19:30.051 [208960] <2> report_drives: TIME = 1389554796 05:19:30.051 [208960] <2> report_drives: MASTER = hqmb1 05:19:30.051 [208960] <2> report_drives: PATH = /dev/rmt0.1 05:19:30.051 [208960] <2> report_drives: MEDIA = 0120L4 05:19:30.051 [208960] <2> report_drives: REQID = -1389007744 05:19:30.051 [208960] <2> report_drives: ALOCID = 932011 05:19:30.051 [208960] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 05:19:30.051 [208960] <2> report_drives: PID = 405582 05:19:30.051 [208960] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 05:19:30.059 [208960] <2> main: Sending [EXIT STATUS 0] to NBJM 05:19:30.059 [208960] <2> bptm: EXITING with status 0 <---------- 05:21:06.125 [315492] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 05:21:06.165 [315492] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 05:21:06.175 [315492] <2> bptm: EXITING with status 0 <---------- 05:29:04.704 [405582] <2> write_data: Received checkpoint for backup id AIXBK_1389555007, calculated blocks: 1707668998 blocks in cpr: 1707668998 05:29:04.733 [405582] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -9 05:29:04.745 [405582] <2> write_backup: tp.tv_sec = 1389562144, stp.tv_sec = 1389560343, tp.tv_usec = 721881, stp.tv_usec = 854537, et = 7186306, mpx_total_kbytes[TWIN_INDEX = 0] = 855505408 05:29:04.832 [405582] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.18563) on drive index 0 05:29:08.762 [405582] <2> write_backup: checkpoint occurred copy 1 --- Fragmenting 05:29:08.796 [405582] <2> write_backup_update_frags: ************** Fragment 4: ******************* 05:29:08.796 [405582] <2> write_backup_update_frags: ++++ total image kbytes so far = 855505408 ++++ ` 05:29:08.796 [405582] <2> write_backup_update_frags: ++++ fragment_num = 4 ++++ 05:29:08.796 [405582] <2> write_backup_update_frags: copy_num = 1 05:29:08.796 [405582] <2> write_backup_update_frags: Kbytes = 220406784 05:29:08.796 [405582] <2> write_backup_update_frags: remainder = 0 05:29:08.796 [405582] <2> write_backup_update_frags: id = 0120L4 05:29:08.796 [405582] <2> write_backup_update_frags: file_num = 7 05:29:08.796 [405582] <2> write_backup_update_frags: block_size = 262144 05:29:08.796 [405582] <2> write_backup_update_frags: offset = 3493060 05:29:08.800 [405582] <2> write_backup_update_frags: ****************************************************** 05:29:08.947 [405582] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 05:29:08.983 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 05:29:08.983 [405582] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 05:29:09.178 [405582] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 05:29:09.179 [405582] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35325 TO 10.2.21.10.13724 fd = 23 05:29:09.179 [405582] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.35325 TO 10.2.21.10.13724 05:29:09.193 [405582] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 05:29:09.193 [405582] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 05:29:09.193 [405582] <2> check_authentication: no authentication required 05:29:09.193 [405582] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 05:29:09.193 [405582] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 05:29:09.612 [405582] <2> send_MDS_msg: MEDIADB 1 932011 0120L4 4000982 *NULL* 6 1389468610 1389555007 1391974207 0 1114626462 7 7 2 1 0 512 1024 0 1012200 0 05:29:09.867 [405582] <2> write_backup: Setting CPR_COMPLETE, index: 0 05:29:09.886 [405582] <2> process_brm_msg: no pending message from bpbrm 05:29:09.932 [405582] <2> write_data: ndmp_dup_max_frag is set to 1073741824000 05:29:09.932 [405582] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: 0 twin_is_disk 0 delay_brm: 0 05:29:09.943 [405582] <2> io_ioctl: command (12)MTBSF 1 from (bptm.c.21169) on drive index 0 05:29:11.604 [405582] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.21176 05:29:11.748 [405582] <2> write_data: absolute block position prior to writing backup header(s) is 4354026, copy 1 05:29:11.763 [405582] <2> io_open: SCSI RESERVE 05:29:11.768 [405582] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 05:29:11.768 [405582] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.21229) on drive index 0 05:29:14.158 [405582] <2> write_data: block position check: actual 4354026, expected 4354026 05:29:14.159 [405582] <2> io_write_back_header: drive index 0, AIXBK_1389555007, file num = 8, mpx_headers = 1, copy 1 05:29:14.180 [405582] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1 05:29:14.180 [405582] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0 05:29:14.180 [405582] <2> write_data: received first buffer (262144 bytes), begin writing data 05:29:29.349 [315456] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007784 -jm 05:29:29.381 [315456] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 05:29:29.382 [315456] <2> bptm: PORT_STATUS = 0x00000000 05:29:29.425 [315456] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 05:29:29.429 [315456] <2> drivename_checklock: Called 05:29:29.429 [315456] <2> drivename_checklock: PID 405582 has lock 05:29:29.466 [315456] <2> report_drives: MODE = 0 05:29:29.466 [315456] <2> report_drives: TIME = 1389554796 05:29:29.466 [315456] <2> report_drives: MASTER = hqmb1 05:29:29.466 [315456] <2> report_drives: PATH = /dev/rmt0.1 05:29:29.466 [315456] <2> report_drives: MEDIA = 0120L4 05:29:29.466 [315456] <2> report_drives: REQID = -1389007744 05:29:29.466 [315456] <2> report_drives: ALOCID = 932011 05:29:29.466 [315456] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 05:29:29.466 [315456] <2> report_drives: PID = 405582 05:29:29.466 [315456] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 05:29:29.503 [315456] <2> main: Sending [EXIT STATUS 0] to NBJM 05:29:29.504 [315456] <2> bptm: EXITING with status 0 <---------- 05:31:20.125 [209008] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 05:31:20.176 [209008] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 05:31:20.195 [209008] <2> bptm: EXITING with status 0 <---------- 05:39:28.622 [589888] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007788 -jm 05:39:28.643 [589888] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 05:39:28.651 [589888] <2> bptm: PORT_STATUS = 0x00000000 05:39:28.659 [589888] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 05:39:28.659 [589888] <2> drivename_checklock: Called 05:39:28.659 [589888] <2> drivename_checklock: PID 405582 has lock 05:39:28.666 [589888] <2> report_drives: MODE = 0 05:39:28.666 [589888] <2> report_drives: TIME = 1389554796 05:39:28.666 [589888] <2> report_drives: MASTER = hqmb1 05:39:28.666 [589888] <2> report_drives: PATH = /dev/rmt0.1 05:39:28.666 [589888] <2> report_drives: MEDIA = 0120L4 05:39:28.666 [589888] <2> report_drives: REQID = -1389007744 05:39:28.666 [589888] <2> report_drives: ALOCID = 932011 05:39:28.666 [589888] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 05:39:28.666 [589888] <2> report_drives: PID = 405582 05:39:28.666 [589888] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 05:39:28.671 [589888] <2> main: Sending [EXIT STATUS 0] to NBJM 05:39:28.671 [589888] <2> bptm: EXITING with status 0 <---------- 05:41:47.856 [589966] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 05:41:47.868 [589966] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 05:41:47.868 [589966] <2> bptm: EXITING with status 0 <---------- 05:49:27.727 [549058] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007791 -jm 05:49:27.740 [549058] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 05:49:27.740 [549058] <2> bptm: PORT_STATUS = 0x00000000 05:49:27.740 [549058] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 05:49:27.740 [549058] <2> drivename_checklock: Called 05:49:27.740 [549058] <2> drivename_checklock: PID 405582 has lock 05:49:27.740 [549058] <2> report_drives: MODE = 0 05:49:27.740 [549058] <2> report_drives: TIME = 1389554796 05:49:27.740 [549058] <2> report_drives: MASTER = hqmb1 05:49:27.740 [549058] <2> report_drives: PATH = /dev/rmt0.1 05:49:27.740 [549058] <2> report_drives: MEDIA = 0120L4 05:49:27.740 [549058] <2> report_drives: REQID = -1389007744 05:49:27.740 [549058] <2> report_drives: ALOCID = 932011 05:49:27.740 [549058] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 05:49:27.740 [549058] <2> report_drives: PID = 405582 05:49:27.740 [549058] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 05:49:27.740 [549058] <2> main: Sending [EXIT STATUS 0] to NBJM 05:49:27.740 [549058] <2> bptm: EXITING with status 0 <---------- 05:52:03.994 [549084] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 05:52:04.006 [549084] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 05:52:04.006 [549084] <2> bptm: EXITING with status 0 <---------- 05:59:28.088 [385150] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007795 -jm 05:59:28.100 [385150] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 05:59:28.101 [385150] <2> bptm: PORT_STATUS = 0x00000000 05:59:28.101 [385150] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 05:59:28.101 [385150] <2> drivename_checklock: Called 05:59:28.101 [385150] <2> drivename_checklock: PID 405582 has lock 05:59:28.101 [385150] <2> report_drives: MODE = 0 05:59:28.101 [385150] <2> report_drives: TIME = 1389554796 05:59:28.101 [385150] <2> report_drives: MASTER = hqmb1 05:59:28.106 [385150] <2> report_drives: PATH = /dev/rmt0.1 05:59:28.106 [385150] <2> report_drives: MEDIA = 0120L4 05:59:28.106 [385150] <2> report_drives: REQID = -1389007744 05:59:28.106 [385150] <2> report_drives: ALOCID = 932011 05:59:28.106 [385150] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 05:59:28.106 [385150] <2> report_drives: PID = 405582 05:59:28.106 [385150] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 05:59:28.106 [385150] <2> main: Sending [EXIT STATUS 0] to NBJM 05:59:28.106 [385150] <2> bptm: EXITING with status 0 <---------- 06:02:13.974 [602126] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 06:02:13.986 [602126] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 06:02:13.986 [602126] <2> bptm: EXITING with status 0 <---------- 06:09:27.629 [602138] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007799 -jm 06:09:27.641 [602138] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 06:09:27.641 [602138] <2> bptm: PORT_STATUS = 0x00000000 06:09:27.641 [602138] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 06:09:27.641 [602138] <2> drivename_checklock: Called 06:09:27.641 [602138] <2> drivename_checklock: PID 405582 has lock 06:09:27.641 [602138] <2> report_drives: MODE = 0 06:09:27.642 [602138] <2> report_drives: TIME = 1389554796 06:09:27.642 [602138] <2> report_drives: MASTER = hqmb1 06:09:27.642 [602138] <2> report_drives: PATH = /dev/rmt0.1 06:09:27.642 [602138] <2> report_drives: MEDIA = 0120L4 06:09:27.642 [602138] <2> report_drives: REQID = -1389007744 06:09:27.642 [602138] <2> report_drives: ALOCID = 932011 06:09:27.642 [602138] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 06:09:27.642 [602138] <2> report_drives: PID = 405582 06:09:27.642 [602138] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 06:09:27.642 [602138] <2> main: Sending [EXIT STATUS 0] to NBJM 06:09:27.642 [602138] <2> bptm: EXITING with status 0 <---------- 06:12:38.871 [295122] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 06:12:38.883 [295122] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 06:12:38.883 [295122] <2> bptm: EXITING with status 0 <---------- 06:19:27.978 [602134] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007802 -jm 06:19:27.990 [602134] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 06:19:27.990 [602134] <2> bptm: PORT_STATUS = 0x00000000 06:19:27.990 [602134] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 06:19:27.990 [602134] <2> drivename_checklock: Called 06:19:27.990 [602134] <2> drivename_checklock: PID 405582 has lock 06:19:27.990 [602134] <2> report_drives: MODE = 0 06:19:27.990 [602134] <2> report_drives: TIME = 1389554796 06:19:27.990 [602134] <2> report_drives: MASTER = hqmb1 06:19:27.990 [602134] <2> report_drives: PATH = /dev/rmt0.1 06:19:27.990 [602134] <2> report_drives: MEDIA = 0120L4 06:19:27.990 [602134] <2> report_drives: REQID = -1389007744 06:19:27.990 [602134] <2> report_drives: ALOCID = 932011 06:19:27.991 [602134] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 06:19:27.991 [602134] <2> report_drives: PID = 405582 06:19:27.991 [602134] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 06:19:27.991 [602134] <2> main: Sending [EXIT STATUS 0] to NBJM 06:19:27.991 [602134] <2> bptm: EXITING with status 0 <---------- 06:23:05.665 [602170] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 06:23:05.678 [602170] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 06:23:05.678 [602170] <2> bptm: EXITING with status 0 <---------- 06:29:29.933 [385062] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007805 -jm 06:29:29.946 [385062] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 06:29:29.946 [385062] <2> bptm: PORT_STATUS = 0x00000000 06:29:29.950 [385062] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 06:29:29.950 [385062] <2> drivename_checklock: Called 06:29:29.950 [385062] <2> drivename_checklock: PID 405582 has lock 06:29:29.950 [385062] <2> report_drives: MODE = 0 06:29:29.950 [385062] <2> report_drives: TIME = 1389554796 06:29:29.950 [385062] <2> report_drives: MASTER = hqmb1 06:29:29.950 [385062] <2> report_drives: PATH = /dev/rmt0.1 06:29:29.950 [385062] <2> report_drives: MEDIA = 0120L4 06:29:29.950 [385062] <2> report_drives: REQID = -1389007744 06:29:29.950 [385062] <2> report_drives: ALOCID = 932011 06:29:29.950 [385062] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 06:29:29.950 [385062] <2> report_drives: PID = 405582 06:29:29.950 [385062] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 06:29:29.950 [385062] <2> main: Sending [EXIT STATUS 0] to NBJM 06:29:29.950 [385062] <2> bptm: EXITING with status 0 <---------- 06:33:13.644 [295162] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 06:33:13.656 [295162] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 06:33:13.657 [295162] <2> bptm: EXITING with status 0 <---------- 06:39:27.471 [385042] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007808 -jm 06:39:27.483 [385042] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 06:39:27.483 [385042] <2> bptm: PORT_STATUS = 0x00000000 06:39:27.483 [385042] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 06:39:27.483 [385042] <2> drivename_checklock: Called 06:39:27.483 [385042] <2> drivename_checklock: PID 405582 has lock 06:39:27.483 [385042] <2> report_drives: MODE = 0 06:39:27.483 [385042] <2> report_drives: TIME = 1389554796 06:39:27.483 [385042] <2> report_drives: MASTER = hqmb1 06:39:27.483 [385042] <2> report_drives: PATH = /dev/rmt0.1 06:39:27.483 [385042] <2> report_drives: MEDIA = 0120L4 06:39:27.483 [385042] <2> report_drives: REQID = -1389007744 06:39:27.483 [385042] <2> report_drives: ALOCID = 932011 06:39:27.483 [385042] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 06:39:27.483 [385042] <2> report_drives: PID = 405582 06:39:27.483 [385042] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 06:39:27.483 [385042] <2> main: Sending [EXIT STATUS 0] to NBJM 06:39:27.483 [385042] <2> bptm: EXITING with status 0 <---------- 06:43:22.668 [614410] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 06:43:22.680 [614410] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 06:43:22.681 [614410] <2> bptm: EXITING with status 0 <---------- 06:49:28.235 [294994] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007811 -jm 06:49:28.247 [294994] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 06:49:28.247 [294994] <2> bptm: PORT_STATUS = 0x00000000 06:49:28.247 [294994] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 06:49:28.247 [294994] <2> drivename_checklock: Called 06:49:28.247 [294994] <2> drivename_checklock: PID 405582 has lock 06:49:28.247 [294994] <2> report_drives: MODE = 0 06:49:28.247 [294994] <2> report_drives: TIME = 1389554796 06:49:28.247 [294994] <2> report_drives: MASTER = hqmb1 06:49:28.247 [294994] <2> report_drives: PATH = /dev/rmt0.1 06:49:28.247 [294994] <2> report_drives: MEDIA = 0120L4 06:49:28.247 [294994] <2> report_drives: REQID = -1389007744 06:49:28.247 [294994] <2> report_drives: ALOCID = 932011 06:49:28.247 [294994] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 06:49:28.247 [294994] <2> report_drives: PID = 405582 06:49:28.247 [294994] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 06:49:28.247 [294994] <2> main: Sending [EXIT STATUS 0] to NBJM 06:49:28.247 [294994] <2> bptm: EXITING with status 0 <---------- 06:53:34.019 [295026] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 06:53:34.031 [295026] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 06:53:34.039 [295026] <2> bptm: EXITING with status 0 <---------- 06:59:28.172 [589912] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007815 -jm 06:59:28.184 [589912] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 06:59:28.184 [589912] <2> bptm: PORT_STATUS = 0x00000000 06:59:28.184 [589912] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 06:59:28.184 [589912] <2> drivename_checklock: Called 06:59:28.184 [589912] <2> drivename_checklock: PID 405582 has lock 06:59:28.184 [589912] <2> report_drives: MODE = 0 06:59:28.184 [589912] <2> report_drives: TIME = 1389554796 06:59:28.184 [589912] <2> report_drives: MASTER = hqmb1 06:59:28.184 [589912] <2> report_drives: PATH = /dev/rmt0.1 06:59:28.184 [589912] <2> report_drives: MEDIA = 0120L4 06:59:28.184 [589912] <2> report_drives: REQID = -1389007744 06:59:28.184 [589912] <2> report_drives: ALOCID = 932011 06:59:28.184 [589912] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 06:59:28.184 [589912] <2> report_drives: PID = 405582 06:59:28.184 [589912] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 06:59:28.184 [589912] <2> main: Sending [EXIT STATUS 0] to NBJM 06:59:28.184 [589912] <2> bptm: EXITING with status 0 <---------- 07:03:43.140 [295150] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 07:03:43.152 [295150] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 07:03:43.152 [295150] <2> bptm: EXITING with status 0 <---------- 07:09:27.745 [614606] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007818 -jm 07:09:27.757 [614606] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 07:09:27.758 [614606] <2> bptm: PORT_STATUS = 0x00000000 07:09:27.758 [614606] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 07:09:27.758 [614606] <2> drivename_checklock: Called 07:09:27.758 [614606] <2> drivename_checklock: PID 405582 has lock 07:09:27.758 [614606] <2> report_drives: MODE = 0 07:09:27.758 [614606] <2> report_drives: TIME = 1389554796 07:09:27.758 [614606] <2> report_drives: MASTER = hqmb1 07:09:27.758 [614606] <2> report_drives: PATH = /dev/rmt0.1 07:09:27.758 [614606] <2> report_drives: MEDIA = 0120L4 07:09:27.758 [614606] <2> report_drives: REQID = -1389007744 07:09:27.758 [614606] <2> report_drives: ALOCID = 932011 07:09:27.758 [614606] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 07:09:27.758 [614606] <2> report_drives: PID = 405582 07:09:27.758 [614606] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 07:09:27.758 [614606] <2> main: Sending [EXIT STATUS 0] to NBJM 07:09:27.758 [614606] <2> bptm: EXITING with status 0 <---------- 07:13:51.921 [344262] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 07:13:51.933 [344262] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 07:13:51.933 [344262] <2> bptm: EXITING with status 0 <---------- 07:19:29.085 [614454] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007821 -jm 07:19:29.097 [614454] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 07:19:29.098 [614454] <2> bptm: PORT_STATUS = 0x00000000 07:19:29.098 [614454] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 07:19:29.098 [614454] <2> drivename_checklock: Called 07:19:29.098 [614454] <2> drivename_checklock: PID 405582 has lock 07:19:29.098 [614454] <2> report_drives: MODE = 0 07:19:29.098 [614454] <2> report_drives: TIME = 1389554796 07:19:29.098 [614454] <2> report_drives: MASTER = hqmb1 07:19:29.098 [614454] <2> report_drives: PATH = /dev/rmt0.1 07:19:29.098 [614454] <2> report_drives: MEDIA = 0120L4 07:19:29.098 [614454] <2> report_drives: REQID = -1389007744 07:19:29.098 [614454] <2> report_drives: ALOCID = 932011 07:19:29.098 [614454] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 07:19:29.098 [614454] <2> report_drives: PID = 405582 07:19:29.104 [614454] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 07:19:29.104 [614454] <2> main: Sending [EXIT STATUS 0] to NBJM 07:19:29.104 [614454] <2> bptm: EXITING with status 0 <---------- 07:24:00.456 [315618] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 07:24:00.468 [315618] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 07:24:00.468 [315618] <2> bptm: EXITING with status 0 <---------- 07:29:27.627 [344270] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007824 -jm 07:29:27.639 [344270] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 07:29:27.639 [344270] <2> bptm: PORT_STATUS = 0x00000000 07:29:27.639 [344270] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 07:29:27.639 [344270] <2> drivename_checklock: Called 07:29:27.639 [344270] <2> drivename_checklock: PID 405582 has lock 07:29:27.639 [344270] <2> report_drives: MODE = 0 07:29:27.639 [344270] <2> report_drives: TIME = 1389554796 07:29:27.639 [344270] <2> report_drives: MASTER = hqmb1 07:29:27.639 [344270] <2> report_drives: PATH = /dev/rmt0.1 07:29:27.639 [344270] <2> report_drives: MEDIA = 0120L4 07:29:27.639 [344270] <2> report_drives: REQID = -1389007744 07:29:27.639 [344270] <2> report_drives: ALOCID = 932011 07:29:27.639 [344270] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 07:29:27.639 [344270] <2> report_drives: PID = 405582 07:29:27.639 [344270] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 07:29:27.639 [344270] <2> main: Sending [EXIT STATUS 0] to NBJM 07:29:27.639 [344270] <2> bptm: EXITING with status 0 <---------- 07:34:09.654 [549014] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 07:34:09.666 [549014] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 07:34:09.666 [549014] <2> bptm: EXITING with status 0 <---------- 07:39:28.179 [315510] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007827 -jm 07:39:28.191 [315510] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 07:39:28.191 [315510] <2> bptm: PORT_STATUS = 0x00000000 07:39:28.191 [315510] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 07:39:28.191 [315510] <2> drivename_checklock: Called 07:39:28.191 [315510] <2> drivename_checklock: PID 405582 has lock 07:39:28.191 [315510] <2> report_drives: MODE = 0 07:39:28.192 [315510] <2> report_drives: TIME = 1389554796 07:39:28.192 [315510] <2> report_drives: MASTER = hqmb1 07:39:28.192 [315510] <2> report_drives: PATH = /dev/rmt0.1 07:39:28.192 [315510] <2> report_drives: MEDIA = 0120L4 07:39:28.192 [315510] <2> report_drives: REQID = -1389007744 07:39:28.192 [315510] <2> report_drives: ALOCID = 932011 07:39:28.192 [315510] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 07:39:28.192 [315510] <2> report_drives: PID = 405582 07:39:28.192 [315510] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 07:39:28.192 [315510] <2> main: Sending [EXIT STATUS 0] to NBJM 07:39:28.192 [315510] <2> bptm: EXITING with status 0 <---------- 07:44:18.871 [344236] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 07:44:18.883 [344236] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 07:44:18.883 [344236] <2> bptm: EXITING with status 0 <---------- 07:49:27.539 [548882] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007830 -jm 07:49:27.552 [548882] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 07:49:27.552 [548882] <2> bptm: PORT_STATUS = 0x00000000 07:49:27.552 [548882] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 07:49:27.552 [548882] <2> drivename_checklock: Called 07:49:27.552 [548882] <2> drivename_checklock: PID 405582 has lock 07:49:27.552 [548882] <2> report_drives: MODE = 0 07:49:27.552 [548882] <2> report_drives: TIME = 1389554796 07:49:27.552 [548882] <2> report_drives: MASTER = hqmb1 07:49:27.556 [548882] <2> report_drives: PATH = /dev/rmt0.1 07:49:27.556 [548882] <2> report_drives: MEDIA = 0120L4 07:49:27.556 [548882] <2> report_drives: REQID = -1389007744 07:49:27.556 [548882] <2> report_drives: ALOCID = 932011 07:49:27.556 [548882] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 07:49:27.556 [548882] <2> report_drives: PID = 405582 07:49:27.556 [548882] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 07:49:27.556 [548882] <2> main: Sending [EXIT STATUS 0] to NBJM 07:49:27.556 [548882] <2> bptm: EXITING with status 0 <---------- 07:54:27.983 [311462] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 07:54:27.995 [311462] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 07:54:27.995 [311462] <2> bptm: EXITING with status 0 <---------- 07:59:27.706 [385152] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007833 -jm 07:59:27.718 [385152] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 07:59:27.718 [385152] <2> bptm: PORT_STATUS = 0x00000000 07:59:27.718 [385152] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 07:59:27.718 [385152] <2> drivename_checklock: Called 07:59:27.718 [385152] <2> drivename_checklock: PID 405582 has lock 07:59:27.718 [385152] <2> report_drives: MODE = 0 07:59:27.718 [385152] <2> report_drives: TIME = 1389554796 07:59:27.718 [385152] <2> report_drives: MASTER = hqmb1 07:59:27.718 [385152] <2> report_drives: PATH = /dev/rmt0.1 07:59:27.718 [385152] <2> report_drives: MEDIA = 0120L4 07:59:27.718 [385152] <2> report_drives: REQID = -1389007744 07:59:27.718 [385152] <2> report_drives: ALOCID = 932011 07:59:27.718 [385152] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 07:59:27.718 [385152] <2> report_drives: PID = 405582 07:59:27.718 [385152] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 07:59:27.719 [385152] <2> main: Sending [EXIT STATUS 0] to NBJM 07:59:27.719 [385152] <2> bptm: EXITING with status 0 <---------- 08:04:37.489 [540882] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 08:04:37.501 [540882] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:04:37.501 [540882] <2> bptm: EXITING with status 0 <---------- 08:09:27.648 [540672] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007836 -jm 08:09:27.660 [540672] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:09:27.660 [540672] <2> bptm: PORT_STATUS = 0x00000000 08:09:27.660 [540672] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 08:09:27.660 [540672] <2> drivename_checklock: Called 08:09:27.660 [540672] <2> drivename_checklock: PID 405582 has lock 08:09:27.660 [540672] <2> report_drives: MODE = 0 08:09:27.660 [540672] <2> report_drives: TIME = 1389554796 08:09:27.660 [540672] <2> report_drives: MASTER = hqmb1 08:09:27.660 [540672] <2> report_drives: PATH = /dev/rmt0.1 08:09:27.660 [540672] <2> report_drives: MEDIA = 0120L4 08:09:27.660 [540672] <2> report_drives: REQID = -1389007744 08:09:27.660 [540672] <2> report_drives: ALOCID = 932011 08:09:27.660 [540672] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 08:09:27.660 [540672] <2> report_drives: PID = 405582 08:09:27.661 [540672] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 08:09:27.661 [540672] <2> main: Sending [EXIT STATUS 0] to NBJM 08:09:27.661 [540672] <2> bptm: EXITING with status 0 <---------- 08:14:47.116 [540696] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 08:14:47.129 [540696] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:14:47.129 [540696] <2> bptm: EXITING with status 0 <---------- 08:19:28.182 [655566] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007839 -jm 08:19:28.194 [655566] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:19:28.194 [655566] <2> bptm: PORT_STATUS = 0x00000000 08:19:28.200 [655566] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 08:19:28.200 [655566] <2> drivename_checklock: Called 08:19:28.200 [655566] <2> drivename_checklock: PID 405582 has lock 08:19:28.200 [655566] <2> report_drives: MODE = 0 08:19:28.200 [655566] <2> report_drives: TIME = 1389554796 08:19:28.200 [655566] <2> report_drives: MASTER = hqmb1 08:19:28.200 [655566] <2> report_drives: PATH = /dev/rmt0.1 08:19:28.200 [655566] <2> report_drives: MEDIA = 0120L4 08:19:28.200 [655566] <2> report_drives: REQID = -1389007744 08:19:28.200 [655566] <2> report_drives: ALOCID = 932011 08:19:28.200 [655566] <2> report_drives: RBID = {5F78EBB9-C5C2-4764-B688-E9AEFA7E71BF 08:19:28.200 [655566] <2> report_drives: PID = 405582 08:19:28.200 [655566] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 08:19:28.200 [655566] <2> main: Sending [EXIT STATUS 0] to NBJM 08:19:28.200 [655566] <2> bptm: EXITING with status 0 <---------- 08:24:45.494 [405582] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -7 08:24:45.506 [405582] <2> write_backup: tp.tv_sec = 1389572685, stp.tv_sec = 1389562154, tp.tv_usec = 467325, stp.tv_usec = 180700, et = 17717592, mpx_total_kbytes[TWIN_INDEX = 0] = 914938880 08:24:45.536 [405582] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.18563) on drive index 0 08:24:47.510 [405582] <2> write_backup_update_frags: ************** Fragment 5: ******************* 08:24:47.510 [405582] <2> write_backup_update_frags: ++++ total image kbytes so far = 914938880 ++++ ` 08:24:47.510 [405582] <2> write_backup_update_frags: ++++ fragment_num = 5 ++++ 08:24:47.510 [405582] <2> write_backup_update_frags: copy_num = 1 08:24:47.510 [405582] <2> write_backup_update_frags: Kbytes = 59433472 08:24:47.510 [405582] <2> write_backup_update_frags: remainder = 0 08:24:47.510 [405582] <2> write_backup_update_frags: id = 0120L4 08:24:47.510 [405582] <2> write_backup_update_frags: file_num = 8 08:24:47.510 [405582] <2> write_backup_update_frags: block_size = 262144 08:24:47.510 [405582] <2> write_backup_update_frags: offset = 4354026 08:24:47.514 [405582] <2> write_backup_update_frags: ****************************************************** 08:24:47.592 [405582] <2> send_MDS_msg: MEDIADB 1 932011 0120L4 4000982 *NULL* 6 1389468610 1389555007 1391974207 0 1174059934 8 8 2 1 0 512 1024 0 1012200 0 08:24:47.903 [405582] <2> read_brm_msg: STOP BACKUP AIXBK_1389555007 08:24:47.910 [405582] <2> io_terminate_tape: writing empty backup header, drive index 0, copy 1 08:24:47.910 [405582] <2> io_terminate_tape: reposition to previous tapemark and rewrite header 08:24:47.910 [405582] <2> io_ioctl: command (12)MTBSF 1 from (bptm.c.8267) on drive index 0 08:24:50.035 [405582] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.8311) on drive index 0 08:24:52.617 [405582] <2> io_write_back_header: drive index 0, empty_file, file num = 9, mpx_headers = 0, copy 1 08:24:52.630 [405582] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.8429 08:24:54.893 [655466] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 08:24:54.906 [655466] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:24:54.906 [655466] <2> bptm: EXITING with status 0 <---------- 08:24:55.245 [405582] <2> io_terminate_tape: absolute block position prior to writing empty header is 4586190, copy 1 08:24:55.245 [405582] <2> send_MDS_msg: MEDIADB 1 932011 0120L4 4000982 *NULL* 6 1389468610 1389555007 1391974207 0 1174059934 8 8 2 1 0 512 1024 0 4586190 0 08:24:55.284 [405582] <2> io_open: SCSI RESERVE 08:24:55.284 [405582] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 0) 08:24:55.284 [405582] <2> io_ioctl: command (12)MTBSF 2 from (bptm.c.8586) on drive index 0 08:24:55.291 [405582] <2> io_ioctl: command (11)MTFSF 1 from (bptm.c.8588) on drive index 0 08:24:55.296 [405582] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.8594 08:24:55.303 [405582] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from io_terminate_tape) 08:25:00.310 [405582] <2> send_brm_msg: EXIT AIXBK_1389555007 150 08:25:00.318 [405582] <2> bct_clear_active: removing group 0 shmid 35651595 08:25:00.343 [405582] <2> bct_clear_active: Set BCTable entry 0 to inactive, ACTIVE_GC count decremented to 0 08:25:00.344 [405582] <2> write_backup_completion_stats: waited for full buffer 2312 times, delayed 349880 times 08:25:00.365 [405582] <2> bptm: waiting for TERMINATE from bpbrm/IRM 08:25:02.365 [405582] <2> read_brm_msg: TERMINATE 08:25:02.371 [405582] <2> updateEMM_freespace: updateEMM_freespace() (1 0) 08:25:02.371 [405582] <2> main: TWIN_INDEX = 0, STU_FLAGS = 0 08:25:02.466 [405582] <2> bptm: EXITING with status 0 <---------- 08:25:02.466 [405582] <2> cleanup: Detached from BPBRM shared memory 08:25:17.458 [405588] <2> bptm: INITIATING (VERBOSE = 5): -unload -dn IBM.ULT3580-TD4.003 -dp /dev/rmt0.1 -dk 2000371 -m 0120L4 -mk 4000982 -mds 8 -alocid 932011 -jobid -1389007840 -jm 08:25:17.470 [405588] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:25:17.475 [405588] <2> bptm: PORT_STATUS = 0x00000000 08:25:17.482 [405588] <2> hosts_equal: The second name is empty 08:25:17.495 [405588] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:25:17.495 [405588] <2> hosts_equal: Comparing hosts and 08:25:17.495 [405588] <2> hosts_equal: names are the same 08:25:17.495 [405588] <4> bptm: emmserver_name = hqmb1 08:25:17.495 [405588] <4> bptm: emmserver_port = 1556 08:25:17.509 [405588] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:25:17.633 [405588] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name 08:25:17.633 [405588] <2> VssInit: vss_auth.cpp.720: Function: VssInit. Using Cached entries FALSE 08:25:17.635 [405588] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name AIXBK 08:25:17.683 [405588] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:25:17.714 [405588] <2> send_brm_msg: PID of bpxm = 405588 08:25:17.717 [405588] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD 08:25:17.741 [405588] <2> RequestMultipleResources: starting 08:25:17.741 [405588] <2> RequestMultipleResources: started 08:25:17.752 [405588] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name 08:25:17.752 [405588] <2> VssInit: vss_auth.cpp.720: Function: VssInit. Using Cached entries FALSE 08:25:17.752 [405588] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name AIXBK 08:25:18.171 [405588] <2> packageMultiResourceRequest: started 08:25:18.180 [405588] <2> packageMultiResourceRequest: retVal = 0 08:25:18.180 [405588] <2> RequestMultipleResources: setting up callback and calling requestResources 08:25:18.182 [405588] <2> logResourceReq: req.versionId : 1 08:25:18.182 [405588] <2> logResourceReq: req.jobId : -1389007840 08:25:18.182 [405588] <2> logResourceReq: req.startedViaJobManager : true 08:25:18.182 [405588] <2> logResourceReq: req.consumer : true 08:25:18.186 [405588] <2> logResourceReq: MediaSelect - 08:25:18.186 [405588] <2> logResourceReq: reqNum : 0 08:25:18.186 [405588] <2> logResourceReq: oldMediaId : 0120L4 08:25:18.186 [405588] <2> logResourceReq: previousFailed : false 08:25:18.186 [405588] <2> logMediaRequest: mreq.mediaId : 0120L4 08:25:18.186 [405588] <2> logMediaRequest: mreq.mediaKey : 0 08:25:18.186 [405588] <2> logMediaRequest: mreq.mediaServer : AIXBK 08:25:18.186 [405588] <2> logMediaRequest: mreq.userReservationId : 08:25:18.186 [405588] <2> logMediaRequest: mreq.assignedTime : 0 08:25:18.186 [405588] <2> logMediaRequest: mreq.client : 08:25:18.186 [405588] <2> logMediaRequest: mreq.usageType : 6 08:25:18.186 [405588] <2> logMediaRequest: mreq.mustBeNdmp : false 08:25:18.186 [405588] <2> logMediaRequest: mreq.driveName : IBM.ULT3580-TD4.003 08:25:18.186 [405588] <2> logMediaRequest: mreq.drivePath : 08:25:18.187 [405588] <2> logMediaRequest: mreq.mediaPool : 08:25:18.187 [405588] <2> logMediaRequest: mreq.robotNumber : -1 08:25:18.187 [405588] <2> logMediaRequest: mreq.slotNumber : -1 08:25:18.187 [405588] <2> logMediaRequest: mreq.density : -1 08:25:18.187 [405588] <2> logMediaRequest: mreq.ndmpControlHost : 08:25:18.187 [405588] <2> logMediaRequest: mreq.failIfNoMedia : true 08:25:18.187 [405588] <2> logMediaRequest: mreq.externalFile : 08:25:18.194 [405588] <2> RequestMultipleResources: BpxmiV->requestResources returns 0 08:25:18.238 [405588] <2> resourcesAvailable: m_allocationSeq.length() == 1 08:25:18.239 [405588] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 4 08:25:18.239 [405588] <2> resourcesAvailable: MEDIADB 1 932011 0120L4 4000982 ------ 6 1389468610 1389553208 1391972408 0 259121054 3 3 2 1 0 512 1024 0 1012200 0 08:25:18.239 [405588] <2> resourcesAvailable: VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0 08:25:18.239 [405588] <2> resourcesAvailable: DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0 08:25:18.239 [405588] <2> resourcesAvailable: STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576 08:25:20.201 [405588] <2> packageMultiResourceRequestResult: totalNumberOfAllocations == 1 08:25:20.201 [405588] <2> packageMultiResourceRequestResult: found MediaAllocation : reqNum == 0 08:25:20.201 [405588] <2> packageMultiResourceRequestResult: matched MediaAllocation to a mediaSelect 08:25:20.201 [405588] <2> packageMultiResourceRequestResult: retVal = 0 08:25:20.201 [405588] <2> RequestMultipleResources: retVal = 0 emmStatus = 0 08:25:20.201 [405588] <2> RequestMultipleResources: returning 08:25:20.209 [405588] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 932011 0120L4 4000982 ------ 6 1389468610 1389553208 1391972408 0 259121054 3 3 2 1 0 512 1024 0 1012200 0], length 116 08:25:20.209 [405588] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0], length 108 08:25:20.209 [405588] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0], length 110 08:25:20.209 [405588] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576], length 43 08:25:20.209 [405588] <2> populateBptmOpaqueStrings: retVal = 0 08:25:20.209 [405588] <2> parse_resource_strings: MEDIADB 1 932011 0120L4 4000982 ------ 6 1389468610 1389553208 1391972408 0 259121054 3 3 2 1 0 512 1024 0 1012200 0 08:25:20.209 [405588] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters 08:25:20.209 [405588] <2> parse_resource_strings: VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0 08:25:20.209 [405588] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters 08:25:20.209 [405588] <2> parse_resource_strings: DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0 08:25:20.209 [405588] <2> parse_resource_strings: Parsed message type 17, version 2, 19 parameters 08:25:20.209 [405588] <2> parse_resource_strings: STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576 08:25:20.209 [405588] <2> parse_resource_strings: Parsed message type 18, version 0, 4 parameters 08:25:20.209 [405588] <2> nbjm_media_request: Job control returned to BPTM 08:25:20.212 [405588] <2> drivename_open: Called with Create 1, file IBM.ULT3580-TD4.003 08:25:20.212 [405588] <2> drivename_lock: lock established 08:25:20.240 [405588] <4> create_tpreq_file: symlink to path /dev/rmt0.1 08:25:20.243 [405588] <2> drivename_write: Called with mode 2 08:25:20.262 [405588] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release) 08:25:20.267 [405588] <2> really_tpunmount: tpunmount'ing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 08:27:38.198 [405588] <4> create_tpreq_file: symlink to path /dev/rmt0.1 08:27:38.221 [405588] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release) 08:27:38.227 [405588] <2> tapealert_and_release: SCSI RELEASE 08:27:38.233 [405588] <2> drivename_unlock: unlocked 08:27:38.233 [405588] <2> drivename_close: Called 08:27:38.233 [405588] <2> drivename_remove: Called 08:27:38.239 [405588] <2> main: Sending [EXIT STATUS 0] to NBJM 08:27:38.239 [405588] <2> bptm: EXITING with status 0 <---------- 08:27:52.917 [655576] <2> bptm: INITIATING (VERBOSE = 5): -pid 602116 -den 6 -rt 8 -rn 0 -cj 8 -mpx 32 -reqid -1389007841 -jm -brm -p NetBackup -stunit aixbk-hcart-robot-tld-0 -maxfrag 1048576 -v -masterversion 600000 -mediasvr aixbk -bpbrm_shm_id 45088778 -blks_per_buffer 512 08:27:52.930 [655576] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:27:52.930 [655576] <2> main: bptm.c.1622: maximum fragment size is 1048576000 Kbytes 08:27:52.930 [655576] <2> bptm: PORT_STATUS = 0x00000000 08:27:52.937 [655576] <2> hosts_equal: The second name is empty 08:27:52.949 [655576] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:27:52.949 [655576] <2> hosts_equal: Comparing hosts and 08:27:52.949 [655576] <2> hosts_equal: names are the same 08:27:52.949 [655576] <4> bptm: emmserver_name = hqmb1 08:27:52.949 [655576] <4> bptm: emmserver_port = 1556 08:27:52.963 [655576] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:27:53.015 [655576] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name 08:27:53.015 [655576] <2> VssInit: vss_auth.cpp.720: Function: VssInit. Using Cached entries FALSE 08:27:53.016 [655576] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name AIXBK 08:27:53.057 [655576] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:27:53.075 [655576] <2> hosts_equal: Comparing hosts and 08:27:53.075 [655576] <2> hosts_equal: names are the same 08:27:53.075 [655576] <4> db_getSTUNIT: EMM interface already initialized (using cached master name hqmb1). 08:27:53.088 [655576] <2> setup_twin_parameters: bptm.c.3860: maximum fragment size is 1048576000 Kbytes 08:27:53.088 [655576] <2> send_brm_msg: PID of bpxm = 655576 08:27:53.090 [655576] <2> process_mpx_protocol: wait for initial START BACKUP message from bpbrm 08:27:59.292 [655576] <2> read_brm_msg: START BACKUP -b AIXBK_1389555007 -bt 1389555007 -c AIXBK -cl AIXBK_FS_SAP_FLASH -st 0 -rl 2 -rp 2419200 -sl Daily -ct 0 -hostname AIXBK -rclnt AIXBK -rclnthostname AIXBK -bclnt AIXBK -bclnthostname AIXBK -ru root -shm -no_callback -connect_options 0x01020100 -jobid 808082 -jobgrpid 808082 08:27:59.301 [655576] <2> validate_parameters: tmcommon.c.4449: maximum fragment size is 1048576000 Kbytes 08:27:59.301 [655576] <2> io_init: bpbrm_shm_id = 45088778, buffer address = 0x30000000 08:27:59.301 [655576] <2> io_init: found index: 0 08:27:59.302 [655576] <2> io_init: using 262144 data buffer size 08:27:59.302 [655576] <2> io_init: CINDEX 0, sched Kbytes for monitoring = 60000 08:27:59.307 [655576] <2> io_init: using 64 data buffers 08:27:59.310 [655576] <2> io_init: child delay = 20, parent delay = 30 (milliseconds) 08:27:59.324 [655576] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 08:27:59.371 [655576] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 08:27:59.371 [655576] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 08:27:59.547 [655576] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 08:27:59.547 [655576] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35786 TO 10.2.21.10.13724 fd = 13 08:27:59.547 [655576] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.35786 TO 10.2.21.10.13724 08:27:59.554 [655576] <2> vauth_get_user_name: vauth_comm.c.726: cached_user_name: root 08:27:59.555 [655576] <2> vauth_get_user_name: vauth_comm.c.728: cached_user_name: :root 08:27:59.555 [655576] <2> vauth_get_user_name: vauth_comm.c.734: user_name: :root 08:27:59.555 [655576] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 08:27:59.555 [655576] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 08:27:59.555 [655576] <2> check_authentication: no authentication required 08:27:59.555 [655576] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 08:27:59.555 [655576] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 08:28:00.024 [655576] <2> read_image_and_init: resuming backup-id AIXBK_1389555007 copy 1 at fragment 5, 512 blocks: 1707668998 08:28:00.024 [655576] <2> mpx_setup_shm: buffer control shared memory address is 0x40000000, size is 49280, shmid is 70254601 08:28:00.025 [655576] <2> mpx_setup_shm: buf control for CINDEX 0 is 0x40000000 08:28:00.025 [655576] <2> mpx_setup_shm: shared memory address for group 0 is 0x50000000, size is 67108864, shmid is 15728653 08:28:00.025 [655576] <2> mpx_setup_shm: shared memory address for CINDEX 0 is 0x50000000, group 0, num_active 1 08:28:00.042 [655576] <2> setup_bpbkar_info: /usr/openv/netbackup/db/config/shm/AIXBK_1389555007 file successfully created 08:28:00.042 [655576] <2> get_data_socket: tmmpx.c.3453: port_status: 16908544 16908544 0x01020100 08:28:00.042 [655576] <2> get_data_socket: tmmpx.c.3454: shm_method: 1 1 0x00000001 08:28:00.042 [655576] <2> get_data_socket: tmmpx.c.3457: client_hostname: AIXBK 08:28:00.042 [655576] <2> nb_bind_on_port_addr: bound to port 4442 08:28:00.042 [655576] <2> get_data_socket: tmmpx.c.3522: *port: 4442 4442 0x0000115a 08:28:00.042 [655576] <2> get_data_socket: tmmpx.c.3523: mpx_ipc: 08:28:00.042 [655576] <2> mpx_start_child: tmmpx.c.1150: Calling: send_brm_msg(BRM_PORT) 08:28:00.042 [655576] <2> send_brm_msg: DATASOCKET AIXBK_1389555007 4442 08:28:00.042 [655576] <2> mpx_start_child: tmmpx.c.1155: Calling: bpcr_get_socket_rqst2 08:28:00.042 [655576] <2> mpx_start_child: tmmpx.c.1232: Calling: bpcr_get_socket_rqst4 08:28:01.234 [655576] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 08:28:01.277 [655576] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 08:28:01.277 [655576] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 08:28:01.466 [655576] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 08:28:01.466 [655576] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35791 TO 10.2.21.10.13724 fd = 13 08:28:01.466 [655576] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.35791 TO 10.2.21.10.13724 08:28:01.466 [655576] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 08:28:01.466 [655576] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 08:28:01.466 [655576] <2> check_authentication: no authentication required 08:28:01.466 [655576] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 08:28:01.467 [655576] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 08:28:02.035 [655576] <2> nbjm_media_request: Passing job control to NBJM, type WRITE 08:28:02.037 [655576] <2> RequestMultipleResources: starting 08:28:02.037 [655576] <2> RequestMultipleResources: started 08:28:02.047 [655576] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name 08:28:02.047 [655576] <2> VssInit: vss_auth.cpp.720: Function: VssInit. Using Cached entries FALSE 08:28:02.047 [655576] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name AIXBK 08:28:02.128 [655576] <2> packageMultiResourceRequest: started 08:28:02.128 [655576] <2> packageMultiResourceRequest: retVal = 0 08:28:02.128 [655576] <2> RequestMultipleResources: setting up callback and calling requestResources 08:28:02.129 [655576] <2> logResourceReq: req.versionId : 1 08:28:02.129 [655576] <2> logResourceReq: req.jobId : -1389007841 08:28:02.129 [655576] <2> logResourceReq: req.startedViaJobManager : true 08:28:02.129 [655576] <2> logResourceReq: req.consumer : true 08:28:02.129 [655576] <2> logResourceReq: STUSelect - 08:28:02.129 [655576] <2> logResourceReq: reqNum : 0 08:28:02.129 [655576] <2> logResourceReq: mediaServer : AIXBK 08:28:02.129 [655576] <2> logResourceReq: oldMediaId : 08:28:02.129 [655576] <2> logResourceReq: previousFailed : false 08:28:02.129 [655576] <2> logResourceReq: storageUnit : aixbk-hcart-robot-tld-0 08:28:02.129 [655576] <2> logResourceReq: mustBeNdmp : false 08:28:02.129 [655576] <2> logResourceReq: getMaxFreeSpace : false 08:28:02.129 [655576] <2> logResourceReq: mediaPool : NetBackup 08:28:02.129 [655576] <2> logResourceReq: retentionLevel : 2 08:28:02.129 [655576] <2> logResourceReq: mustUseLocalMediaServer : false 08:28:02.129 [655576] <2> logResourceReq: failOnError : false 08:28:02.129 [655576] <2> logResourceReq: mpxRequired : false 08:28:02.129 [655576] <2> logResourceReq: client : AIXBK 08:28:02.129 [655576] <2> logResourceReq: usageType : 1 08:28:02.136 [655576] <2> RequestMultipleResources: BpxmiV->requestResources returns 0 08:28:02.150 [655576] <2> resourcesAvailable: m_allocationSeq.length() == 1 08:28:02.150 [655576] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 4 08:28:02.150 [655576] <2> resourcesAvailable: MEDIADB 1 932029 0120L4 4000982 ------ 6 1389468610 1389555007 1391974207 0 1174059934 8 8 2 1 0 512 1024 0 4586190 0 08:28:02.150 [655576] <2> resourcesAvailable: VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0 08:28:02.150 [655576] <2> resourcesAvailable: DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0 08:28:02.150 [655576] <2> resourcesAvailable: STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576 08:28:04.155 [655576] <2> packageMultiResourceRequestResult: totalNumberOfAllocations == 1 08:28:04.155 [655576] <2> packageMultiResourceRequestResult: found MediaAllocation : reqNum == 0 08:28:04.155 [655576] <2> packageMultiResourceRequestResult: matched MediaAllocation to an stuReq 08:28:04.155 [655576] <2> packageMultiResourceRequestResult: retVal = 0 08:28:04.155 [655576] <2> RequestMultipleResources: retVal = 0 emmStatus = 0 08:28:04.155 [655576] <2> RequestMultipleResources: returning 08:28:04.155 [655576] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 932029 0120L4 4000982 ------ 6 1389468610 1389555007 1391974207 0 1174059934 8 8 2 1 0 512 1024 0 4586190 0], length 117 08:28:04.155 [655576] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0], length 108 08:28:04.155 [655576] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0], length 110 08:28:04.155 [655576] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576], length 43 08:28:04.155 [655576] <2> populateBptmOpaqueStrings: retVal = 0 08:28:04.155 [655576] <2> parse_resource_strings: MEDIADB 1 932029 0120L4 4000982 ------ 6 1389468610 1389555007 1391974207 0 1174059934 8 8 2 1 0 512 1024 0 4586190 0 08:28:04.155 [655576] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters 08:28:04.155 [655576] <2> parse_resource_strings: VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0 08:28:04.155 [655576] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters 08:28:04.155 [655576] <2> parse_resource_strings: DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0 08:28:04.155 [655576] <2> parse_resource_strings: Parsed message type 17, version 2, 19 parameters 08:28:04.155 [655576] <2> parse_resource_strings: STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576 08:28:04.155 [655576] <2> parse_resource_strings: Parsed message type 18, version 0, 4 parameters 08:28:04.155 [655576] <2> nbjm_media_request: Job control returned to BPTM 08:28:04.155 [655576] <2> drivename_open: Called with Create 1, file IBM.ULT3580-TD4.003 08:28:04.166 [655576] <2> drivename_lock: lock established 08:28:04.166 [655576] <2> drivename_write: Called with mode 0 08:28:04.170 [655576] <2> bptm media_id_to_monitor: job_id = 808082 08:28:04.177 [655576] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 08:28:04.213 [655576] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 08:28:04.213 [655576] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpjobd 08:28:04.400 [655576] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 08:28:04.400 [655576] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35798 TO 10.2.21.10.13724 fd = 20 08:28:04.400 [655576] <2> logconnections: BPJOBD CONNECT FROM 10.2.21.39.35798 TO 10.2.21.10.13724 08:28:04.400 [655576] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 08:28:04.400 [655576] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 08:28:04.400 [655576] <2> job_authenticate_connection: no authentication required 08:28:04.400 [655576] <2> job_authenticate_connection: ignoring VxSS authentication check for now... 08:28:04.405 [655576] <2> job_connect: Connected to the host hqmb1 contype 10 jobid <808082> socket <20> 08:28:04.405 [655576] <2> job_connect: Connected on port 35798 08:28:04.405 [655576] <2> bptm media_id_to_monitor: pDstMediaId = 0120L4 08:28:04.405 [655576] <2> set_job_details: Sending jobData jobid (808082) 08:28:04.405 [655576] <2> send_structure_data: Index 28 Field m_szDstMediaID Value <0120L4> 08:28:04.405 [655576] <2> set_job_details: Done 08:28:04.405 [655576] <2> mount_open_media: Waiting for mount of media id 0120L4 (copy 1) on server aixbk. 08:28:04.406 [655576] <4> create_tpreq_file: symlink to path /dev/rmt0.1 08:28:04.415 [655576] <2> manage_scsi_reserve: SCSI RESERVE 08:28:04.418 [655576] <4> expandpath: /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 08:28:05.327 [655576] <2> process_brm_msg: no pending message from bpbrm 08:29:01.490 [655576] <2> io_open: report_attr, fl1 0x00000849, fl2 0x00000000 08:29:01.511 [655576] <2> io_open: SCSI RESERVE 08:29:01.513 [655576] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 08:29:01.531 [655576] <2> write_backup: media id 0120L4 mounted on drive index 0, drivepath /dev/rmt0.1, drivename IBM.ULT3580-TD4.003, copy 1 08:29:01.531 [655576] <2> io_read_media_header: drive index 0, reading media header, buflen = 65536, buff = 0x2062b018, copy 1 08:29:01.531 [655576] <2> io_ioctl: command (6)MTREW 1 from (bptm.c.7774) on drive index 0 08:29:01.543 [655576] <2> io_ioctl: command (11)MTFSF 1 from (bptm.c.8031) on drive index 0 08:29:01.567 [655576] <2> io_position_for_write: position media id 0120L4, copy 1, current number images = 8 08:29:01.567 [655576] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.6648 08:29:01.568 [655576] <2> io_position_for_write: locating to absolute block number 4586190, copy 1 08:29:27.543 [422142] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007844 -jm 08:29:27.556 [422142] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:29:27.556 [422142] <2> bptm: PORT_STATUS = 0x00000000 08:29:27.556 [422142] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 08:29:27.556 [422142] <2> drivename_checklock: Called 08:29:27.556 [422142] <2> drivename_checklock: PID 655576 has lock 08:29:27.556 [422142] <2> report_drives: MODE = 0 08:29:27.556 [422142] <2> report_drives: TIME = 1389572884 08:29:27.556 [422142] <2> report_drives: MASTER = hqmb1 08:29:27.556 [422142] <2> report_drives: PATH = /dev/rmt0.1 08:29:27.556 [422142] <2> report_drives: MEDIA = 0120L4 08:29:27.556 [422142] <2> report_drives: REQID = -1389007841 08:29:27.556 [422142] <2> report_drives: ALOCID = 932029 08:29:27.556 [422142] <2> report_drives: RBID = {D58D18CC-9C93-4D4E-8526-8E0CBA7B5D91 08:29:27.556 [422142] <2> report_drives: PID = 655576 08:29:27.556 [422142] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 08:29:27.556 [422142] <2> main: Sending [EXIT STATUS 0] to NBJM 08:29:27.556 [422142] <2> bptm: EXITING with status 0 <---------- 08:30:47.574 [655576] <2> io_position_for_write: locate block is done 08:30:47.593 [655576] <2> io_open: SCSI RESERVE 08:30:47.595 [655576] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 08:30:48.893 [655576] <2> io_position_for_write: processing empty header, filenum = 9, bid = (empty_file), copy 1 08:30:48.893 [655576] <2> io_position_for_write: empty header found on 0120L4, OK, copy 1 08:30:48.893 [655576] <2> io_ioctl: command (12)MTBSF 1 from (bptm.c.20524) on drive index 0 08:30:48.905 [655576] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.20558) on drive index 0 08:30:53.640 [655576] <2> send_MDS_msg: MEDIADB 1 932029 0120L4 4000982 *NULL* 6 1389468610 1389555007 1391974207 0 1174059934 8 8 2 1 0 512 1024 0 4586190 0 08:30:53.684 [655576] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 08:30:53.988 [655576] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 08:30:53.988 [655576] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 08:30:54.252 [655576] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 08:30:54.252 [655576] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35810 TO 10.2.21.10.13724 fd = 23 08:30:54.252 [655576] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.35810 TO 10.2.21.10.13724 08:30:54.252 [655576] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 08:30:54.252 [655576] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 08:30:54.252 [655576] <2> check_authentication: no authentication required 08:30:54.252 [655576] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 08:30:54.252 [655576] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 08:30:54.664 [655576] <4> write_backup: begin writing backup id AIXBK_1389555007, copy 1, fragment 5, to media id 0120L4 on drive index 0 08:30:54.664 [655576] <2> process_brm_msg: no pending message from bpbrm 08:30:54.664 [655576] <2> write_backup: waiting 5 seconds for start of another backup 08:30:59.664 [655576] <2> send_brm_msg: MEDIA READY 08:30:59.675 [655576] <2> write_data: ndmp_dup_max_frag is set to 1073741824000 08:30:59.675 [655576] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: 0 twin_is_disk 0 delay_brm: 0 08:30:59.675 [655576] <2> io_ioctl: command (12)MTBSF 1 from (bptm.c.21169) on drive index 0 08:31:01.523 [655576] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.21176 08:31:01.526 [655576] <2> write_data: absolute block position prior to writing backup header(s) is 4586190, copy 1 08:31:01.543 [655576] <2> io_open: SCSI RESERVE 08:31:01.545 [655576] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 08:31:01.545 [655576] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.21229) on drive index 0 08:31:04.089 [655576] <2> io_write_back_header: drive index 0, AIXBK_1389555007, file num = 9, mpx_headers = 1, copy 1 08:31:04.115 [655576] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1 08:31:04.115 [655576] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0 08:31:04.115 [655576] <2> write_data: received first buffer (262144 bytes), begin writing data 08:35:11.091 [446518] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 08:35:11.181 [446518] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:35:11.260 [446518] <2> bptm: EXITING with status 0 <---------- 08:39:29.853 [536824] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007849 -jm 08:39:29.885 [536824] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:39:29.893 [536824] <2> bptm: PORT_STATUS = 0x00000000 08:39:29.943 [536824] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 08:39:29.948 [536824] <2> drivename_checklock: Called 08:39:29.948 [536824] <2> drivename_checklock: PID 655576 has lock 08:39:29.960 [536824] <2> report_drives: MODE = 0 08:39:29.960 [536824] <2> report_drives: TIME = 1389572884 08:39:29.960 [536824] <2> report_drives: MASTER = hqmb1 08:39:29.960 [536824] <2> report_drives: PATH = /dev/rmt0.1 08:39:29.960 [536824] <2> report_drives: MEDIA = 0120L4 08:39:29.960 [536824] <2> report_drives: REQID = -1389007841 08:39:29.960 [536824] <2> report_drives: ALOCID = 932029 08:39:29.960 [536824] <2> report_drives: RBID = {D58D18CC-9C93-4D4E-8526-8E0CBA7B5D91 08:39:29.960 [536824] <2> report_drives: PID = 655576 08:39:29.960 [536824] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 08:39:29.979 [536824] <2> main: Sending [EXIT STATUS 0] to NBJM 08:39:29.979 [536824] <2> bptm: EXITING with status 0 <---------- 08:45:26.291 [307370] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 08:45:26.310 [307370] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:45:26.310 [307370] <2> bptm: EXITING with status 0 <---------- 08:49:27.971 [319668] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007852 -jm 08:49:27.984 [319668] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:49:27.984 [319668] <2> bptm: PORT_STATUS = 0x00000000 08:49:28.001 [319668] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 08:49:28.001 [319668] <2> drivename_checklock: Called 08:49:28.001 [319668] <2> drivename_checklock: PID 655576 has lock 08:49:28.005 [319668] <2> report_drives: MODE = 0 08:49:28.005 [319668] <2> report_drives: TIME = 1389572884 08:49:28.005 [319668] <2> report_drives: MASTER = hqmb1 08:49:28.005 [319668] <2> report_drives: PATH = /dev/rmt0.1 08:49:28.005 [319668] <2> report_drives: MEDIA = 0120L4 08:49:28.005 [319668] <2> report_drives: REQID = -1389007841 08:49:28.005 [319668] <2> report_drives: ALOCID = 932029 08:49:28.005 [319668] <2> report_drives: RBID = {D58D18CC-9C93-4D4E-8526-8E0CBA7B5D91 08:49:28.005 [319668] <2> report_drives: PID = 655576 08:49:28.005 [319668] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 08:49:28.005 [319668] <2> main: Sending [EXIT STATUS 0] to NBJM 08:49:28.005 [319668] <2> bptm: EXITING with status 0 <---------- 08:50:54.766 [655576] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -7 08:50:54.780 [655576] <2> write_backup: tp.tv_sec = 1389574254, stp.tv_sec = 1389573064, tp.tv_usec = 730655, stp.tv_usec = 115500, et = 1190615, mpx_total_kbytes[TWIN_INDEX = 0] = 59433472 08:50:54.811 [655576] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.18563) on drive index 0 08:50:56.765 [655576] <2> write_backup_update_frags: ************** Fragment 5: ******************* 08:50:56.771 [655576] <2> write_backup_update_frags: ++++ total image kbytes so far = 59433472 ++++ ` 08:50:56.778 [655576] <2> write_backup_update_frags: ++++ fragment_num = 5 ++++ 08:50:56.778 [655576] <2> write_backup_update_frags: copy_num = 1 08:50:56.778 [655576] <2> write_backup_update_frags: Kbytes = 59433472 08:50:56.778 [655576] <2> write_backup_update_frags: remainder = 0 08:50:56.778 [655576] <2> write_backup_update_frags: id = 0120L4 08:50:56.778 [655576] <2> write_backup_update_frags: file_num = 9 08:50:56.778 [655576] <2> write_backup_update_frags: block_size = 262144 08:50:56.778 [655576] <2> write_backup_update_frags: offset = 4586190 08:50:56.781 [655576] <2> write_backup_update_frags: ****************************************************** 08:50:56.855 [655576] <2> send_MDS_msg: MEDIADB 1 932029 0120L4 4000982 *NULL* 6 1389468610 1389555007 1391974207 0 1233493406 9 9 2 1 0 512 1024 0 4586190 0 08:50:57.171 [655576] <2> read_brm_msg: STOP BACKUP AIXBK_1389555007 08:50:57.177 [655576] <2> io_terminate_tape: writing empty backup header, drive index 0, copy 1 08:50:57.177 [655576] <2> io_terminate_tape: reposition to previous tapemark and rewrite header 08:50:57.177 [655576] <2> io_ioctl: command (12)MTBSF 1 from (bptm.c.8267) on drive index 0 08:50:59.275 [655576] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.8311) on drive index 0 08:51:01.845 [655576] <2> io_write_back_header: drive index 0, empty_file, file num = 10, mpx_headers = 0, copy 1 08:51:01.856 [655576] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.8429 08:51:04.528 [655576] <2> io_terminate_tape: absolute block position prior to writing empty header is 4818354, copy 1 08:51:04.528 [655576] <2> send_MDS_msg: MEDIADB 1 932029 0120L4 4000982 *NULL* 6 1389468610 1389555007 1391974207 0 1233493406 9 9 2 1 0 512 1024 0 4818354 0 08:51:04.565 [655576] <2> io_open: SCSI RESERVE 08:51:04.565 [655576] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 0) 08:51:04.566 [655576] <2> io_ioctl: command (12)MTBSF 2 from (bptm.c.8586) on drive index 0 08:51:04.572 [655576] <2> io_ioctl: command (11)MTFSF 1 from (bptm.c.8588) on drive index 0 08:51:04.577 [655576] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.8594 08:51:04.579 [655576] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from io_terminate_tape) 08:51:09.588 [655576] <2> send_brm_msg: EXIT AIXBK_1389555007 150 08:51:09.594 [655576] <2> bct_clear_active: removing group 0 shmid 15728653 08:51:09.623 [655576] <2> bct_clear_active: Set BCTable entry 0 to inactive, ACTIVE_GC count decremented to 0 08:51:09.623 [655576] <2> write_backup_completion_stats: waited for full buffer 908 times, delayed 23008 times 08:51:09.641 [655576] <2> bptm: waiting for TERMINATE from bpbrm/IRM 08:51:13.642 [655576] <2> read_brm_msg: TERMINATE 08:51:13.650 [655576] <2> updateEMM_freespace: updateEMM_freespace() (1 0) 08:51:13.650 [655576] <2> main: TWIN_INDEX = 0, STU_FLAGS = 0 08:51:13.758 [655576] <2> bptm: EXITING with status 0 <---------- 08:51:13.758 [655576] <2> cleanup: Detached from BPBRM shared memory 08:51:27.638 [655584] <2> bptm: INITIATING (VERBOSE = 5): -unload -dn IBM.ULT3580-TD4.003 -dp /dev/rmt0.1 -dk 2000371 -m 0120L4 -mk 4000982 -mds 8 -alocid 932029 -jobid -1389007853 -jm 08:51:27.650 [655584] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:51:27.659 [655584] <2> bptm: PORT_STATUS = 0x00000000 08:51:27.666 [655584] <2> hosts_equal: The second name is empty 08:51:27.678 [655584] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:51:27.678 [655584] <2> hosts_equal: Comparing hosts and 08:51:27.678 [655584] <2> hosts_equal: names are the same 08:51:27.678 [655584] <4> bptm: emmserver_name = hqmb1 08:51:27.678 [655584] <4> bptm: emmserver_port = 1556 08:51:27.693 [655584] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:51:27.818 [655584] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name 08:51:27.818 [655584] <2> VssInit: vss_auth.cpp.720: Function: VssInit. Using Cached entries FALSE 08:51:27.819 [655584] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name AIXBK 08:51:27.858 [655584] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:51:27.877 [655584] <2> send_brm_msg: PID of bpxm = 655584 08:51:27.880 [655584] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD 08:51:27.904 [655584] <2> RequestMultipleResources: starting 08:51:27.904 [655584] <2> RequestMultipleResources: started 08:51:27.915 [655584] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name 08:51:27.915 [655584] <2> VssInit: vss_auth.cpp.720: Function: VssInit. Using Cached entries FALSE 08:51:27.915 [655584] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name AIXBK 08:51:28.110 [655584] <2> packageMultiResourceRequest: started 08:51:28.119 [655584] <2> packageMultiResourceRequest: retVal = 0 08:51:28.119 [655584] <2> RequestMultipleResources: setting up callback and calling requestResources 08:51:28.121 [655584] <2> logResourceReq: req.versionId : 1 08:51:28.121 [655584] <2> logResourceReq: req.jobId : -1389007853 08:51:28.121 [655584] <2> logResourceReq: req.startedViaJobManager : true 08:51:28.121 [655584] <2> logResourceReq: req.consumer : true 08:51:28.125 [655584] <2> logResourceReq: MediaSelect - 08:51:28.125 [655584] <2> logResourceReq: reqNum : 0 08:51:28.125 [655584] <2> logResourceReq: oldMediaId : 0120L4 08:51:28.125 [655584] <2> logResourceReq: previousFailed : false 08:51:28.125 [655584] <2> logMediaRequest: mreq.mediaId : 0120L4 08:51:28.125 [655584] <2> logMediaRequest: mreq.mediaKey : 0 08:51:28.125 [655584] <2> logMediaRequest: mreq.mediaServer : AIXBK 08:51:28.126 [655584] <2> logMediaRequest: mreq.userReservationId : 08:51:28.126 [655584] <2> logMediaRequest: mreq.assignedTime : 0 08:51:28.126 [655584] <2> logMediaRequest: mreq.client : 08:51:28.126 [655584] <2> logMediaRequest: mreq.usageType : 6 08:51:28.126 [655584] <2> logMediaRequest: mreq.mustBeNdmp : false 08:51:28.126 [655584] <2> logMediaRequest: mreq.driveName : IBM.ULT3580-TD4.003 08:51:28.126 [655584] <2> logMediaRequest: mreq.drivePath : 08:51:28.126 [655584] <2> logMediaRequest: mreq.mediaPool : 08:51:28.126 [655584] <2> logMediaRequest: mreq.robotNumber : -1 08:51:28.126 [655584] <2> logMediaRequest: mreq.slotNumber : -1 08:51:28.126 [655584] <2> logMediaRequest: mreq.density : -1 08:51:28.126 [655584] <2> logMediaRequest: mreq.ndmpControlHost : 08:51:28.126 [655584] <2> logMediaRequest: mreq.failIfNoMedia : true 08:51:28.126 [655584] <2> logMediaRequest: mreq.externalFile : 08:51:28.131 [655584] <2> RequestMultipleResources: BpxmiV->requestResources returns 0 08:51:28.169 [655584] <2> resourcesAvailable: m_allocationSeq.length() == 1 08:51:28.170 [655584] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 4 08:51:28.170 [655584] <2> resourcesAvailable: MEDIADB 1 932029 0120L4 4000982 ------ 6 1389468610 1389555007 1391974207 0 1174059934 8 8 2 1 0 512 1024 0 4586190 0 08:51:28.170 [655584] <2> resourcesAvailable: VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0 08:51:28.170 [655584] <2> resourcesAvailable: DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0 08:51:28.170 [655584] <2> resourcesAvailable: STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576 08:51:30.138 [655584] <2> packageMultiResourceRequestResult: totalNumberOfAllocations == 1 08:51:30.138 [655584] <2> packageMultiResourceRequestResult: found MediaAllocation : reqNum == 0 08:51:30.138 [655584] <2> packageMultiResourceRequestResult: matched MediaAllocation to a mediaSelect 08:51:30.138 [655584] <2> packageMultiResourceRequestResult: retVal = 0 08:51:30.138 [655584] <2> RequestMultipleResources: retVal = 0 emmStatus = 0 08:51:30.138 [655584] <2> RequestMultipleResources: returning 08:51:30.148 [655584] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 932029 0120L4 4000982 ------ 6 1389468610 1389555007 1391974207 0 1174059934 8 8 2 1 0 512 1024 0 4586190 0], length 117 08:51:30.148 [655584] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0], length 108 08:51:30.148 [655584] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0], length 110 08:51:30.148 [655584] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576], length 43 08:51:30.148 [655584] <2> populateBptmOpaqueStrings: retVal = 0 08:51:30.152 [655584] <2> parse_resource_strings: MEDIADB 1 932029 0120L4 4000982 ------ 6 1389468610 1389555007 1391974207 0 1174059934 8 8 2 1 0 512 1024 0 4586190 0 08:51:30.152 [655584] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters 08:51:30.152 [655584] <2> parse_resource_strings: VOLUME 1 0120L4 4000982 S40120L4 NetBackup *NULL* *NULL* 6 8 0 26 0 {00000000-0000-0000-0000-000000000000} 0 08:51:30.152 [655584] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters 08:51:30.152 [655584] <2> parse_resource_strings: DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0 08:51:30.152 [655584] <2> parse_resource_strings: Parsed message type 17, version 2, 19 parameters 08:51:30.152 [655584] <2> parse_resource_strings: STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576 08:51:30.152 [655584] <2> parse_resource_strings: Parsed message type 18, version 0, 4 parameters 08:51:30.152 [655584] <2> nbjm_media_request: Job control returned to BPTM 08:51:30.156 [655584] <2> drivename_open: Called with Create 1, file IBM.ULT3580-TD4.003 08:51:30.156 [655584] <2> drivename_lock: lock established 08:51:30.175 [655584] <4> create_tpreq_file: symlink to path /dev/rmt0.1 08:51:30.180 [655584] <2> drivename_write: Called with mode 2 08:51:30.209 [655584] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release) 08:51:30.211 [655584] <2> really_tpunmount: tpunmount'ing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 08:52:59.795 [655584] <4> create_tpreq_file: symlink to path /dev/rmt0.1 08:52:59.819 [655584] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release) 08:52:59.823 [655584] <2> tapealert_and_release: SCSI RELEASE 08:52:59.831 [655584] <2> drivename_unlock: unlocked 08:52:59.831 [655584] <2> drivename_close: Called 08:52:59.831 [655584] <2> drivename_remove: Called 08:52:59.842 [655584] <2> main: Sending [EXIT STATUS 0] to NBJM 08:52:59.842 [655584] <2> bptm: EXITING with status 0 <---------- 08:55:36.519 [405642] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 08:55:36.532 [405642] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:55:36.532 [405642] <2> bptm: EXITING with status 0 <---------- 08:57:26.944 [307446] <2> bptm: INITIATING (VERBOSE = 5): -pid 647292 -den 6 -rt 8 -rn 0 -cj 8 -mpx 32 -reqid -1389007857 -jm -brm -p NetBackup -stunit aixbk-hcart-robot-tld-0 -maxfrag 1048576 -v -masterversion 600000 -mediasvr aixbk -bpbrm_shm_id 46137354 -blks_per_buffer 512 08:57:26.956 [307446] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:57:26.956 [307446] <2> main: bptm.c.1622: maximum fragment size is 1048576000 Kbytes 08:57:26.956 [307446] <2> bptm: PORT_STATUS = 0x00000000 08:57:26.964 [307446] <2> hosts_equal: The second name is empty 08:57:26.976 [307446] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:57:26.976 [307446] <2> hosts_equal: Comparing hosts and 08:57:26.976 [307446] <2> hosts_equal: names are the same 08:57:26.976 [307446] <4> bptm: emmserver_name = hqmb1 08:57:26.976 [307446] <4> bptm: emmserver_port = 1556 08:57:26.995 [307446] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:57:27.055 [307446] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name 08:57:27.055 [307446] <2> VssInit: vss_auth.cpp.720: Function: VssInit. Using Cached entries FALSE 08:57:27.056 [307446] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name AIXBK 08:57:27.103 [307446] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:57:27.120 [307446] <2> hosts_equal: Comparing hosts and 08:57:27.120 [307446] <2> hosts_equal: names are the same 08:57:27.120 [307446] <4> db_getSTUNIT: EMM interface already initialized (using cached master name hqmb1). 08:57:27.134 [307446] <2> setup_twin_parameters: bptm.c.3860: maximum fragment size is 1048576000 Kbytes 08:57:27.134 [307446] <2> send_brm_msg: PID of bpxm = 307446 08:57:27.136 [307446] <2> process_mpx_protocol: wait for initial START BACKUP message from bpbrm 08:57:34.138 [307446] <2> read_brm_msg: START BACKUP -b AIXBK_1389574871 -bt 1389574871 -c AIXBK -cl AIXBK_ROAD_1 -st 0 -rl 10 -rp 86400 -sl Full -ct 0 -hostname AIXBK -rclnt AIXBK -rclnthostname AIXBK -bclnt AIXBK -bclnthostname AIXBK -ru root -shm -no_callback -connect_options 0x01020100 -jobid 808104 -jobgrpid 808104 08:57:34.147 [307446] <2> validate_parameters: tmcommon.c.4449: maximum fragment size is 1048576000 Kbytes 08:57:34.151 [307446] <2> io_init: bpbrm_shm_id = 46137354, buffer address = 0x30000000 08:57:34.155 [307446] <2> io_init: found index: 0 08:57:34.157 [307446] <2> io_init: using 262144 data buffer size 08:57:34.157 [307446] <2> io_init: CINDEX 0, sched Kbytes for monitoring = 60000 08:57:34.161 [307446] <2> io_init: using 64 data buffers 08:57:34.164 [307446] <2> io_init: child delay = 20, parent delay = 30 (milliseconds) 08:57:34.178 [307446] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 08:57:34.222 [307446] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 08:57:34.222 [307446] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 08:57:34.371 [307446] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 08:57:34.371 [307446] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35917 TO 10.2.21.10.13724 fd = 13 08:57:34.371 [307446] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.35917 TO 10.2.21.10.13724 08:57:34.371 [307446] <2> vauth_get_user_name: vauth_comm.c.726: cached_user_name: root 08:57:34.371 [307446] <2> vauth_get_user_name: vauth_comm.c.728: cached_user_name: :root 08:57:34.371 [307446] <2> vauth_get_user_name: vauth_comm.c.734: user_name: :root 08:57:34.371 [307446] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 08:57:34.371 [307446] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 08:57:34.371 [307446] <2> check_authentication: no authentication required 08:57:34.371 [307446] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 08:57:34.371 [307446] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 08:57:34.856 [307446] <2> mpx_setup_shm: buffer control shared memory address is 0x40000000, size is 49280, shmid is 14 08:57:34.856 [307446] <2> mpx_setup_shm: buf control for CINDEX 0 is 0x40000000 08:57:34.856 [307446] <2> mpx_setup_shm: shared memory address for group 0 is 0x50000000, size is 67108864, shmid is 15 08:57:34.856 [307446] <2> mpx_setup_shm: shared memory address for CINDEX 0 is 0x50000000, group 0, num_active 1 08:57:34.883 [307446] <2> setup_bpbkar_info: /usr/openv/netbackup/db/config/shm/AIXBK_1389574871 file successfully created 08:57:34.883 [307446] <2> get_data_socket: tmmpx.c.3453: port_status: 16908544 16908544 0x01020100 08:57:34.883 [307446] <2> get_data_socket: tmmpx.c.3454: shm_method: 1 1 0x00000001 08:57:34.883 [307446] <2> get_data_socket: tmmpx.c.3457: client_hostname: AIXBK 08:57:34.883 [307446] <2> nb_bind_on_port_addr: bound to port 3379 08:57:34.883 [307446] <2> get_data_socket: tmmpx.c.3522: *port: 3379 3379 0x00000d33 08:57:34.883 [307446] <2> get_data_socket: tmmpx.c.3523: mpx_ipc: 08:57:34.883 [307446] <2> mpx_start_child: tmmpx.c.1150: Calling: send_brm_msg(BRM_PORT) 08:57:34.883 [307446] <2> send_brm_msg: DATASOCKET AIXBK_1389574871 3379 08:57:34.883 [307446] <2> mpx_start_child: tmmpx.c.1155: Calling: bpcr_get_socket_rqst2 08:57:34.883 [307446] <2> mpx_start_child: tmmpx.c.1232: Calling: bpcr_get_socket_rqst4 08:57:36.058 [307446] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 08:57:36.162 [307446] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 08:57:36.162 [307446] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 08:57:36.288 [307446] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 08:57:36.288 [307446] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35922 TO 10.2.21.10.13724 fd = 13 08:57:36.288 [307446] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.35922 TO 10.2.21.10.13724 08:57:36.288 [307446] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 08:57:36.288 [307446] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 08:57:36.288 [307446] <2> check_authentication: no authentication required 08:57:36.288 [307446] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 08:57:36.288 [307446] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 08:57:36.864 [307446] <2> nbjm_media_request: Passing job control to NBJM, type WRITE 08:57:36.868 [307446] <2> RequestMultipleResources: starting 08:57:36.868 [307446] <2> RequestMultipleResources: started 08:57:36.875 [307446] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name 08:57:36.875 [307446] <2> VssInit: vss_auth.cpp.720: Function: VssInit. Using Cached entries FALSE 08:57:36.875 [307446] <2> VssGetFQDNHostName: vss_auth.cpp.4008: Function: VssGetFQDNHostName. Search name AIXBK 08:57:36.941 [307446] <2> packageMultiResourceRequest: started 08:57:36.941 [307446] <2> packageMultiResourceRequest: retVal = 0 08:57:36.941 [307446] <2> RequestMultipleResources: setting up callback and calling requestResources 08:57:36.941 [307446] <2> logResourceReq: req.versionId : 1 08:57:36.941 [307446] <2> logResourceReq: req.jobId : -1389007857 08:57:36.941 [307446] <2> logResourceReq: req.startedViaJobManager : true 08:57:36.941 [307446] <2> logResourceReq: req.consumer : true 08:57:36.941 [307446] <2> logResourceReq: STUSelect - 08:57:36.941 [307446] <2> logResourceReq: reqNum : 0 08:57:36.941 [307446] <2> logResourceReq: mediaServer : AIXBK 08:57:36.941 [307446] <2> logResourceReq: oldMediaId : 08:57:36.941 [307446] <2> logResourceReq: previousFailed : false 08:57:36.941 [307446] <2> logResourceReq: storageUnit : aixbk-hcart-robot-tld-0 08:57:36.941 [307446] <2> logResourceReq: mustBeNdmp : false 08:57:36.941 [307446] <2> logResourceReq: getMaxFreeSpace : false 08:57:36.941 [307446] <2> logResourceReq: mediaPool : NetBackup 08:57:36.941 [307446] <2> logResourceReq: retentionLevel : 10 08:57:36.941 [307446] <2> logResourceReq: mustUseLocalMediaServer : false 08:57:36.941 [307446] <2> logResourceReq: failOnError : false 08:57:36.941 [307446] <2> logResourceReq: mpxRequired : false 08:57:36.941 [307446] <2> logResourceReq: client : AIXBK 08:57:36.941 [307446] <2> logResourceReq: usageType : 1 08:57:36.948 [307446] <2> RequestMultipleResources: BpxmiV->requestResources returns 0 08:57:36.989 [307446] <2> resourcesAvailable: m_allocationSeq.length() == 1 08:57:36.989 [307446] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 4 08:57:36.989 [307446] <2> resourcesAvailable: MEDIADB 1 932034 0631L4 4001384 ------ 6 1389574870 0 0 0 0 0 0 10 1 0 0 0 0 0 0 08:57:36.989 [307446] <2> resourcesAvailable: VOLUME 1 0631L4 4001384 S40631L4 NetBackup FUJIFILM 11NG118157 6 8 0 60 0 {00000000-0000-0000-0000-000000000000} 0 08:57:36.989 [307446] <2> resourcesAvailable: DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0 08:57:36.989 [307446] <2> resourcesAvailable: STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576 08:57:38.955 [307446] <2> packageMultiResourceRequestResult: totalNumberOfAllocations == 1 08:57:38.955 [307446] <2> packageMultiResourceRequestResult: found MediaAllocation : reqNum == 0 08:57:38.955 [307446] <2> packageMultiResourceRequestResult: matched MediaAllocation to an stuReq 08:57:38.955 [307446] <2> packageMultiResourceRequestResult: retVal = 0 08:57:38.955 [307446] <2> RequestMultipleResources: retVal = 0 emmStatus = 0 08:57:38.955 [307446] <2> RequestMultipleResources: returning 08:57:38.955 [307446] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 932034 0631L4 4001384 ------ 6 1389574870 0 0 0 0 0 0 10 1 0 0 0 0 0 0], length 80 08:57:38.955 [307446] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 0631L4 4001384 S40631L4 NetBackup FUJIFILM 11NG118157 6 8 0 60 0 {00000000-0000-0000-0000-000000000000} 0], length 114 08:57:38.955 [307446] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0], length 110 08:57:38.955 [307446] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576], length 43 08:57:38.955 [307446] <2> populateBptmOpaqueStrings: retVal = 0 08:57:38.955 [307446] <2> parse_resource_strings: MEDIADB 1 932034 0631L4 4001384 ------ 6 1389574870 0 0 0 0 0 0 10 1 0 0 0 0 0 0 08:57:38.955 [307446] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters 08:57:38.955 [307446] <2> parse_resource_strings: VOLUME 1 0631L4 4001384 S40631L4 NetBackup FUJIFILM 11NG118157 6 8 0 60 0 {00000000-0000-0000-0000-000000000000} 0 08:57:38.955 [307446] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters 08:57:38.955 [307446] <2> parse_resource_strings: DRIVE 2 IBM.ULT3580-TD4.003 2000371 1310020535 /dev/rmt0.1 -1 -1 -1 -1 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 1 0 08:57:38.955 [307446] <2> parse_resource_strings: Parsed message type 17, version 2, 19 parameters 08:57:38.955 [307446] <2> parse_resource_strings: STORAGE 0 aixbk-hcart-robot-tld-0 6 1048576 08:57:38.955 [307446] <2> parse_resource_strings: Parsed message type 18, version 0, 4 parameters 08:57:38.955 [307446] <2> nbjm_media_request: Job control returned to BPTM 08:57:38.955 [307446] <2> drivename_open: Called with Create 1, file IBM.ULT3580-TD4.003 08:57:38.970 [307446] <2> drivename_lock: lock established 08:57:38.970 [307446] <2> drivename_write: Called with mode 0 08:57:38.975 [307446] <2> select_media: Tape allocated 1389574871, retention 10. Client 0 allocated 1389574871, retention 10 08:57:38.975 [307446] <2> send_MDS_msg: MEDIADB 1 932034 0631L4 4001384 *NULL* 6 1389574871 0 0 0 0 0 0 10 1 0 16 1024 0 0 0 08:57:39.011 [307446] <2> bptm media_id_to_monitor: job_id = 808104 08:57:39.018 [307446] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 08:57:39.073 [307446] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 08:57:39.073 [307446] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpjobd 08:57:39.220 [307446] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 08:57:39.220 [307446] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35929 TO 10.2.21.10.13724 fd = 20 08:57:39.220 [307446] <2> logconnections: BPJOBD CONNECT FROM 10.2.21.39.35929 TO 10.2.21.10.13724 08:57:39.220 [307446] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 08:57:39.220 [307446] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 08:57:39.220 [307446] <2> job_authenticate_connection: no authentication required 08:57:39.220 [307446] <2> job_authenticate_connection: ignoring VxSS authentication check for now... 08:57:39.222 [307446] <2> job_connect: Connected to the host hqmb1 contype 10 jobid <808104> socket <20> 08:57:39.222 [307446] <2> job_connect: Connected on port 35929 08:57:39.222 [307446] <2> bptm media_id_to_monitor: pDstMediaId = 0631L4 08:57:39.222 [307446] <2> set_job_details: Sending jobData jobid (808104) 08:57:39.222 [307446] <2> send_structure_data: Index 28 Field m_szDstMediaID Value <0631L4> 08:57:39.222 [307446] <2> set_job_details: Done 08:57:39.223 [307446] <2> mount_open_media: Waiting for mount of media id 0631L4 (copy 1) on server aixbk. 08:57:39.223 [307446] <4> create_tpreq_file: symlink to path /dev/rmt0.1 08:57:39.232 [307446] <2> manage_scsi_reserve: SCSI RESERVE 08:57:39.239 [307446] <4> expandpath: /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 08:57:39.961 [307446] <2> process_brm_msg: no pending message from bpbrm 08:58:36.099 [307446] <2> io_open: report_attr, fl1 0x00000849, fl2 0x00000000 08:58:36.118 [307446] <2> io_open: SCSI RESERVE 08:58:36.120 [307446] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 08:58:36.135 [307446] <2> write_backup: media id 0631L4 mounted on drive index 0, drivepath /dev/rmt0.1, drivename IBM.ULT3580-TD4.003, copy 1 08:58:36.135 [307446] <2> io_read_media_header: drive index 0, reading media header, buflen = 65536, buff = 0x2062b028, copy 1 08:58:36.135 [307446] <2> io_ioctl: command (6)MTREW 1 from (bptm.c.7774) on drive index 0 08:58:36.150 [307446] <2> io_write_media_header: drive index 0, writing media header 08:58:36.150 [307446] <2> io_ioctl: command (6)MTREW 1 from (bptm.c.9019) on drive index 0 08:58:36.168 [307446] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.9024 08:58:36.189 [307446] <2> io_open: SCSI RESERVE 08:58:36.191 [307446] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 08:58:36.254 [307446] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.9060) on drive index 0 08:58:39.691 [307446] <2> io_ioctl: command (6)MTREW 1 from (bptm.c.9067) on drive index 0 08:58:42.228 [307446] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.9070 08:58:42.232 [307446] <2> io_write_media_header: report_density, 0x46 [LTO-CVE U-416 ] 08:58:42.232 [307446] <2> send_MDS_msg: VOL_UPDATE 0 932034 0631L4 4001384 *NULL* *NULL* 7 70 08:58:42.281 [307446] <2> io_open: SCSI RESERVE 08:58:42.283 [307446] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 08:58:42.283 [307446] <2> io_ioctl: command (6)MTREW 1 from (bptm.c.9096) on drive index 0 08:58:42.286 [307446] <2> io_ioctl: command (11)MTFSF 1 from (bptm.c.9098) on drive index 0 08:58:42.290 [307446] <2> send_MDS_msg: MEDIADB 1 932034 0631L4 4001384 *NULL* 6 1389574871 1389574871 1389661271 0 0 0 0 10 1 0 0 1024 0 0 0 08:58:42.315 [307446] <2> vnet_async_connect: vnet_vnetd.c.3971: connect in progress: 0 0x00000000 08:58:42.361 [307446] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006 08:58:42.361 [307446] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: service: bpdbm 08:58:42.643 [307446] <2> vnet_async_connect: vnet_vnetd.c.4151: in progress connect: 0 0x00000000 08:58:42.643 [307446] <2> vnet_async_connect: vnet_vnetd.c.4154: connect: async CONNECT FROM 10.2.21.39.35933 TO 10.2.21.10.13724 fd = 23 08:58:42.643 [307446] <2> logconnections: BPDBM CONNECT FROM 10.2.21.39.35933 TO 10.2.21.10.13724 08:58:42.643 [307446] <2> vauth_authentication_required: vauth_comm.c.789: no methods for address: no authentication required 08:58:42.643 [307446] <2> vauth_connector: vauth_comm.c.200: no methods for address: no authentication required 08:58:42.649 [307446] <2> check_authentication: no authentication required 08:58:42.649 [307446] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.778: Ignoring VxSS authentication: 2 0x00000002 08:58:42.649 [307446] <2> vnet_check_vxss_client_magic_with_info: vnet_vxss_helper.c.934: Not using VxSS authentication: 2 0x00000002 08:58:43.270 [307446] <4> write_backup: begin writing backup id AIXBK_1389574871, copy 1, fragment 1, to media id 0631L4 on drive index 0 08:58:43.270 [307446] <2> process_brm_msg: no pending message from bpbrm 08:58:43.270 [307446] <2> write_backup: waiting 5 seconds for start of another backup 08:58:48.270 [307446] <2> send_brm_msg: MEDIA READY 08:58:48.280 [307446] <2> write_data: ndmp_dup_max_frag is set to 1073741824000 08:58:48.280 [307446] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: 0 twin_is_disk 0 delay_brm: 0 08:58:48.280 [307446] <2> io_ioctl: command (12)MTBSF 1 from (bptm.c.21169) on drive index 0 08:58:48.284 [307446] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003, from bptm.c.21176 08:58:48.286 [307446] <2> write_data: absolute block position prior to writing backup header(s) is 2, copy 1 08:58:48.300 [307446] <2> io_open: SCSI RESERVE 08:58:48.302 [307446] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 successfully opened (mode 2) 08:58:48.302 [307446] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.21229) on drive index 0 08:58:50.196 [307446] <2> io_write_back_header: drive index 0, AIXBK_1389574871, file num = 1, mpx_headers = 1, copy 1 08:58:50.209 [307446] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1 08:58:50.209 [307446] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0 08:58:50.209 [307446] <2> write_data: received first buffer (262144 bytes), begin writing data 08:59:29.394 [643298] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007861 -jm 08:59:29.420 [643298] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 08:59:29.424 [643298] <2> bptm: PORT_STATUS = 0x00000000 08:59:29.459 [643298] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 08:59:29.459 [643298] <2> drivename_checklock: Called 08:59:29.459 [643298] <2> drivename_checklock: PID 307446 has lock 08:59:29.466 [643298] <2> report_drives: MODE = 0 08:59:29.466 [643298] <2> report_drives: TIME = 1389574658 08:59:29.466 [643298] <2> report_drives: MASTER = hqmb1 08:59:29.466 [643298] <2> report_drives: PATH = /dev/rmt0.1 08:59:29.466 [643298] <2> report_drives: MEDIA = 0631L4 08:59:29.466 [643298] <2> report_drives: REQID = -1389007857 08:59:29.466 [643298] <2> report_drives: ALOCID = 932034 08:59:29.466 [643298] <2> report_drives: RBID = {19E809E5-0044-4E36-9006-7CF3FECB6370 08:59:29.466 [643298] <2> report_drives: PID = 307446 08:59:29.466 [643298] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 08:59:29.483 [643298] <2> main: Sending [EXIT STATUS 0] to NBJM 08:59:29.483 [643298] <2> bptm: EXITING with status 0 <---------- 09:05:55.709 [540856] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 09:05:55.735 [540856] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 09:05:55.755 [540856] <2> bptm: EXITING with status 0 <---------- 09:09:30.367 [327714] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007864 -jm 09:09:30.388 [327714] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 09:09:30.408 [327714] <2> bptm: PORT_STATUS = 0x00000000 09:09:30.428 [327714] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 09:09:30.428 [327714] <2> drivename_checklock: Called 09:09:30.428 [327714] <2> drivename_checklock: PID 307446 has lock 09:09:30.434 [327714] <2> report_drives: MODE = 0 09:09:30.435 [327714] <2> report_drives: TIME = 1389574658 09:09:30.435 [327714] <2> report_drives: MASTER = hqmb1 09:09:30.435 [327714] <2> report_drives: PATH = /dev/rmt0.1 09:09:30.435 [327714] <2> report_drives: MEDIA = 0631L4 09:09:30.435 [327714] <2> report_drives: REQID = -1389007857 09:09:30.435 [327714] <2> report_drives: ALOCID = 932034 09:09:30.435 [327714] <2> report_drives: RBID = {19E809E5-0044-4E36-9006-7CF3FECB6370 09:09:30.435 [327714] <2> report_drives: PID = 307446 09:09:30.435 [327714] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 09:09:30.440 [327714] <2> main: Sending [EXIT STATUS 0] to NBJM 09:09:30.440 [327714] <2> bptm: EXITING with status 0 <---------- 09:16:13.524 [643192] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 09:16:13.551 [643192] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 09:16:13.574 [643192] <2> bptm: EXITING with status 0 <---------- 09:19:29.996 [643278] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1389007868 -jm 09:19:30.028 [643278] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 09:19:30.045 [643278] <2> bptm: PORT_STATUS = 0x00000000 09:19:30.087 [643278] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.003 09:19:30.092 [643278] <2> drivename_checklock: Called 09:19:30.092 [643278] <2> drivename_checklock: PID 307446 has lock 09:19:30.103 [643278] <2> report_drives: MODE = 0 09:19:30.103 [643278] <2> report_drives: TIME = 1389574658 09:19:30.103 [643278] <2> report_drives: MASTER = hqmb1 09:19:30.103 [643278] <2> report_drives: PATH = /dev/rmt0.1 09:19:30.103 [643278] <2> report_drives: MEDIA = 0631L4 09:19:30.103 [643278] <2> report_drives: REQID = -1389007857 09:19:30.103 [643278] <2> report_drives: ALOCID = 932034 09:19:30.103 [643278] <2> report_drives: RBID = {19E809E5-0044-4E36-9006-7CF3FECB6370 09:19:30.104 [643278] <2> report_drives: PID = 307446 09:19:30.104 [643278] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.003 09:19:30.134 [643278] <2> main: Sending [EXIT STATUS 0] to NBJM 09:19:30.135 [643278] <2> bptm: EXITING with status 0 <---------- 09:26:27.960 [643146] <2> bptm: INITIATING (VERBOSE = 5): -delete_expired 09:26:27.992 [643146] <2> nbconf_get_info: nbconf_glue.cpp.237: NBCONF_LIB: /usr/openv/lib/libVnbconf.so 09:26:28.067 [643146] <2> bptm: EXITING with status 0 <----------