nbu备份报错13 file read failed

Question

nbu备份报错13 file read failed
master server 6.5
相关报错如下:
12/11/2009 03:28:49 ycdb ycdb  started backup job for client ycdb, policy YKCDB-DB-BKP, schedule Default-Application-Backup on
                    storage unit ycdb-hcart2-robot-tld-1
12/11/2009 03:28:51 ycdb ycdb  started backup job for client ycdb, policy YKCDB-DB-BKP, schedule Default-Application-Backup on
                    storage unit ycdb-hcart2-robot-tld-1
12/11/2009 03:28:52 ycdb ycdb  started backup job for client ycdb, policy YKCDB-DB-BKP, schedule Default-Application-Backup on
                    storage unit ycdb-hcart2-robot-tld-1
12/11/2009 03:29:34 ycdb ycdb  socket read failed: errno = 119 - System call timed out.
12/11/2009 03:29:37 ycdb ycdb  media manager terminated by parent process
12/11/2009 03:29:44 ycdb ycdb  begin writing backup id ycdb_1260473329, copy 1, fragment 1, to media id A00241 on drive
                    ngbss_mast_svrhcart2TLD00117 (index 17)
12/11/2009 03:29:45 ycdb ycdb  begin writing backup id ycdb_1260473330, copy 1, fragment 1, to media id A00245 on drive
                    ngbss_mast_svrhcart2TLD0012 (index 16)
12/11/2009 03:29:45 ycdb ycdb  begin writing backup id yk
12/11/2009 03:29:48 ycdb ycdb  backup of client ycdb exited with status 13 (file read failed)

Answer 1

2012-1-11 22:20:22 - Error bpbrm(pid=7437) socket read failed: errno = 62 - Timer expired   

检查一下客户端的bpcd和bpbkar日志.

Answer 2

同样是13号错：
2012-1-11 21:52:37 - requesting resource dwdb03-hcart2-robot-tld-2
2012-1-11 21:52:37 - requesting resource nbu_master_nh.NBU_CLIENT.MAXJOBS.dwdb03
2012-1-11 21:52:37 - requesting resource nbu_master_nh.NBU_POLICY.MAXJOBS.dwdb03
2012-1-11 21:52:43 - granted resource nbu_master_nh.NBU_CLIENT.MAXJOBS.dwdb03
2012-1-11 21:52:43 - granted resource nbu_master_nh.NBU_POLICY.MAXJOBS.dwdb03
2012-1-11 21:52:43 - granted resource 000956
2012-1-11 21:52:43 - granted resource HP.ULTRIUM5-SCSI.004
2012-1-11 21:52:43 - granted resource dwdb03-hcart2-robot-tld-2
2012-1-11 21:52:43 - estimated 0 Kbytes needed
2012-1-11 21:52:44 - started process bpbrm (7437)
2012-1-11 21:52:45 - connecting
2012-1-11 21:52:53 - connected; connect time: 00:00:08
2012-1-11 21:52:54 - mounting 000956
2012-1-11 21:55:15 - Error bptm(pid=753 error requesting media, TpErrno = Robot operation failed     
2012-1-11 21:55:15 - Warning bptm(pid=753 media id 000956 load operation reported an error     
2012-1-11 21:55:15 - current media 000956 complete, requesting next resource Any
2012-1-11 21:57:32 - current media -- complete, awaiting next media Any Reason: Media is in use, Media Server: dwdb03,
          Robot Number: 2, Robot Type: TLD, Media ID: N/A, Drive Name: N/A,
          Volume Pool: dwdb-db, Storage Unit: dwdb03-hcart2-robot-tld-2, Drive Scan Host: N/A
         
2012-1-11 22:15:18 - granted resource 000929
2012-1-11 22:15:18 - granted resource HP.ULTRIUM5-SCSI.005
2012-1-11 22:15:18 - granted resource dwdb03-hcart2-robot-tld-2
2012-1-11 22:15:19 - mounted
2012-1-11 22:15:19 - positioning 000929 to file 5
2012-1-11 22:15:22 - positioned 000929; position time: 00:00:03
2012-1-11 22:15:22 - begin writing
2012-1-11 22:20:22 - Error bpbrm(pid=7437) socket read failed: errno = 62 - Timer expired   
2012-1-11 22:20:25 - Error bptm(pid=753 media manager terminated by parent process      
2012-1-11 22:20:50 - end writing; write time: 00:05:28
file read failed(13)

     请教高手！

Answer 3

有可能文件正在被读写

Answer 4

一个是client connect timeout 一个是client read timeout，缺省是300，改成3000试一试。

Answer 5

原帖由 无牙 于 2009-12-12 21:18 发表
改一下超时时间再试一试。

改media server/client属性中的加NetBackup Client Read Timeout ?

Answer 6

改一下超时时间再试一试。

Answer 7

感觉是备份的文件太大。

请大家多多指教

Answer 8

03:28:27.046 [737806] <2> io_open: SCSI RESERVE
03:28:27.046 [737806] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_ngbss_mast_svrhcart2TLD0018 successfully opened (m
ode 0)
03:28:27.046 [737806] <2> io_ioctl: command (12)MTBSF 2 from (bptm.c.8902) on drive index 8
03:28:27.093 [647406] <4> report_throughput: VBRT 1 647406 5 1 ngbss_mast_svrhcart2TLD00117 A00241 0 1 0 15170848  15170848 (bptm.c.
22075)
03:28:27.121 [647406] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2043: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
03:28:27.122 [647406] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2057: service: bpdbm
03:28:27.261 [647406] <2> logconnections: BPDBM CONNECT FROM 192.168.15.1.38796 TO 192.168.9.19.13724
03:28:27.684 [647406] <2> send_MDS_msg: MEDIADB 1 60926 A00241 4000232 *NULL* 14 1254348356 1260472800 1261682400 0 568461312 56 30
1 23 0 0 1024 0 2220715 0
03:28:27.728 [647406] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2043: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
03:28:27.728 [647406] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2057: service: bpdbm
03:28:27.861 [647406] <2> logconnections: BPDBM CONNECT FROM 192.168.15.1.38797 TO 192.168.9.19.13724
03:28:28.076 [659494] <2> io_terminate_tape: absolute block position prior to writing empty header is 1685559, copy 1
03:28:28.076 [659494] <2> io_terminate_tape: block position check: actual 1685559, expected 1685559
03:28:28.076 [659494] <2> send_MDS_msg: MEDIADB 1 60927 A00245 4000233 *NULL* 14 1255633218 1260472811 1261682411 0 418169184 27 8 1
23 0 0 1024 0 1685559 0
03:28:28.112 [659494] <2> io_open: SCSI RESERVE
03:28:28.112 [659494] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_ngbss_mast_svrhcart2TLD0012 successfully opened (m
ode 0)
03:28:28.113 [659494] <2> io_ioctl: command (12)MTBSF 2 from (bptm.c.8902) on drive index 16
03:28:28.280 [647406] <4> write_backup: successfully wrote backup id ycdb_1260472800, copy 1, fragment 1, 15170848 Kbytes at 34195
.224 Kbytes/sec
03:28:28.280 [647406] <2> notify: executing - /usr/openv/netbackup/bin/backup_notify bptm ycdb_1260472800
03:28:28.327 [647406] <2> updateEMM_freespace: updateEMM_freespace() (1 0)
03:28:28.327 [647406] <2> updateEMM_freespace: 0, ycdb-hcart2-robot-tld-1 (1 0 2 1)
03:28:28.327 [647406] <2> bptm: Calling tpunmount for media A00241
03:28:28.327 [647406] <2> drivename_write: Called with mode 1
03:28:28.327 [647406] <2> drivename_unlock: unlocked
03:28:28.327 [647406] <2> drivename_close: Called for file ngbss_mast_svrhcart2TLD00117
03:28:28.327 [647406] <2> send_MDS_msg: MEDIA_DONE 0 -1257606833 0 A00241 4000232 180 {02A90BBC-1DD2-11B2-8B28-5C516D380000}
03:28:28.327 [647406] <2> packageBptmResourceDoneMsg: msg (MEDIA_DONE 0 -1257606833 0 A00241 4000232 180 {02A90BBC-1DD2-11B2-8B28-5C
03:28:28.327 [647406] <2> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid -1257606833 copyNum 0 mediaId A00241 mediaK
ey 4000232 unloadDelay 180 allocId {02A90BBC-1DD2-11B2-8B28-5C516D380000}
03:28:28.327 [647406] <2> packageBptmResourceDoneMsg: returns 0
03:28:28.329 [647406] <2> JobInst::sendIrmMsg: returning
03:28:28.329 [647406] <2> bptm: EXITING with status 0 <----------
03:28:28.351 [647406] <2> cleanup: Detached from BPBRM shared memory
03:28:29.275 [737806] <2> io_ioctl: command (11)MTFSF 1 from (bptm.c.8904) on drive index 8
03:28:29.285 [737806] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_ngbss_mast_svrhcart2TLD0018, from bptm.c.8910
03:28:29.290 [737806] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from io_terminate_tape)
03:28:29.317 [737806] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2043: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
03:28:29.317 [737806] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2057: service: bpdbm
03:28:29.461 [737806] <2> logconnections: BPDBM CONNECT FROM 192.168.15.1.38799 TO 192.168.9.19.13724
03:28:29.881 [737806] <4> report_throughput: VBRT 1 737806 5 1 ngbss_mast_svrhcart2TLD0018 A00252 0 1 0 14329632  14329632 (bptm.c.2
2075)
03:28:29.910 [737806] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2043: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
03:28:29.910 [737806] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2057: service: bpdbm

03:29:02.142 [4383414] <2> logconnections: BPDBM ACCEPT FROM 192.168.9.19.57070 TO 192.168.9.19.13724
03:29:02.338 [4383414] <2> bpdbm: request complete: exit status 0  
03:29:10.942 [6099398] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38914 TO 192.168.9.19.13724
03:29:10.943 [4383420] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38913 TO 192.168.9.19.13724
03:29:11.339 [4383420] <2> config_db: Q_CONFIGGET
03:29:11.339 [6099398] <2> config_db: Q_CONFIGGET
03:29:11.340 [6091064] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38915 TO 192.168.9.19.13724
03:29:11.343 [4383420] <2> LOCAL CLASS_ATT_DEFS: Product ID = 6
03:29:11.343 [6099398] <2> LOCAL CLASS_ATT_DEFS: Product ID = 6
03:29:11.344 [4383420] <2> bpdbm: request complete: exit status 0  
03:29:11.344 [6099398] <2> bpdbm: request complete: exit status 0  
03:29:11.540 [6181274] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38917 TO 192.168.9.19.13724
03:29:11.541 [4158092] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38916 TO 192.168.9.19.13724
03:29:11.739 [6091064] <2> config_db: Q_CONFIGGET
03:29:11.743 [6091064] <2> LOCAL CLASS_ATT_DEFS: Product ID = 6
03:29:11.744 [6091064] <2> bpdbm: request complete: exit status 0  
03:29:11.939 [6181274] <2> error_db: Q_ERRADD
03:29:11.939 [4158092] <2> error_db: Q_ERRADD
03:29:11.939 [6181274] <2> db_error_add_to_file: dberrorq.c:midnite = 1260460800
03:29:11.939 [4158092] <2> db_error_add_to_file: dberrorq.c:midnite = 1260460800
03:29:11.940 [4145792] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38918 TO 192.168.9.19.13724
03:29:11.956 [6181274] <2> bpdbm: request complete: exit status 0  
03:29:11.967 [4158092] <2> bpdbm: request complete: exit status 0  
03:29:12.140 [6115646] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38920 TO 192.168.9.19.13724
03:29:12.141 [4199088] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38919 TO 192.168.9.19.13724
03:29:12.339 [4145792] <2> error_db: Q_ERRADD
03:29:12.339 [4145792] <2> db_error_add_to_file: dberrorq.c:midnite = 1260460800
03:29:12.355 [4145792] <2> bpdbm: request complete: exit status 0  
03:29:12.539 [6115646] <2> image_db: Q_IMAGE_BY_BACKUPID
03:29:12.539 [4199088] <2> image_db: Q_IMAGE_BY_BACKUPID
03:29:12.540 [6115646] <2> db_get_image_info: Job in progress, found image file /usr/openv/netbackup/db/images/ycdb/1260000000/tmp
/YKCDB-DB-BKP_1260473330_UBAK
03:29:12.540 [4199088] <2> db_get_image_info: Job in progress, found image file /usr/openv/netbackup/db/images/ycdb/1260000000/tmp
/YKCDB-DB-BKP_1260473329_UBAK
03:29:12.540 [6115646] <2> bpdbm: request complete: exit status 0  
03:29:12.540 [4199088] <2> bpdbm: request complete: exit status 0  
03:29:12.540 [4309570] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38921 TO 192.168.9.19.13724
03:29:12.939 [4309570] <2> image_db: Q_IMAGE_BY_BACKUPID
03:29:12.939 [4309570] <2> db_get_image_info: Job in progress, found image file /usr/openv/netbackup/db/images/ycdb/1260000000/tmp
/YKCDB-DB-BKP_1260473331_UBAK
03:29:12.940 [4309570] <2> bpdbm: request complete: exit status 0  
03:29:34.143 [4383436] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38925 TO 192.168.9.19.13724
03:29:34.540 [4383436] <2> error_db: Q_ERRADD
03:29:34.540 [4383436] <2> db_error_add_to_file: dberrorq.c:midnite = 1260460800
03:29:34.557 [4383436] <2> bpdbm: request complete: exit status 0  
03:29:36.743 [5984518] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38928 TO 192.168.9.19.13724
03:29:37.140 [5984518] <2> error_db: Q_ERRADD
03:29:37.140 [5984518] <2> db_error_add_to_file: dberrorq.c:midnite = 1260460800
03:29:37.152 [5984518] <2> bpdbm: request complete: exit status 0  
03:29:42.743 [6099410] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38930 TO 192.168.9.19.13724
03:29:42.744 [4326138] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38931 TO 192.168.9.19.13724
03:29:43.140 [4326138] <2> error_db: Q_ERRADD
03:29:43.140 [6099410] <2> error_db: Q_ERRADD
03:29:43.140 [4326138] <2> db_error_add_to_file: dberrorq.c:midnite = 1260460800
03:29:43.140 [6099410] <2> db_error_add_to_file: dberrorq.c:midnite = 1260460800
03:29:43.141 [5984524] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38932 TO 192.168.9.19.13724
03:29:43.147 [4326138] <2> bpdbm: request complete: exit status 0  
03:29:43.155 [6099410] <2> bpdbm: request complete: exit status 0  
03:29:43.540 [5984524] <2> error_db: Q_ERRADD
03:29:43.540 [5984524] <2> db_error_add_to_file: dberrorq.c:midnite = 1260460800
03:29:43.550 [5984524] <2> bpdbm: request complete: exit status 0  
03:29:44.343 [6181288] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38933 TO 192.168.9.19.13724
03:29:44.740 [6181288] <2> error_db: Q_ERRADD
03:29:44.740 [6181288] <2> db_error_add_to_file: dberrorq.c:midnite = 1260460800
03:29:44.751 [6181288] <2> bpdbm: request complete: exit status 0  
03:29:44.943 [5984526] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38935 TO 192.168.9.19.13724
03:29:45.141 [6091066] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38936 TO 192.168.9.19.13724
03:29:45.340 [5984526] <2> error_db: Q_ERRADD
03:29:45.340 [5984526] <2> db_error_add_to_file: dberrorq.c:midnite = 1260460800
03:29:45.351 [5984526] <2> bpdbm: request complete: exit status 0  
03:29:45.540 [6091066] <2> error_db: Q_ERRADD
03:29:45.540 [6091066] <2> db_error_add_to_file: dberrorq.c:midnite = 1260460800
03:29:45.547 [6091066] <2> bpdbm: request complete: exit status 0  
03:29:58.944 [5984534] <2> logconnections: BPDBM ACCEPT FROM 192.168.15.1.38940 TO 192.168.9.19.13724
03:29:59.341 [5984534] <2> image_db: Q_IMAGE_ADD_FILES (locking)
03:29:59.341 [5984534] <2> db_get_image_info: Job in progress, found image file /usr/openv/netbackup/db/images/ycdb/1260000000/tmp
/YKCDB-DB-BKP_1260473331_UBAK

Answer 9

03:28:20.899 [647406] <2> write_data: writing block shorter than BUFF_SIZE, 32768 bytes
03:28:20.899 [647406] <2> write_data: writing short block, 32768 bytes, remainder 0
03:28:20.899 [647406] <2> write_data: waited for full buffer 110 times, delayed 17325 times
03:28:20.899 [647406] <2> write_data: Total Kbytes transferred 15170848
03:28:20.899 [647406] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = 0
03:28:20.899 [647406] <2> io_terminate_tape: writing empty backup header, drive index 17, copy 1
03:28:20.899 [647406] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.8627) on drive index 17
03:28:21.978 [647406] <2> io_write_back_header: drive index 17, empty_file, file num = 57, mpx_headers = 0, copy 1
03:28:21.987 [647406] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_ngbss_mast_svrhcart2TLD00117, from bptm.c.8745
03:28:23.420 [737806] <2> write_data: writing block shorter than BUFF_SIZE, 32768 bytes
03:28:23.421 [737806] <2> write_data: writing short block, 32768 bytes, remainder 0
03:28:23.421 [737806] <2> write_data: waited for full buffer 634 times, delayed 17066 times
03:28:23.421 [737806] <2> write_data: Total Kbytes transferred 14329632
03:28:23.421 [737806] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = 0
03:28:23.421 [737806] <2> io_terminate_tape: writing empty backup header, drive index 8, copy 1
03:28:23.421 [737806] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.8627) on drive index 8

03:29:02.559 [6042064] <4> db_getSTUNITlist: emmserver_name = ngbss_mast_svr
03:29:02.559 [6042064] <4> db_getSTUNITlist: emmserver_port = 1556
03:29:02.585 [6042064] <2> Orb::init: initializing ORB Default_CLIENT_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAdd
resses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''"
-ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-
ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_CLIENT_Orb'" -ORBSvcConfDirect
ive "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf /dev/null -ORBSvcConfDirective "static Server_Strategy_Fact
ory '-ORBMaxRecvGIOPPayloadSize 268435456'"  -ORBDebug  -ORBDebugLevel 1(Orb.cpp:714)
03:29:02.585 [6042064] <2> TAO: starting up daemon dbstunitq
03:29:02.585 [6042064] <2> TAO: Service_Config::process_directive - static PBXIOP_Factory '-enable_keepalive'
03:29:02.585 [6042064] <2> TAO: opening static service PBXIOP_Factory
03:29:02.585 [6042064] <2> TAO: did static on PBXIOP_Factory, error = 0
03:29:02.585 [6042064] <2> TAO: Service_Config::process_directive - static EndpointSelectorFactory ''
03:29:02.585 [6042064] <2> TAO: opening static service EndpointSelectorFactory
03:29:02.585 [6042064] <2> TAO: did static on EndpointSelectorFactory, error = 0
03:29:02.585 [6042064] <2> TAO: Service_Config::process_directive - static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'
03:29:02.585 [6042064] <2> TAO: opening static service Resource_Factory
03:29:02.585 [6042064] <2> TAO: did static on Resource_Factory, error = 0
03:29:02.586 [6042064] <2> TAO: Service_Config::process_directive - static Resource_Factory '-ORBProtocolFactory IIOP_Factory'
03:29:02.586 [6042064] <2> TAO: opening static service Resource_Factory
03:29:02.586 [6042064] <2> TAO: did static on Resource_Factory, error = 0
03:29:02.586 [6042064] <2> TAO: Service_Config::process_directive - static PBXIOP_Evaluator_Factory '-orb Default_CLIENT_Orb'
03:29:02.586 [6042064] <2> TAO: opening static service PBXIOP_Evaluator_Factory
03:29:02.586 [6042064] <2> TAO: did static on PBXIOP_Evaluator_Factory, error = 0
03:29:02.586 [6042064] <2> TAO: Service_Config::process_directive - static Resource_Factory '-ORBConnectionCacheMax 1024 '
03:29:02.586 [6042064] <2> TAO: opening static service Resource_Factory
03:29:02.586 [6042064] <2> TAO: did static on Resource_Factory, error = 0
03:29:02.586 [6042064] <2> TAO: Service_Config::process_directive - static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 26843
5456'
03:29:02.586 [6042064] <2> TAO: opening static service Server_Strategy_Factory
03:29:02.586 [6042064] <2> TAO: did static on Server_Strategy_Factory, error = 0
03:29:02.586 [6042064] <2> TAO: ACE_Select_Reactor_Notify:pen: notification pipe successfully opened with read_handle=8, write_han
dle=9
03:29:02.586 [6042064] <2> TAO: TAO (6042064|1) Loaded protocol <BXIOP_Factory>
03:29:02.586 [6042064] <2> TAO: TAO (6042064|1) Loaded protocol <IIOP_Factory>
03:29:02.594 [6042064] <2> TAO: TAO (6042064|1) Timeout is <60000>
03:29:02.594 [6042064] <2> TAO: TAO (6042064|1) Timeout is <0>
03:29:02.595 [6042064] <2> TAO: TAO (6042064|1) - Transport_Cache_Manager::fill_set_i, current_size = 0, cache_maximum = 1024
03:29:02.595 [6042064] <2> TAO: (6042064|1) PBXIOP_Connector::get_local_address, policy supplied local addr:130.51.9.19
03:29:02.595 [6042064] <2> TAO: (6042064|1) PBXIOP_Connector::get_local_address using local addr 130.51.9.19
03:29:02.595 [6042064] <2> TAO: (6042064|1) PBXIOP_Connector::make_connection, attempting local bind to 0
03:29:02.595 [6042064] <2> TAO: TAO (6042064|1) PBXIOP connection to peer <130.51.9.19:1556> on 10
03:29:02.596 [6042064] <2> TAO: TAO (6042064|1) - Transport_Cache_Manager::bind_i, 0x2ff1d3e8 -> 0x301a9118 Transport[10]
03:29:02.596 [6042064] <2> TAO: TAO (6042064|1) - Synch_Invocation::invoke_i, timeout on recv is <59998>
03:29:02.597 [6042064] <2> TAO: TAO (6042064|1) Synch_Invocation::invoke_i, timeout after recv is <59995> status <1>
03:29:02.604 [6042064] <2> TAO: TAO (6042064|1) Timeout is <0>
03:29:02.604 [6042064] <2> TAO: TAO (6042064|1) - Transport_Cache_Manager::fill_set_i, current_size = 1, cache_maximum = 1024
03:29:02.604 [6042064] <2> TAO: (6042064|1) PBXIOP_Connector::get_local_address, policy supplied local addr:130.51.9.19
03:29:02.604 [6042064] <2> TAO: (6042064|1) PBXIOP_Connector::get_local_address using local addr 130.51.9.19
03:29:02.604 [6042064] <2> TAO: (6042064|1) PBXIOP_Connector::make_connection, attempting local bind to 0
03:29:02.604 [6042064] <2> TAO: TAO (6042064|1) PBXIOP connection to peer <130.51.9.19:1556> on 11
03:29:02.604 [6042064] <2> TAO: TAO (6042064|1) - Transport_Cache_Manager::bind_i, 0x2ff1dbd8 -> 0x301bb078 Transport[11]
03:29:02.604 [6042064] <2> TAO: TAO (6042064|1) - Synch_Invocation::invoke_i, timeout on recv is <59988>
03:29:02.605 [6042064] <2> TAO: TAO (6042064|1) Synch_Invocation::invoke_i, timeout after recv is <59986> status <1>
03:29:02.605 [6042064] <2> TAO: TAO (6042064|1) Timeout is <60000>
03:29:02.605 [6042064] <2> TAO: TAO (6042064|1) Timeout is <0>
03:29:02.606 [6042064] <2> TAO: TAO (6042064|1) - Transport_Cache_Manager::is_entry_idle_i, state is [0]
03:29:02.606 [6042064] <2> TAO: TAO (6042064|1) - Synch_Invocation::invoke_i, timeout on recv is <59999>
03:29:02.606 [6042064] <2> TAO: TAO (6042064|1) Synch_Invocation::invoke_i, timeout after recv is <59999> status <1>
03:29:02.606 [6042064] <2> TAO: TAO (6042064|1) Timeout is <60000>
03:29:02.606 [6042064] <2> TAO: TAO (6042064|1) Timeout is <0>
03:29:02.606 [6042064] <2> TAO: TAO (6042064|1) - Transport_Cache_Manager::is_entry_idle_i, state is [0]
03:29:02.606 [6042064] <2> TAO: TAO (6042064|1) - Synch_Invocation::invoke_i, timeout on recv is <59999>
03:29:02.607 [6042064] <2> TAO: TAO (6042064|1) Synch_Invocation::invoke_i, timeout after recv is <59998> status <1>
03:29:02.607 [6042064] <2> TAO: TAO (6042064|1) Timeout is <1800000>
03:29:02.607 [6042064] <2> TAO: TAO (6042064|1) Timeout is <0>
03:29:02.607 [6042064] <2> TAO: TAO (6042064|1) - Transport_Cache_Manager::is_entry_idle_i, state is [0]
03:29:02.607 [6042064] <2> TAO: TAO (6042064|1) - Synch_Invocation::invoke_i, timeout on recv is <1799999>
03:29:02.739 [6042064] <2> TAO: TAO (6042064|1) Synch_Invocation::invoke_i, timeout after recv is <1799735> status <1>
03:29:02.740 [6042064] <2> TAO: TAO (6042064|1) Timeout is <60000>
03:29:02.740 [6042064] <2> TAO: TAO (6042064|1) Timeout is <0>
03:29:02.740 [6042064] <2> TAO: TAO (6042064|1) - Transport_Cache_Manager::is_entry_idle_i, state is [0]
03:29:02.740 [6042064] <2> TAO: TAO (6042064|1) - Synch_Invocation::invoke_i, timeout on recv is <59999>
03:29:02.740 [6042064] <2> TAO: TAO (6042064|1) Synch_Invocation::invoke_i, timeout after recv is <59998> status <1>
03:29:02.741 [6042064] <2> TAO: TAO (6042064|1) Timeout is <1800000>
03:29:02.741 [6042064] <2> TAO: TAO (6042064|1) Timeout is <0>
03:29:02.741 [6042064] <2> TAO: TAO (6042064|1) - Transport_Cache_Manager::is_entry_idle_i, state is [0]
03:29:02.741 [6042064] <2> TAO: TAO (6042064|1) - Synch_Invocation::invoke_i, timeout on recv is <1799999>
03:29:02.747 [6042064] <2> TAO: TAO (6042064|1) Synch_Invocation::invoke_i, timeout after recv is <1799987> status <1>
03:29:04.749 [6042064] <2> TAO: finalizing ACE_Naming_Context
03:29:04.749 [6042064] <2> TAO: ACE_Naming_Context::fini
03:29:04.749 [6042064] <2> TAO: destroying ACE_Naming_Context, flags = 3
03:29:04.749 [6042064] <2> TAO: finalizing Notify_Default_Event_Manager_Objects_Factory
03:29:04.749 [6042064] <2> TAO: destroying Notify_Default_Event_Manager_Objects_Factory, flags = 3
03:29:04.749 [6042064] <2> TAO: finalizing CosNotify_Service
03:29:04.749 [6042064] <2> TAO: destroying CosNotify_Service, flags = 3
03:29:04.749 [6042064] <2> TAO: finalizing ACE_Service_Manager
03:29:04.749 [6042064] <2> TAO: destroying ACE_Service_Manager, flags = 3
03:29:04.749 [6042064] <2> TAO: finalizing Default_Collocation_Resolver
03:29:04.749 [6042064] <2> TAO: destroying Default_Collocation_Resolver, flags = 3
03:29:04.749 [6042064] <2> TAO: finalizing Default_Thread_Lane_Resources_Manager_Factory
03:29:04.749 [6042064] <2> TAO: destroying Default_Thread_Lane_Resources_Manager_Factory, flags = 3
03:29:04.749 [6042064] <2> TAO: finalizing Protocols_Hooks
03:29:04.749 [6042064] <2> TAO: destroying Protocols_Hooks, flags = 3
03:29:04.749 [6042064] <2> TAO: finalizing Default_Endpoint_Selector_Factory
03:29:04.749 [6042064] <2> TAO: destroying Default_Endpoint_Selector_Factory, flags = 3
03:29:04.749 [6042064] <2> TAO: finalizing Default_Stub_Factory
03:29:04.749 [6042064] <2> TAO: destroying Default_Stub_Factory, flags = 3
03:29:04.749 [6042064] <2> TAO: finalizing DLL_Parser
03:29:04.749 [6042064] <2> TAO: destroying DLL_Parser, flags = 3
03:29:04.749 [6042064] <2> TAO: finalizing FILE_Parser
03:29:04.749 [6042064] <2> TAO: destroying FILE_Parser, flags = 3
03:29:04.749 [6042064] <2> TAO: finalizing CORBALOC_Parser
03:29:04.750 [6042064] <2> TAO: destroying CORBALOC_Parser, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing CORBANAME_Parser
03:29:04.750 [6042064] <2> TAO: destroying CORBANAME_Parser, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing MCAST_Parser
03:29:04.750 [6042064] <2> TAO: destroying MCAST_Parser, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing IIOP_Factory
03:29:04.750 [6042064] <2> TAO: destroying IIOP_Factory, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing EndpointSelectorFactory
03:29:04.750 [6042064] <2> TAO: destroying EndpointSelectorFactory, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing PBXIOP_Evaluator_Factory
03:29:04.750 [6042064] <2> TAO: destroying PBXIOP_Evaluator_Factory, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing VxSSIOP_Factory
03:29:04.750 [6042064] <2> TAO: destroying VxSSIOP_Factory, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing PBXIOP_Factory
03:29:04.750 [6042064] <2> TAO: destroying PBXIOP_Factory, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing UTF16_BOM_Factory
03:29:04.750 [6042064] <2> TAO: destroying UTF16_BOM_Factory, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing UTF8-Latin1_Factory
03:29:04.750 [6042064] <2> TAO: destroying UTF8-Latin1_Factory, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing Server_Strategy_Factory
03:29:04.750 [6042064] <2> TAO: destroying Server_Strategy_Factory, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing Client_Strategy_Factory
03:29:04.750 [6042064] <2> TAO: destroying Client_Strategy_Factory, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing Resource_Factory
03:29:04.750 [6042064] <2> TAO: destroying Resource_Factory, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing DynamicAny_Loader
03:29:04.750 [6042064] <2> TAO: destroying DynamicAny_Loader, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing TAO_POA
03:29:04.750 [6042064] <2> TAO: destroying TAO_POA, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing TAO_IORTable
03:29:04.750 [6042064] <2> TAO: destroying TAO_IORTable, flags = 3
03:29:04.750 [6042064] <2> TAO: finalizing BiDirGIOP_Loader
03:29:04.750 [6042064] <2> TAO: destroying BiDirGIOP_Loader, flags = 3
03:28:24.266 [647406] <2> io_terminate_tape: absolute block position prior to writing empty header is 2220715, copy 1
03:28:24.266 [647406] <2> io_terminate_tape: block position check: actual 2220715, expected 2220715
03:28:24.266 [647406] <2> send_MDS_msg: MEDIADB 1 60926 A00241 4000232 *NULL* 14 1254348356 1260472800 1261682400 0 553290464 55 29
1 23 0 0 1024 0 2220715 0
03:28:24.298 [647406] <2> io_open: SCSI RESERVE
03:28:24.298 [647406] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_ngbss_mast_svrhcart2TLD00117 successfully opened (
mode 0)
03:28:24.298 [647406] <2> io_ioctl: command (12)MTBSF 2 from (bptm.c.8902) on drive index 17
03:28:24.572 [659494] <2> write_data: writing block shorter than BUFF_SIZE, 32768 bytes
03:28:24.572 [659494] <2> write_data: writing short block, 32768 bytes, remainder 0
03:28:24.572 [659494] <2> write_data: waited for full buffer 795 times, delayed 18299 times
03:28:24.572 [659494] <2> write_data: Total Kbytes transferred 13312800
03:28:24.572 [659494] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = 0
03:28:24.572 [659494] <2> io_terminate_tape: writing empty backup header, drive index 16, copy 1
03:28:24.572 [659494] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.8627) on drive index 16
03:28:24.721 [737806] <2> io_write_back_header: drive index 8, empty_file, file num = 7, mpx_headers = 0, copy 1
03:28:24.729 [737806] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_ngbss_mast_svrhcart2TLD0018, from bptm.c.8745
03:28:25.793 [659494] <2> io_write_back_header: drive index 16, empty_file, file num = 29, mpx_headers = 0, copy 1
03:28:25.803 [659494] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_ngbss_mast_svrhcart2TLD0012, from bptm.c.8745
03:28:26.539 [647406] <2> io_ioctl: command (11)MTFSF 1 from (bptm.c.8904) on drive index 17
03:28:26.551 [647406] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_ngbss_mast_svrhcart2TLD00117, from bptm.c.8910
03:28:26.555 [647406] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from io_terminate_tape)
03:28:26.583 [647406] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2043: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
03:28:26.583 [647406] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2057: service: bpdbm
03:28:26.661 [647406] <2> logconnections: BPDBM CONNECT FROM 192.168.15.1.38795 TO 192.168.9.19.13724
03:28:27.008 [737806] <2> io_terminate_tape: absolute block position prior to writing empty header is 326674, copy 1
03:28:27.008 [737806] <2> io_terminate_tape: block position check: actual 326674, expected 326674
03:28:27.008 [737806] <2> send_MDS_msg: MEDIADB 1 60928 A00252 4000240 *NULL* 14 1259866817 1260472812 1261682412 0 69293984 5 5 1 2
3 0 0 1024 0 326674 0