cancel
Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
Showing results for 
Search instead for 
Did you mean: 
Veritas.com
Support

RMAN Backup Fails - Failed to process backup file

Jamba1
Level 3

‎07-06-2015 05:30 PM

Hi,

Version - 7.5.0.6

Master Server -  Microsoft Windows Server 2008 R2 Enterprise Version 6.1.7601 Service Pack 1 Build 7601

Media Servers - Microsoft Windows Server 2008 R2 Enterprise Version 6.1.7601 Service Pack 1 Build 7601

Client/Host (NBagent 7.1) -  Oracle Solaris 10 9/10 s10s_u9wos_14a SPARC

Database - Oracle Enterprise Edition 11GR2

Master and Media Server - Client Read Timeout = 9600

                                         - Client Connect Timeout = 9600

 Client/Host - Client_Read_Timeout = 10800

                      List_Files_Timeout = 9600
 

Occasionally our RMAN backups fail mainly due to the following:

 

ORA-19511: Error received from media manager layer, error text:

Failed to process backup file <bk_74594_1_884027536>

ORA-19502: write error on file "bk_74594_1_884027536", blockno 6006785 (blocksize=512)

ORA-27030: skgfwrt: sbtwrite2 returned error

ORA-19511: Error received from media manager layer, error text:

VxBSASendData: Failed with error:

 

Below is pretty much what I see in the error logs during the time of fail.

Media Server

 

BPBRM Media Server logs

18:56:32.441 [11388.5988] <2> put_short: (10) network write() error: An established connection was aborted by the software in your host machine. ; socket = 700
18:56:32.441 [11388.5988] <2> bpcr_disconnect_rqst: bpcr protocol error - couldn't send request type
18:56:32.441 [11388.5988] <2> verify_client: bpbrm.c.38245: bpcr_disconnect_rqst failed: -1 4294967295 0xffffffff
18:56:32.441 [11388.5988] <2> bpbrm read_filelist: reading filelist.
18:56:32.441 [11388.5988] <2> bpbrm read_filelist: filepath from bpsched: FILEPATH orasperprod_1436172988 /bk_20772_1_884372179


19:03:06.675 [10464.11112] <2> bpbrm read_media_msg: read from media manager: WROTE orasperprod_1436172988 400384 0 67190.363 0
19:03:06.675 [10464.11112] <2> bpbrm send_parent_msg: WROTE orasperprod_1436172988 400384 0 67190.363 0
19:03:06.675 [10464.11112] <2> put_strlen_str: cannot write data to network:  An existing connection was forcibly closed by the remote host.
19:03:06.675 [10464.11112] <16> bpbrm send_parent_msg: could not write WROTE orasperprod_1436172988 400384 0 67190.363 0 message to OUTSOCK
19:03:06.675 [10464.11112] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbmaster, query type 1
19:03:06.675 [10464.11112] <2> vnet_pbxConnect: pbxConnectEx Succeeded
19:03:06.675 [10464.11112] <2> logconnections: BPDBM CONNECT FROM 10.46.2.13.63996 TO 10.46.2.10.1556 fd = 712
19:03:06.675 [10464.11112] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
19:03:06.738 [10464.11112] <2> db_end: Need to collect reply
19:03:08.377 [7064.9292] <2> bpbrm handle_backup: client orasperprod EXIT STATUS = 6: the backup failed to back up the requested files
19:03:08.377 [7064.9292] <2> bpbrm handle_backup: client orasperprod EXIT STATUS = 6: the backup failed to back up the requested files
19:03:08.580 [7064.9292] <2> job_monitoring_exex: ACK disconnect
19:03:08.580 [7064.9292] <2> job_disconnect: Disconnected
19:03:08.798 [10464.11112] <2> bpbrm brm_child_done: child done, status 6
19:03:08.798 [10464.11112] <2> bpbrm brm_child_done: child 7064 exited with status 6: the backup failed to back up the requested files
19:03:08.798 [10464.11112] <2> bpbrm send_status_to_parent: bpbrm child is done, but the media manager child is not.
19:03:08.798 [10464.11112] <2> bpbrm tell_mm: sending media manager msg: STOP BACKUP orasperprod_1436170841
19:03:08.939 [11388.5988] <2> bpbrm handle_backup: client orasperprod EXIT STATUS = 6: the backup failed to back up the requested files
19:03:08.939 [11388.5988] <2> bpbrm handle_backup: client orasperprod EXIT STATUS = 6: the backup failed to back up the requested files
19:03:09.157 [11388.5988] <2> job_monitoring_exex: ACK disconnect
19:03:09.157 [11388.5988] <2> job_disconnect: Disconnected
19:03:15.229 [11932.9952] <16> bpbrm main: from client orasperprod: ERR - Script exited with status = 1 <the requested operation was partially successful>
19:03:15.229 [11932.9952] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbmaster, query type 1
19:03:15.229 [11932.9952] <2> vnet_pbxConnect: pbxConnectEx Succeeded
19:03:15.229 [11932.9952] <2> logconnections: BPDBM CONNECT FROM 10.46.2.13.63998 TO 10.46.2.10.1556 fd = 632
19:03:15.229 [11932.9952] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
19:03:15.276 [11932.9952] <2> db_end: Need to collect reply
19:03:48.460 [10464.11112] <2> bpbrm read_media_msg: read from media manager: ERROR 150
19:03:48.460 [10464.11112] <2> bpbrm send_parent_msg: ERROR 150
19:03:48.460 [10464.11112] <2> put_strlen_str: cannot write data to network:  An existing connection was forcibly closed by the remote host.
19:03:48.460 [10464.11112] <16> bpbrm send_parent_msg: could not write ERROR 150 message to OUTSOCK
19:03:48.460 [10464.11112] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbmaster, query type 1
19:03:48.460 [10464.11112] <2> vnet_pbxConnect: pbxConnectEx Succeeded
19:03:48.460 [10464.11112] <2> logconnections: BPDBM CONNECT FROM 10.46.2.13.64028 TO 10.46.2.10.1556 fd = 364
19:03:48.460 [10464.11112] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
19:03:48.507 [10464.11112] <2> db_end: Need to collect reply
19:03:48.507 [10464.11112] <2> bpbrm process_media_msg: got ERROR 150 from media manager
19:03:48.507 [10464.11112] <2> bpbrm kill_bpbrm_child: terminating bpbrm child 11388 jobid=1568504
19:03:48.507 [10464.11112] <2> bpbrm signal_bpbrm_child: sending Terminate to bpbrm child 11388
19:03:48.507 [10464.11112] <2> bpbrm signal_bpbrm_child: bpbrm child process 11388 already done.
19:03:48.507 [10464.11112] <2> put_strlen_str: cannot write data to network:  An existing connection was forcibly closed by the remote host.
19:03:48.507 [10464.11112] <2> bpbrm send_status_to_parent: EXIT orasperprod_1436170841 6 sent to parent process for jobid = 1568418.
19:03:48.507 [10464.11112] <2> bpbrm brm_child_done: child done, status 6
19:03:48.507 [10464.11112] <2> bpbrm brm_child_done: child 11388 exited with status 6: the backup failed to back up the requested files
19:03:48.507 [10464.11112] <2> put_strlen_str: cannot write data to network:  An existing connection was forcibly closed by the remote host.
19:03:48.507 [10464.11112] <2> bpbrm send_status_to_parent: EXIT orasperprod_1436172988 150 sent to parent process for jobid = 1568504.
19:03:48.507 [10464.11112] <2> put_strlen_str: cannot write data to network:  An existing connection was forcibly closed by the remote host.
19:03:48.507 [10464.11112] <2> bpbrm Exit: ERROR 150 sent to parent process
19:03:48.507 [10464.11112] <8> vnet_close_socket_safely: [vnet.c:2017] error on read EOF 0 0x0
19:03:48.507 [10464.11112] <2> bpbrm Exit: Error occured during closure of socket to nbjm, vnet status 9
19:03:48.928 [10464.11112] <2> job_monitoring_exex: ACK disconnect
19:03:48.928 [10464.11112] <2> job_disconnect: Disconnected

 

BPTM Media Server logs

 

18:58:17.106 [12020.7796] <2> parse_resource_strings: MEDIADB 1 3023127 J01842 4000951 ------ 14 1436171352 0 0 0 0 0 0 11 8 0 0 0 0 0 0
18:58:17.106 [12020.7796] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
18:58:17.106 [12020.7796] <2> parse_resource_strings: VOLUME 1 J01842 4000951 J01842L5 ENCR_7years HP 1041477348 14 8 0 62 0 {00000000-0000-0000-0000-000000000000} 0
18:58:17.106 [12020.7796] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
18:58:17.106 [12020.7796] <2> parse_resource_strings: DRIVE 3 HP.ULTRIUM5-SCSI.001 2000035 HUE510195F {2,0,5,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
18:58:17.106 [12020.7796] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
18:58:17.106 [12020.7796] <2> parse_resource_strings: STORAGE 1 LTO5-CBD-4_Drives 14 25600 2 1 0 0 BAKNB3 BAKNB3 *NULL*
18:58:17.106 [12020.7796] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
18:58:17.106 [12020.7796] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
18:58:17.106 [12020.7796] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
18:58:17.106 [12020.7796] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
18:58:17.106 [12020.7796] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
18:58:17.106 [12020.7796] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
18:58:17.106 [12020.7796] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
18:58:17.106 [12020.7796] <2> nbjm_media_request: Job control returned to BPTM
18:58:17.106 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:17.106 [12020.7796] <2> drivename_checklock: Called
18:58:17.106 [12020.7796] <2> drivename_checklock: File is locked
18:58:17.106 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:17.106 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:18.120 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:18.120 [12020.7796] <2> drivename_checklock: Called
18:58:18.120 [12020.7796] <2> drivename_checklock: File is locked
18:58:18.120 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:18.120 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:19.134 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:19.134 [12020.7796] <2> drivename_checklock: Called
18:58:19.134 [12020.7796] <2> drivename_checklock: File is locked
18:58:19.134 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:19.134 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:20.148 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:20.148 [12020.7796] <2> drivename_checklock: Called
18:58:20.148 [12020.7796] <2> drivename_checklock: File is locked
18:58:20.148 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:20.148 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:21.162 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:21.162 [12020.7796] <2> drivename_checklock: Called
18:58:21.162 [12020.7796] <2> drivename_checklock: File is locked
18:58:21.162 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:21.162 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:22.176 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:22.176 [12020.7796] <2> drivename_checklock: Called
18:58:22.176 [12020.7796] <2> drivename_checklock: File is locked
18:58:22.176 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:22.176 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:23.190 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:23.190 [12020.7796] <2> drivename_checklock: Called
18:58:23.190 [12020.7796] <2> drivename_checklock: File is locked
18:58:23.190 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:23.190 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:24.204 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:24.204 [12020.7796] <2> drivename_checklock: Called
18:58:24.204 [12020.7796] <2> drivename_checklock: File is locked
18:58:24.204 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:24.204 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:25.218 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:25.218 [12020.7796] <2> drivename_checklock: Called
18:58:25.218 [12020.7796] <2> drivename_checklock: File is locked
18:58:25.218 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:25.218 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:26.232 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:26.232 [12020.7796] <2> drivename_checklock: Called
18:58:26.232 [12020.7796] <2> drivename_checklock: File is locked
18:58:26.232 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:26.232 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:27.247 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:27.247 [12020.7796] <2> drivename_checklock: Called
18:58:27.247 [12020.7796] <2> drivename_checklock: File is locked
18:58:27.247 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:27.247 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:28.261 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:28.261 [12020.7796] <2> drivename_checklock: Called
18:58:28.261 [12020.7796] <2> drivename_checklock: File is locked
18:58:28.261 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:28.261 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:29.275 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:29.275 [12020.7796] <2> drivename_checklock: Called
18:58:29.275 [12020.7796] <2> drivename_checklock: File is locked
18:58:29.275 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:29.275 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:30.289 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:30.289 [12020.7796] <2> drivename_checklock: Called
18:58:30.289 [12020.7796] <2> drivename_checklock: File is locked
18:58:30.289 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:30.289 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:31.303 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:31.303 [12020.7796] <2> drivename_checklock: Called
18:58:31.303 [12020.7796] <2> drivename_checklock: File is locked
18:58:31.303 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:31.303 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:32.317 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:32.317 [12020.7796] <2> drivename_checklock: Called
18:58:32.317 [12020.7796] <2> drivename_checklock: File is locked
18:58:32.317 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:32.317 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:33.331 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:33.331 [12020.7796] <2> drivename_checklock: Called
18:58:33.331 [12020.7796] <2> drivename_checklock: File is locked
18:58:33.331 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:33.331 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:34.345 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:34.345 [12020.7796] <2> drivename_checklock: Called
18:58:34.345 [12020.7796] <2> drivename_checklock: File is locked
18:58:34.345 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:34.345 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:35.359 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:35.359 [12020.7796] <2> drivename_checklock: Called
18:58:35.359 [12020.7796] <2> drivename_checklock: File is locked
18:58:35.359 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:35.359 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:36.373 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:36.373 [12020.7796] <2> drivename_checklock: Called
18:58:36.373 [12020.7796] <2> drivename_checklock: File is locked
18:58:36.373 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:36.373 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:37.387 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:37.387 [12020.7796] <2> drivename_checklock: Called
18:58:37.387 [12020.7796] <2> drivename_checklock: File is locked
18:58:37.387 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:37.387 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:38.401 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:38.401 [12020.7796] <2> drivename_checklock: Called
18:58:38.401 [12020.7796] <2> drivename_checklock: File is locked
18:58:38.401 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:38.401 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:39.415 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:39.415 [12020.7796] <2> drivename_checklock: Called
18:58:39.415 [12020.7796] <2> drivename_checklock: File is locked
18:58:39.415 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:39.415 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:40.429 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:40.429 [12020.7796] <2> drivename_checklock: Called
18:58:40.429 [12020.7796] <2> drivename_checklock: File is locked
18:58:40.429 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:40.429 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:41.443 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:41.443 [12020.7796] <2> drivename_checklock: Called
18:58:41.443 [12020.7796] <2> drivename_checklock: File is locked
18:58:41.443 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:41.443 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:42.457 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:42.457 [12020.7796] <2> drivename_checklock: Called
18:58:42.457 [12020.7796] <2> drivename_checklock: File is locked
18:58:42.457 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:42.457 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:43.471 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:43.471 [12020.7796] <2> drivename_checklock: Called
18:58:43.471 [12020.7796] <2> drivename_checklock: File is locked
18:58:43.471 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:43.471 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:44.485 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:44.485 [12020.7796] <2> drivename_checklock: Called
18:58:44.485 [12020.7796] <2> drivename_checklock: File is locked
18:58:44.485 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:44.485 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:45.499 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:45.499 [12020.7796] <2> drivename_checklock: Called
18:58:45.499 [12020.7796] <2> drivename_checklock: File is locked
18:58:45.499 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:45.499 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:46.513 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:46.513 [12020.7796] <2> drivename_checklock: Called
18:58:46.513 [12020.7796] <2> drivename_checklock: File is locked
18:58:46.513 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:46.513 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:47.527 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:47.527 [12020.7796] <2> drivename_checklock: Called
18:58:47.527 [12020.7796] <2> drivename_checklock: File is locked
18:58:47.527 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:47.527 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:48.541 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:48.541 [12020.7796] <2> drivename_checklock: Called
18:58:48.541 [12020.7796] <2> drivename_checklock: File is locked
18:58:48.541 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:48.541 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:49.556 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:49.556 [12020.7796] <2> drivename_checklock: Called
18:58:49.556 [12020.7796] <2> drivename_checklock: File is locked
18:58:49.556 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:49.556 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:50.570 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:50.570 [12020.7796] <2> drivename_checklock: Called
18:58:50.570 [12020.7796] <2> drivename_checklock: File is locked
18:58:50.570 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:50.570 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:51.584 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:51.584 [12020.7796] <2> drivename_checklock: Called
18:58:51.584 [12020.7796] <2> drivename_checklock: File is locked
18:58:51.584 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:51.584 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:52.598 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:52.598 [12020.7796] <2> drivename_checklock: Called
18:58:52.598 [12020.7796] <2> drivename_checklock: File is locked
18:58:52.598 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:52.598 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:53.612 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:53.612 [12020.7796] <2> drivename_checklock: Called
18:58:53.612 [12020.7796] <2> drivename_checklock: File is locked
18:58:53.612 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:53.612 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:54.626 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:54.626 [12020.7796] <2> drivename_checklock: Called
18:58:54.626 [12020.7796] <2> drivename_checklock: File is locked
18:58:54.626 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:54.626 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:55.640 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:55.640 [12020.7796] <2> drivename_checklock: Called
18:58:55.640 [12020.7796] <2> drivename_checklock: File is locked
18:58:55.640 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:55.640 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:56.654 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:56.654 [12020.7796] <2> drivename_checklock: Called
18:58:56.654 [12020.7796] <2> drivename_checklock: File is locked
18:58:56.654 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:56.654 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:57.668 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:57.668 [12020.7796] <2> drivename_checklock: Called
18:58:57.668 [12020.7796] <2> drivename_checklock: File is locked
18:58:57.668 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:57.668 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:58.682 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:58.682 [12020.7796] <2> drivename_checklock: Called
18:58:58.682 [12020.7796] <2> drivename_checklock: File is locked
18:58:58.682 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:58.682 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:58:59.696 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:58:59.696 [12020.7796] <2> drivename_checklock: Called
18:58:59.696 [12020.7796] <2> drivename_checklock: File is locked
18:58:59.696 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:58:59.696 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:00.710 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:00.710 [12020.7796] <2> drivename_checklock: Called
18:59:00.710 [12020.7796] <2> drivename_checklock: File is locked
18:59:00.710 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:00.710 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:01.724 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:01.724 [12020.7796] <2> drivename_checklock: Called
18:59:01.724 [12020.7796] <2> drivename_checklock: File is locked
18:59:01.724 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:01.724 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:02.738 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:02.738 [12020.7796] <2> drivename_checklock: Called
18:59:02.738 [12020.7796] <2> drivename_checklock: File is locked
18:59:02.738 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:02.738 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:03.752 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:03.752 [12020.7796] <2> drivename_checklock: Called
18:59:03.752 [12020.7796] <2> drivename_checklock: File is locked
18:59:03.752 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:03.752 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:04.766 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:04.766 [12020.7796] <2> drivename_checklock: Called
18:59:04.766 [12020.7796] <2> drivename_checklock: File is locked
18:59:04.766 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:04.766 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:05.780 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:05.780 [12020.7796] <2> drivename_checklock: Called
18:59:05.780 [12020.7796] <2> drivename_checklock: File is locked
18:59:05.780 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:05.780 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:06.794 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:06.794 [12020.7796] <2> drivename_checklock: Called
18:59:06.794 [12020.7796] <2> drivename_checklock: File is locked
18:59:06.794 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:06.794 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:07.808 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:07.808 [12020.7796] <2> drivename_checklock: Called
18:59:07.808 [12020.7796] <2> drivename_checklock: File is locked
18:59:07.808 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:07.808 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:08.822 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:08.822 [12020.7796] <2> drivename_checklock: Called
18:59:08.822 [12020.7796] <2> drivename_checklock: File is locked
18:59:08.822 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:08.822 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:09.836 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:09.836 [12020.7796] <2> drivename_checklock: Called
18:59:09.836 [12020.7796] <2> drivename_checklock: File is locked
18:59:09.836 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:09.836 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:10.850 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:10.850 [12020.7796] <2> drivename_checklock: Called
18:59:10.850 [12020.7796] <2> drivename_checklock: File is locked
18:59:10.850 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:10.850 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:11.865 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:11.865 [12020.7796] <2> drivename_checklock: Called
18:59:11.865 [12020.7796] <2> drivename_checklock: File is locked
18:59:11.865 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:11.865 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:12.879 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:12.879 [12020.7796] <2> drivename_checklock: Called
18:59:12.879 [12020.7796] <2> drivename_checklock: File is locked
18:59:12.879 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:12.879 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:13.893 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:13.893 [12020.7796] <2> drivename_checklock: Called
18:59:13.893 [12020.7796] <2> drivename_checklock: File is locked
18:59:13.893 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:13.893 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:14.907 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:14.907 [12020.7796] <2> drivename_checklock: Called
18:59:14.907 [12020.7796] <2> drivename_checklock: File is locked
18:59:14.907 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:14.907 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:15.921 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:15.921 [12020.7796] <2> drivename_checklock: Called
18:59:15.921 [12020.7796] <2> drivename_checklock: File is locked
18:59:15.921 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:15.921 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:16.935 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:16.935 [12020.7796] <2> drivename_checklock: Called
18:59:16.935 [12020.7796] <2> drivename_checklock: File is locked
18:59:16.935 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:16.935 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:17.949 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:17.949 [12020.7796] <2> drivename_checklock: Called
18:59:17.949 [12020.7796] <2> drivename_checklock: File is locked
18:59:17.949 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:17.949 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:18.963 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:18.963 [12020.7796] <2> drivename_checklock: Called
18:59:18.963 [12020.7796] <2> drivename_checklock: File is locked
18:59:18.963 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:18.963 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:23.971 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:23.971 [12020.7796] <2> drivename_checklock: Called
18:59:23.971 [12020.7796] <2> drivename_checklock: File is locked
18:59:23.971 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:23.971 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:28.978 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:28.978 [12020.7796] <2> drivename_checklock: Called
18:59:28.978 [12020.7796] <2> drivename_checklock: File is locked
18:59:28.978 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:28.978 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:33.986 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:33.986 [12020.7796] <2> drivename_checklock: Called
18:59:33.986 [12020.7796] <2> drivename_checklock: File is locked
18:59:33.986 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:33.986 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:38.994 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:38.994 [12020.7796] <2> drivename_checklock: Called
18:59:38.994 [12020.7796] <2> drivename_checklock: File is locked
18:59:38.994 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:38.994 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:44.002 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:44.002 [12020.7796] <2> drivename_checklock: Called
18:59:44.002 [12020.7796] <2> drivename_checklock: File is locked
18:59:44.002 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:44.002 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:49.010 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:49.010 [12020.7796] <2> drivename_checklock: Called
18:59:49.010 [12020.7796] <2> drivename_checklock: File is locked
18:59:49.010 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:49.010 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:54.018 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:54.018 [12020.7796] <2> drivename_checklock: Called
18:59:54.018 [12020.7796] <2> drivename_checklock: File is locked
18:59:54.018 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:54.018 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
18:59:59.025 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
18:59:59.025 [12020.7796] <2> drivename_checklock: Called
18:59:59.025 [12020.7796] <2> drivename_checklock: File is locked
18:59:59.025 [12020.7796] <2> drivename_lock: lock failed (already locked)
18:59:59.025 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:00:04.033 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:00:04.033 [12020.7796] <2> drivename_checklock: Called
19:00:04.033 [12020.7796] <2> drivename_checklock: File is locked
19:00:04.033 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:00:04.033 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:00:09.041 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:00:09.041 [12020.7796] <2> drivename_checklock: Called
19:00:09.041 [12020.7796] <2> drivename_checklock: File is locked
19:00:09.041 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:00:09.041 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:00:14.049 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:00:14.049 [12020.7796] <2> drivename_checklock: Called
19:00:14.049 [12020.7796] <2> drivename_checklock: File is locked
19:00:14.049 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:00:14.049 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:00:19.057 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:00:19.057 [12020.7796] <2> drivename_checklock: Called
19:00:19.057 [12020.7796] <2> drivename_checklock: File is locked
19:00:19.057 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:00:19.057 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:00:24.065 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:00:24.065 [12020.7796] <2> drivename_checklock: Called
19:00:24.065 [12020.7796] <2> drivename_checklock: File is locked
19:00:24.065 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:00:24.065 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:00:29.072 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:00:29.072 [12020.7796] <2> drivename_checklock: Called
19:00:29.072 [12020.7796] <2> drivename_checklock: File is locked
19:00:29.072 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:00:29.072 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:00:34.080 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:00:34.080 [12020.7796] <2> drivename_checklock: Called
19:00:34.080 [12020.7796] <2> drivename_checklock: File is locked
19:00:34.080 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:00:34.080 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:00:39.088 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:00:39.088 [12020.7796] <2> drivename_checklock: Called
19:00:39.088 [12020.7796] <2> drivename_checklock: File is locked
19:00:39.088 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:00:39.088 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:00:44.096 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:00:44.096 [12020.7796] <2> drivename_checklock: Called
19:00:44.096 [12020.7796] <2> drivename_checklock: File is locked
19:00:44.096 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:00:44.096 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:00:49.104 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:00:49.104 [12020.7796] <2> drivename_checklock: Called
19:00:49.104 [12020.7796] <2> drivename_checklock: File is locked
19:00:49.104 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:00:49.104 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:00:54.111 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:00:54.111 [12020.7796] <2> drivename_checklock: Called
19:00:54.111 [12020.7796] <2> drivename_checklock: File is locked
19:00:54.111 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:00:54.111 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:00:57.232 [9948.6448] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -6
19:00:57.232 [9948.6448] <2> io_ioctl: command (0)MTWEOF 1 0x81 from (bptm.c.20166) on drive index 1
19:00:57.232 [9948.6448] <2> write_backup: maximum fragment size written copy 1 --- Fragmenting
19:00:57.232 [9948.6448] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbmaster, query type 1
19:00:57.247 [9948.6448] <2> vnet_pbxConnect: pbxConnectEx Succeeded
19:00:57.247 [9948.6448] <2> logconnections: BPDBM CONNECT FROM 10.46.2.13.63895 TO 10.46.2.10.1556 fd = 992
19:00:57.247 [9948.6448] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
19:00:57.294 [9948.6448] <2> db_end: Need to collect reply
19:00:57.294 [9948.6448] <4> report_throughput: VBRT 1 9948 5 1 HP.ULTRIUM5-SCSI.001 J01842 2 2 0 1 5856256 19743744  25600000 (bptm.c.20627)
19:00:57.294 [9948.6448] <2> process_brm_msg: no pending message from bpbrm
19:00:57.294 [9948.6448] <4> write_backup: waiting for client data or brm message
19:00:57.294 [9948.6448] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 0 delay_brm: 0
19:00:57.294 [9948.6448] <2> write_data: Total Kbytes transferred 490485695
19:00:57.310 [9948.6448] <2> write_data: absolute block position prior to writing backup header(s) is 174428, copy 1
19:00:57.310 [9948.6448] <2> write_data: block position check: actual 174428, expected 174428
19:00:57.310 [9948.6448] <2> io_write_back_header: drive index 1, orasperprod_1436170841, file num = 6, mpx_headers = 2, copy 1
19:00:57.310 [9948.6448] <2> io_write_back_header: encryption status: nexus scope 0, key scope 0
19:00:57.310 [9948.6448] <2> io_write_back_header: encryp mode 0x0, decryp mode 0x0, algorithm index 0, key instance 0
19:00:57.325 [9948.6448] <2> io_write_back_header: drive index 1, orasperprod_1436172988, file num = 6, mpx_headers = 1, copy 1
19:00:57.325 [9948.6448] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1
19:00:57.325 [9948.6448] <2> KMSCLIB::kmsDecryptKey: Entering function....(KMSClib.cpp:699)
19:00:57.325 [9948.6448] <2> KMSCLIB::kmsTransformKey: Entering function....(KMSClib.cpp:357)
19:00:57.325 [9948.6448] <2> manage_drive_encryption: encryption status: nexus scope 1, key scope 1
19:00:57.325 [9948.6448] <2> manage_drive_encryption: encryp mode 0x2, decryp mode 0x0, algorithm index 1, key instance 59
19:00:57.325 [9948.6448] <2> manage_drive_encryption: Kad type 0x0, Kad length 32 Kad [359c657e8f688a4b0abb46db4e0760e362014bbb092c4fdbbdabe23a19de3a6f]
19:00:57.325 [9948.6448] <2> write_data: first write, twin_index: 0 cindex: 1 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0
19:00:57.325 [9948.6448] <2> write_data: received first buffer (524288 bytes), begin writing data
19:00:59.119 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:00:59.119 [12020.7796] <2> drivename_checklock: Called
19:00:59.119 [12020.7796] <2> drivename_checklock: File is locked
19:00:59.119 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:00:59.119 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:01:04.127 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:01:04.127 [12020.7796] <2> drivename_checklock: Called
19:01:04.127 [12020.7796] <2> drivename_checklock: File is locked
19:01:04.127 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:01:04.127 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:01:09.135 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:01:09.135 [12020.7796] <2> drivename_checklock: Called
19:01:09.135 [12020.7796] <2> drivename_checklock: File is locked
19:01:09.135 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:01:09.135 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:01:14.143 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:01:14.143 [12020.7796] <2> drivename_checklock: Called
19:01:14.143 [12020.7796] <2> drivename_checklock: File is locked
19:01:14.143 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:01:14.143 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:01:19.151 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:01:19.151 [12020.7796] <2> drivename_checklock: Called
19:01:19.151 [12020.7796] <2> drivename_checklock: File is locked
19:01:19.151 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:01:19.151 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:01:24.158 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:01:24.158 [12020.7796] <2> drivename_checklock: Called
19:01:24.158 [12020.7796] <2> drivename_checklock: File is locked
19:01:24.158 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:01:24.158 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:01:29.166 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:01:29.166 [12020.7796] <2> drivename_checklock: Called
19:01:29.166 [12020.7796] <2> drivename_checklock: File is locked
19:01:29.166 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:01:29.166 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:01:34.174 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:01:34.174 [12020.7796] <2> drivename_checklock: Called
19:01:34.174 [12020.7796] <2> drivename_checklock: File is locked
19:01:34.174 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:01:34.174 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:01:39.182 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:01:39.182 [12020.7796] <2> drivename_checklock: Called
19:01:39.182 [12020.7796] <2> drivename_checklock: File is locked
19:01:39.182 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:01:39.182 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:01:44.190 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:01:44.190 [12020.7796] <2> drivename_checklock: Called
19:01:44.190 [12020.7796] <2> drivename_checklock: File is locked
19:01:44.190 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:01:44.190 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:01:49.198 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:01:49.198 [12020.7796] <2> drivename_checklock: Called
19:01:49.198 [12020.7796] <2> drivename_checklock: File is locked
19:01:49.198 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:01:49.198 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:01:54.205 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:01:54.205 [12020.7796] <2> drivename_checklock: Called
19:01:54.205 [12020.7796] <2> drivename_checklock: File is locked
19:01:54.205 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:01:54.205 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:01:59.213 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:01:59.213 [12020.7796] <2> drivename_checklock: Called
19:01:59.213 [12020.7796] <2> drivename_checklock: File is locked
19:01:59.213 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:01:59.213 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:02:04.221 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:02:04.221 [12020.7796] <2> drivename_checklock: Called
19:02:04.221 [12020.7796] <2> drivename_checklock: File is locked
19:02:04.221 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:02:04.221 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:02:09.229 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:02:09.229 [12020.7796] <2> drivename_checklock: Called
19:02:09.229 [12020.7796] <2> drivename_checklock: File is locked
19:02:09.229 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:02:09.229 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:02:14.237 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:02:14.237 [12020.7796] <2> drivename_checklock: Called
19:02:14.237 [12020.7796] <2> drivename_checklock: File is locked
19:02:14.237 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:02:14.237 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:02:19.245 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:02:19.245 [12020.7796] <2> drivename_checklock: Called
19:02:19.245 [12020.7796] <2> drivename_checklock: File is locked
19:02:19.245 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:02:19.245 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:02:24.252 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:02:24.252 [12020.7796] <2> drivename_checklock: Called
19:02:24.252 [12020.7796] <2> drivename_checklock: File is locked
19:02:24.252 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:02:24.252 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:02:29.260 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:02:29.260 [12020.7796] <2> drivename_checklock: Called
19:02:29.260 [12020.7796] <2> drivename_checklock: File is locked
19:02:29.260 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:02:29.260 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:02:34.268 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:02:34.268 [12020.7796] <2> drivename_checklock: Called
19:02:34.268 [12020.7796] <2> drivename_checklock: File is locked
19:02:34.268 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:02:34.268 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:02:39.276 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:02:39.276 [12020.7796] <2> drivename_checklock: Called
19:02:39.276 [12020.7796] <2> drivename_checklock: File is locked
19:02:39.276 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:02:39.276 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:02:44.284 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:02:44.284 [12020.7796] <2> drivename_checklock: Called
19:02:44.284 [12020.7796] <2> drivename_checklock: File is locked
19:02:44.284 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:02:44.284 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:02:49.291 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:02:49.291 [12020.7796] <2> drivename_checklock: Called
19:02:49.291 [12020.7796] <2> drivename_checklock: File is locked
19:02:49.291 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:02:49.291 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:02:54.299 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:02:54.299 [12020.7796] <2> drivename_checklock: Called
19:02:54.299 [12020.7796] <2> drivename_checklock: File is locked
19:02:54.299 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:02:54.299 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:02:59.308 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:02:59.308 [12020.7796] <2> drivename_checklock: Called
19:02:59.308 [12020.7796] <2> drivename_checklock: File is locked
19:02:59.308 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:02:59.308 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:03:04.318 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:03:04.318 [12020.7796] <2> drivename_checklock: Called
19:03:04.318 [12020.7796] <2> drivename_checklock: File is locked
19:03:04.318 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:03:04.318 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:03:06.051 [9648.10752] <2> bptm: INITIATING (VERBOSE = 0): -rptdrv -jobid -1435902526 -jm
19:03:06.067 [9648.10752] <2> drivename_open: Called with Create 0, file HP.ULTRIUM5-SCSI.001
19:03:06.067 [9648.10752] <2> drivename_checklock: Called
19:03:06.067 [9648.10752] <2> drivename_checklock: File is locked
19:03:06.067 [9648.10752] <2> report_drives: DRIVE = HP.ULTRIUM5-SCSI.001 LOCK = TRUE CURTIME = 1436173386
19:03:06.067 [9648.10752] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:03:06.067 [9648.10752] <2> report_drives: MODE = 0
19:03:06.067 [9648.10752] <2> report_drives: TIME = 1436171355
19:03:06.067 [9648.10752] <2> report_drives: MASTER = nbmaster
19:03:06.067 [9648.10752] <2> report_drives: SR_KEY = 0 1
19:03:06.067 [9648.10752] <2> report_drives: PATH = {2,0,5,0}
19:03:06.067 [9648.10752] <2> report_drives: MEDIA = J01842
19:03:06.067 [9648.10752] <2> report_drives: REQID = -1435902260
19:03:06.067 [9648.10752] <2> report_drives: ALOCID = 3023127
19:03:06.067 [9648.10752] <2> report_drives: RBID = {9FC7669F-1706-4516-B51A-AF4923B68A04}
19:03:06.067 [9648.10752] <2> report_drives: PID = 9948
19:03:06.067 [9648.10752] <2> report_drives: FILE = D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM5-SCSI.001
19:03:06.067 [9648.10752] <2> main: Sending [EXIT STATUS 0] to NBJM
19:03:06.067 [9648.10752] <2> bptm: EXITING with status 0 <----------
19:03:08.377 [9948.6448] <2> mm_check_child_write: Received Terminate Event
19:03:08.408 [9948.6448] <2> io_terminate_tape: writing empty backup header, drive index 1, copy 1
19:03:08.408 [9948.6448] <2> io_terminate_tape: reposition to previous tapemark and rewrite header
19:03:08.408 [9948.6448] <2> io_ioctl: command (2)MTBSF 1 0x0 from (bptm.c.8770) on drive index 1
19:03:09.329 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:03:09.329 [12020.7796] <2> drivename_checklock: Called
19:03:09.329 [12020.7796] <2> drivename_checklock: File is locked
19:03:09.329 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:03:09.329 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:03:14.339 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:03:14.339 [12020.7796] <2> drivename_checklock: Called
19:03:14.339 [12020.7796] <2> drivename_checklock: File is locked
19:03:14.339 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:03:14.339 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:03:19.350 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:03:19.350 [12020.7796] <2> drivename_checklock: Called
19:03:19.350 [12020.7796] <2> drivename_checklock: File is locked
19:03:19.350 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:03:19.350 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:03:24.360 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:03:24.360 [12020.7796] <2> drivename_checklock: Called
19:03:24.360 [12020.7796] <2> drivename_checklock: File is locked
19:03:24.360 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:03:24.360 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:03:29.370 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:03:29.370 [12020.7796] <2> drivename_checklock: Called
19:03:29.370 [12020.7796] <2> drivename_checklock: File is locked
19:03:29.370 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:03:29.370 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:03:34.381 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:03:34.381 [12020.7796] <2> drivename_checklock: Called
19:03:34.381 [12020.7796] <2> drivename_checklock: File is locked
19:03:34.381 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:03:34.381 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:03:36.098 [9948.6448] <2> io_ioctl: command (0)MTWEOF 1 0x1 from (bptm.c.8852) on drive index 1
19:03:39.391 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:03:39.391 [12020.7796] <2> drivename_checklock: Called
19:03:39.391 [12020.7796] <2> drivename_checklock: File is locked
19:03:39.391 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:03:39.391 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:03:43.106 [9948.6448] <2> io_terminate_tape: absolute block position prior to writing empty header is 174428, copy 1
19:03:43.106 [9948.6448] <2> io_write_back_header: drive index 1, empty_file, file num = 6, mpx_headers = 0, copy 1
19:03:43.122 [9948.6448] <2> io_write_back_header: encryption status: nexus scope 0, key scope 0
19:03:43.122 [9948.6448] <2> io_write_back_header: encryp mode 0x0, decryp mode 0x0, algorithm index 0, key instance 0
19:03:43.122 [9948.6448] <2> io_close: closing D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM5-SCSI.001, from bptm.c.8965
19:03:43.122 [9948.6448] <2> send_MDS_msg: MEDIADB 1 3023127 J01842 4000951 *NULL* 14 1436170841 1436172988 1656924988 0 89298541 5 5 11 8 0 8704 1024 0 174428 0
19:03:43.169 [9948.6448] <2> openTpreqFile: tpreq_file: D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM5-SCSI.001, serial_num: HUE510195F
19:03:43.169 [9948.6448] <2> get_drive_path: SCSI coordinates {2,0,5,0}, dos_path \\.\Tape5, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_5-scsi#5&d78263f&0&000500#{53f5630b-b6bf-11d0-94f2-00a0c91ef...}
19:03:43.169 [9948.6448] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,5,0}, dos_path \\.\Tape5, drive serial number HUE510195F, expected serial number HUE510195F
19:03:43.184 [9948.6448] <2> init_tape: \\.\Tape5 (SCSI coordinates {2,0,5,0}) configured with blocksize 0
19:03:43.247 [9948.6448] <2> init_tape: \\.\Tape5 (SCSI coordinates {2,0,5,0}) has compression enabled
19:03:43.247 [9948.6448] <2> io_open: SCSI RESERVE
19:03:43.247 [9948.6448] <2> io_open: file D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM5-SCSI.001 successfully opened (mode 2)
19:03:44.402 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:03:44.402 [12020.7796] <2> drivename_checklock: Called
19:03:44.402 [12020.7796] <2> drivename_checklock: File is locked
19:03:44.402 [12020.7796] <2> drivename_lock: lock failed (already locked)
19:03:44.402 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:03:48.054 [9948.6448] <2> io_terminate_tape: locate block positioned tape to 174428 in io_terminate_tape
19:03:48.070 [9948.6448] <2> io_close: closing D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM5-SCSI.001, from bptm.c.9148
19:03:48.070 [9948.6448] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from io_terminate_tape)
19:03:48.070 [9948.6448] <2> send_brm_msg: ERROR 150
19:03:48.070 [9948.6448] <2> mm_terminate: EXITING with status 150
19:03:48.070 [9948.6448] <2> cleanup: Detached from BPBRM shared memory
19:03:49.412 [12020.7796] <2> drivename_open: Called with Create 1, file HP.ULTRIUM5-SCSI.001
19:03:49.412 [12020.7796] <2> drivename_checklock: Called
19:03:49.412 [12020.7796] <2> drivename_lock: lock established
19:03:49.412 [12020.7796] <4> create_tpreq_file: {2,0,5,0}
19:03:49.412 [12020.7796] <2> drivename_write: Called with mode 2
19:03:49.412 [12020.7796] <2> drivename_unlock: unlocked
19:03:49.412 [12020.7796] <2> drivename_checklock: Called
19:03:49.412 [12020.7796] <2> drivename_lock: lock established
19:03:49.412 [12020.7796] <2> openNTDevice: config_path: {2,0,5,0}, serial_num: HUE510195F
19:03:49.412 [12020.7796] <2> get_drive_path: SCSI coordinates {2,0,5,0}, dos_path \\.\Tape5, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_5-scsi#5&d78263f&0&000500#{53f5630b-b6bf-11d0-94f2-00a0c91ef...}
19:03:49.428 [12020.7796] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,5,0}, dos_path \\.\Tape5, drive serial number HUE510195F, expected serial number HUE510195F
19:03:49.443 [12020.7796] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
19:03:49.443 [12020.7796] <2> really_tpunmount: tpunmount'ing D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM5-SCSI.001
19:03:49.646 [12020.7796] <2> tapelib: wait_for_ltid, UnMount, timeout 2400
19:06:19.021 [12020.7796] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbmaster, query type 1
19:06:19.021 [12020.7796] <2> vnet_pbxConnect: pbxConnectEx Succeeded
19:06:19.021 [12020.7796] <2> logconnections: BPDBM CONNECT FROM 10.46.2.13.64115 TO 10.46.2.10.1556 fd = 1184
19:06:19.021 [12020.7796] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
19:06:19.068 [12020.7796] <2> db_end: Need to collect reply
19:06:19.068 [12020.7796] <4> report_resource_done: VBRD 1 12020 0 HP.ULTRIUM5-SCSI.001 J01842
19:06:19.068 [12020.7796] <2> openNTDevice: config_path: {2,0,5,0}, serial_num: HUE510195F
19:06:19.068 [12020.7796] <2> get_drive_path: SCSI coordinates {2,0,5,0}, dos_path \\.\Tape5, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_5-scsi#5&d78263f&0&000500#{53f5630b-b6bf-11d0-94f2-00a0c91ef...}
19:06:19.084 [12020.7796] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,5,0}, dos_path \\.\Tape5, drive serial number HUE510195F, expected serial number HUE510195F
19:06:19.084 [12020.7796] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
19:06:19.099 [12020.7796] <2> tapealert_and_release: report_attr, fl1 0x00000001, fl2 0x00000000
19:06:19.115 [12020.7796] <2> tapealert_and_release: SCSI RELEASE
19:06:19.115 [12020.7796] <2> drivename_unlock: unlocked
19:06:19.115 [12020.7796] <2> drivename_close: Called for file HP.ULTRIUM5-SCSI.001
19:06:19.115 [12020.7796] <2> drivename_remove: Called
19:06:19.115 [12020.7796] <2> main: Sending [EXIT STATUS 0] to NBJM
19:06:19.115 [12020.7796] <2> bptm: EXITING with status 0 <----------

 


BPRD Master Server logs

 

18:43:35.973 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:44:08.528 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:44:40.959 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:45:13.484 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:45:47.927 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:46:20.592 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:46:53.023 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:47:25.454 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:47:57.885 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:48:13.999 [6688.2344] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbmaster, query type 98
18:48:14.014 [6688.2344] <2> logconnections: BPDBM CONNECT FROM 10.46.2.10.54457 TO 10.46.2.10.13721 fd = 592
18:48:14.014 [6688.2344] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
18:48:14.014 [6688.2344] <2> db_end: Need to collect reply
18:48:30.316 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:49:02.747 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:49:35.178 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:50:07.609 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:50:40.039 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:51:12.470 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:51:44.901 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:52:19.345 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:52:51.776 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:53:13.178 [6688.2344] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbmaster, query type 98
18:53:13.193 [6688.2344] <2> logconnections: BPDBM CONNECT FROM 10.46.2.10.54637 TO 10.46.2.10.13721 fd = 592
18:53:13.193 [6688.2344] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
18:53:13.193 [6688.2344] <2> db_end: Need to collect reply
18:53:24.238 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:53:56.669 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:54:29.271 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:55:01.702 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:55:34.133 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:56:06.564 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:56:39.182 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:57:11.676 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:57:44.106 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:58:13.355 [6688.2344] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbmaster, query type 98
18:58:13.355 [6688.2344] <2> logconnections: BPDBM CONNECT FROM 10.46.2.10.54727 TO 10.46.2.10.13721 fd = 680
18:58:13.355 [6688.2344] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
18:58:13.355 [6688.2344] <2> db_end: Need to collect reply
18:58:18.550 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:58:50.981 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:59:23.412 [3816.4596] <4> msgbackup: waiting for response from nbpem
18:59:55.843 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:00:28.273 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:01:00.704 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:01:33.135 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:02:05.566 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:02:37.997 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:03:10.428 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:03:13.548 [6688.2344] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbmaster, query type 98
19:03:13.548 [6688.2344] <2> logconnections: BPDBM CONNECT FROM 10.46.2.10.54873 TO 10.46.2.10.13721 fd = 596
19:03:13.548 [6688.2344] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
19:03:13.548 [6688.2344] <2> db_end: Need to collect reply
19:03:42.859 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:04:17.380 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:04:49.811 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:05:22.242 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:05:54.673 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:06:27.104 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:06:59.535 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:07:31.966 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:08:04.397 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:08:13.725 [6688.2344] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbmaster, query type 98
19:08:13.741 [6688.2344] <2> logconnections: BPDBM CONNECT FROM 10.46.2.10.54991 TO 10.46.2.10.13721 fd = 680
19:08:13.741 [6688.2344] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
19:08:13.741 [6688.2344] <2> db_end: Need to collect reply
19:08:36.828 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:09:09.259 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:09:41.690 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:10:14.121 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:10:48.564 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:11:20.995 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:11:53.426 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:12:25.857 [3816.4596] <4> msgbackup: waiting for response from nbpem
19:12:58.288 [3816.4596] <4> msgbackup: waiting for response from nbpem

 

dbclient log

 

19:03:07.881 [24244] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:07.932 [24243] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.041 [24243] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.051 [24244] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.078 [24244] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.120 [24244] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.147 [24244] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.156 [24243] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.186 [24244] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.272 [24243] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.381 [24243] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.421 [24244] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.448 [24244] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.477 [24244] <2> int_WriteData: INF - writing buffer # 104000 of size 262144
19:03:08.480 [24244] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.493 [24243] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.509 [24244] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.540 [24244] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.568 [24244] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.609 [24243] <4> dbc_put: INF - sending keepalive on NAME Socket
19:03:08.623 [24243] <16> writeToServer: ERR - send() to server on socket failed: Broken pipe (32)
19:03:08.623 [24243] <16> dbc_put: ERR - failed sending data to server
19:03:08.623 [24243] <4> closeApi: entering closeApi.
19:03:08.623 [24243] <4> closeApi: INF - EXIT STATUS 6: the backup failed to back up the requested files

19:03:08.623 [24243] <4> closeApi: INF - closing commSock 17
19:03:08.623 [24243] <4> closeApi: INF - close of commSock returned <0> errno is <32>
19:03:08.623 [24243] <4> closeApi: INF - closing dataSock 19
19:03:08.623 [24243] <4> closeApi: INF - close of dataSock returned <0> errno is <32>
19:03:08.623 [24243] <4> closeApi: INF - setting linger on nameSock 18
19:03:08.623 [24243] <4> closeApi: INF - closing nameSock 18
19:03:08.623 [24243] <4> closeApi: INF - close of nameSock returned <0> errno is <32>
19:03:08.624 [24243] <16> VxBSASendData: ERR - Could not do a bsa_put().
19:03:08.624 [24243] <2> xbsa_ProcessError: INF - entering
19:03:08.624 [24243] <2> xbsa_ProcessError: INF - leaving
19:03:08.624 [24243] <16> xbsa_SendData: ERR - VxBSASendData: Failed with error:
   Server Status:  Communication with the server has not been initiated or the server status has not been retrieved from the serve
19:03:08.624 [24243] <2> sbterror: INF - entering
19:03:08.624 [24243] <2> sbterror: INF - Error=7501: VxBSASendData: Failed with error:
   Server Status:  Communication with the server has not been initiated or the server status has not been retrieved from the serve.
19:03:08.624 [24243] <2> sbterror: INF - leaving
19:03:08.638 [24243] <2> sbtclose2: INF - entering
19:03:08.638 [24243] <2> int_CloseImage: INF - entering
19:03:08.639 [24243] <2> int_CloseImage: INF - Backup - closing <bk_20770_1_884370037>
19:03:08.639 [24243] <2> xbsa_EndData: INF - entering
19:03:08.639 [24243] <4> VxBSAEndData: INF - entering EndData.
19:03:08.639 [24243] <4> finishTarImage: INF - FractionalObjectBytes: 0
19:03:08.639 [24243] <4> finishTarImage: INF - writing LF_END_U_LEN_FILE record
19:03:08.639 [24243] <4> write_LF_END_tarHeader: entering write_LF_END_tarHeader.
19:03:08.639 [24243] <16> writeToServer: ERR - send() to server on socket failed: Bad file number (9)
19:03:08.639 [24243] <16> write_LF_END_tarHeader: ERR - failed writing LF_END_U_LEN_FILE record on DATA socket
19:03:08.639 [24243] <16> finishTarImage: ERR - write_LF_END_tarHeader() failed.
19:03:08.639 [24243] <16> VxBSAEndData: ERR - EndData unable to bsa_finishTarImage().
19:03:08.639 [24243] <2> xbsa_ProcessError: INF - entering
19:03:08.639 [24243] <2> xbsa_ProcessError: INF - leaving
19:03:08.639 [24243] <16> xbsa_EndData: ERR - VxBSAEndData: Failed with error:
   Server Status:  Communication with the server has not been initiated or the server status has not been retrieved from the serve
19:03:08.639 [24243] <2> xbsa_EndData: INF - leaving (3)

19:03:08.639 [24243] <16> int_CloseImage: ERR - Failed to process backup file <bk_20770_1_884370037>

19:03:08.639 [24243] <2> xbsa_EndTransaction: INF - entering
19:03:08.639 [24243] <4> VxBSAEndTxn: INF - entering VxBSAEndTxn.
19:03:08.639 [24243] <4> VxBSAEndTxn: INF - Transaction being ABORTED.
19:03:08.639 [24243] <4> VxBSAGetEnv: INF - entering GetEnv - NBBSA_LOG_DIRECTORY
19:03:08.639 [24243] <4> VxBSAGetEnv: INF - returning - dbclient
19:03:08.639 [24243] <4> VxBSAEndTxn: INF - Cleaning directory: </usr/openv/netbackup/logs/dbclient>
19:03:08.639 [24243] <4> delete_old_files: entering delete_old_files.
19:03:08.639 [24243] <8> close_image: Session being terminated abnormally, cleaning up
19:03:08.639 [24243] <4> closeApi: entering closeApi.
19:03:08.639 [24243] <4> closeApi: INF - EXIT STATUS 6: the backup failed to back up the requested files

19:03:08.639 [24243] <4> close_image: INF - backup FAILED
19:03:08.639 [24243] <4> close_image: INF ---- end of Backup ---

19:03:08.639 [24243] <2> xbsa_EndTransaction: INF - leaving (0)

19:03:08.639 [24243] <2> int_CloseImage: INF - leaving
19:03:08.639 [24243] <2> sbtclose2: INF - leaving
19:03:08.639 [24243] <2> sbterror: INF - entering
19:03:08.639 [24243] <2> sbterror: INF - Error=7501: Failed to process backup file <bk_20770_1_884370037>
.
19:03:08.639 [24243] <2> sbterror: INF - leaving
19:03:09.173 [24244] <16> writeToServer: ERR - send() to server on socket failed: Broken pipe (32)
19:03:09.173 [24244] <16> dbc_put: ERR - failed sending data to server
19:03:09.173 [24244] <4> closeApi: entering closeApi.
19:03:09.173 [24244] <4> closeApi: INF - EXIT STATUS 6: the backup failed to back up the requested files

19:03:09.173 [24244] <4> closeApi: INF - closing commSock 17
19:03:09.173 [24244] <4> closeApi: INF - close of commSock returned <0> errno is <32>
19:03:09.173 [24244] <4> closeApi: INF - closing dataSock 19
19:03:09.173 [24244] <4> closeApi: INF - close of dataSock returned <0> errno is <32>
19:03:09.173 [24244] <4> closeApi: INF - setting linger on nameSock 18
19:03:09.173 [24244] <4> closeApi: INF - closing nameSock 18
19:03:09.173 [24244] <4> closeApi: INF - close of nameSock returned <0> errno is <32>
19:03:09.173 [24244] <16> VxBSASendData: ERR - Could not do a bsa_put().
19:03:09.173 [24244] <2> xbsa_ProcessError: INF - entering
19:03:09.173 [24244] <2> xbsa_ProcessError: INF - leaving
19:03:09.173 [24244] <16> xbsa_SendData: ERR - VxBSASendData: Failed with error:
   Server Status:  Communication with the server has not been initiated or the server status has not been retrieved from the serve
19:03:09.173 [24244] <2> sbterror: INF - entering
19:03:09.173 [24244] <2> sbterror: INF - Error=7501: VxBSASendData: Failed with error:
   Server Status:  Communication with the server has not been initiated or the server status has not been retrieved from the serve.
19:03:09.173 [24244] <2> sbterror: INF - leaving
19:03:09.196 [24244] <2> sbtclose2: INF - entering
19:03:09.196 [24244] <2> int_CloseImage: INF - entering
19:03:09.196 [24244] <2> int_CloseImage: INF - Backup - closing <bk_20772_1_884372179>
19:03:09.196 [24244] <2> xbsa_EndData: INF - entering
19:03:09.196 [24244] <4> VxBSAEndData: INF - entering EndData.
19:03:09.196 [24244] <4> finishTarImage: INF - FractionalObjectBytes: 0
19:03:09.196 [24244] <4> finishTarImage: INF - writing LF_END_U_LEN_FILE record
19:03:09.196 [24244] <4> write_LF_END_tarHeader: entering write_LF_END_tarHeader.
19:03:09.196 [24244] <16> writeToServer: ERR - send() to server on socket failed: Bad file number (9)
19:03:09.196 [24244] <16> write_LF_END_tarHeader: ERR - failed writing LF_END_U_LEN_FILE record on DATA socket
19:03:09.196 [24244] <16> finishTarImage: ERR - write_LF_END_tarHeader() failed.
19:03:09.196 [24244] <16> VxBSAEndData: ERR - EndData unable to bsa_finishTarImage().
19:03:09.196 [24244] <2> xbsa_ProcessError: INF - entering
19:03:09.196 [24244] <2> xbsa_ProcessError: INF - leaving
19:03:09.196 [24244] <16> xbsa_EndData: ERR - VxBSAEndData: Failed with error:
   Server Status:  Communication with the server has not been initiated or the server status has not been retrieved from the serve
19:03:09.196 [24244] <2> xbsa_EndData: INF - leaving (3)

19:03:09.196 [24244] <16> int_CloseImage: ERR - Failed to process backup file <bk_20772_1_884372179>

19:03:09.196 [24244] <2> xbsa_EndTransaction: INF - entering
19:03:09.196 [24244] <4> VxBSAEndTxn: INF - entering VxBSAEndTxn.
19:03:09.196 [24244] <4> VxBSAEndTxn: INF - Transaction being ABORTED.
19:03:09.196 [24244] <4> VxBSAGetEnv: INF - entering GetEnv - NBBSA_LOG_DIRECTORY
19:03:09.196 [24244] <4> VxBSAGetEnv: INF - returning - dbclient
19:03:09.196 [24244] <4> VxBSAEndTxn: INF - Cleaning directory: </usr/openv/netbackup/logs/dbclient>
19:03:09.196 [24244] <4> delete_old_files: entering delete_old_files.
19:03:09.197 [24244] <8> close_image: Session being terminated abnormally, cleaning up
19:03:09.197 [24244] <4> closeApi: entering closeApi.
19:03:09.197 [24244] <4> closeApi: INF - EXIT STATUS 6: the backup failed to back up the requested files

19:03:09.197 [24244] <4> close_image: INF - backup FAILED
19:03:09.197 [24244] <4> close_image: INF ---- end of Backup ---

19:03:09.197 [24244] <2> xbsa_EndTransaction: INF - leaving (0)

19:03:09.197 [24244] <2> int_CloseImage: INF - leaving
19:03:09.197 [24244] <2> sbtclose2: INF - leaving
19:03:09.197 [24244] <2> sbterror: INF - entering
19:03:09.197 [24244] <2> sbterror: INF - Error=7501: Failed to process backup file <bk_20772_1_884372179>

 

Is anyone able to provide some assistance with the information provided and advise what the problem may be. Other database backups which are part of the same backup policy will continue to backup to the same media server after the initial fail. This particular fail was a re-run of a monthly backup which only contained 2 databases in the backup policy.

/export/home/SA-NB-Unix/sperprarch_backup_monthly.sh
/export/home/SA-NB-Unix/sperdes2_backup_monthly.sh

First database backup failed for (the info provided above), the second database backup started immediately after the fail and had no issues backing up to the same media server.

Any assistance would be much appreciated.
 

 

 

0 Kudos
10 REPLIES 10

Marianne
Level 6
Partner    VIP    Accredited Certified

‎07-06-2015 08:22 PM

Please post logs as File attachments and not in the body of the post. Snippets of logs do not help as we cannot see the beginning of particular stream to get a feel for possible network or firewall timeout. Best to copy logs to .txt files and upload as File attachments. How long does the backup run before it fails? Is there a firewall anywhere in the picture? We normally see this when a firewall timeout terminates the connection. If no firewall, we need to see full logs (as File attachments ) plus all text in Details tab of failed job.

Handy NetBackup Links
0 Kudos

Varunthilak_B
Level 3
Certified

‎07-07-2015 03:32 AM

As per log, Backup failed with Communication error.

"Server Status:  Communication with the server has not been initiated or the server status has not been retrieved from the server"

What was changed in your environment ? 

Have you done normal basic communication tests ? if so kindly post those here

How about archive log/control file backup ? 

0 Kudos

Jamba1
Level 3

‎07-07-2015 05:10 PM

Hi Marianne,

I have attached the logs for the last time of fail (6th July) please advise if you require more log information.

Not sure if this will help but just want to list a quick history of this intermittent fail which has happened 4 times in the past 2 weeks. There is no firewall involved, the backup servers and host are all internal. During this time, I'm not aware of any changes to our environment. Would just like to add that I believe this issue has been ongoing for some time however, has never been investigated due to the intermittent nature and worked around by re-running the backup.

24th June

 

Netbackup/RMAN integration

Backup policy (Backup Selections)
/export/home/SA-NB-Unix/sperpr_backup.sh
/export/home/SA-NB-Unix/sperprarch_backup.sh
/export/home/SA-NB-Unix/spadmin_backup.sh
/export/home/SA-NB-Unix/sperdes2_backup.sh

Backup starts at 7pm and fails at 10:01:01pm
Backing up to media server BAKNB1
Backing up SPERPR Database
The backup piece that fails started backing up at 9:55pm
Continues backing up next database in the backup selection (SPERPRARCH @10:02:27 to BAKNB3)
Note - change of media server as the backup continues after fail
Netbackup reports error code 636

1st July (Changed backup Selection order in the netbackup policy)

Backup policy (Backup Selections)
/export/home/SA-NB-Unix/spadmin_backup.sh
/export/home/SA-NB-Unix/sperdes2_backup.sh
/export/home/SA-NB-Unix/sperpr_backup.sh
/export/home/SA-NB-Unix/sperprarch_backup.sh

Backup starts at 7pm and fails at 7:02:32
Backing up to media server BAKNB1
Backing up SPADMIN Database
The backup piece that fails started backing up at 7:01:19pm
Continues backing up next database in the backup selection (SPERDES2 @10:02:39 to BAKNB1)
Note - continues to backup to the same media server
Netbackup reports error code 636

2nd July

Backup policy (Backup Selections)
/export/home/SA-NB-Unix/sperpr_backup.sh
/export/home/SA-NB-Unix/sperprarch_backup.sh
/export/home/SA-NB-Unix/spadmin_backup.sh
/export/home/SA-NB-Unix/sperdes2_backup.sh

Backup starts at 7pm and fails at 7:16:03
Backing up to media server BAKNB1
Backing up SPERPR Database
The X2 backup pieces that fail started backing up at 7:12:29pm
Continues backing up next database in the backup selection (SPERPRARCH @7:23:40 to BAKNB4)
Note - change of media server as the backup continues after fail
Netbackup reports error code 636


6th July

Backup policy (Backup Selections) - Monthly backup re-run
/export/home/SA-NB-Unix/sperprarch_backup.sh
/export/home/SA-NB-Unix/sperdes2_backup.sh

Backup starts at 5pm and fails at 6:58pm
Backing up to media server BAKNB3
Backing up SPERPRARCH Database
The backup piece that fail started backing up at 6:20:41pm
Continues backing up next database in the backup selection (SPERDES @7:03:22 to BAKNB3)
Note - continues to backup to the same media server
Netbackup reports error code 636

Backup_Logs.zip
5224 KB
0 Kudos

Marianne
Level 6
Partner    VIP    Accredited Certified

‎07-08-2015 01:47 AM

I do not have the time to look at logs today, sorry.

Status 636 is a good clue though. 

Although this TN is for MS-SQL and firewall involved, it should still be worthwile to adjust KeepAlive settings on master and media servers:

http://www.symantec.com/docs/TECH197144 

Another TN: http://www.symantec.com/docs/HOWTO99910 

and: http://www.symantec.com/docs/TECH202675


Handy NetBackup Links
0 Kudos

Jamba1
Level 3

‎07-08-2015 08:13 PM

No need to apologise, whenever your ready.

Thanks for the links I'm not sure the TCP KeepAlive is the problem but will consider this as an option. Looking back at some history inidicates this problem happens (not always but recently) around the same time - 6:56pm and 7:20pm. I would just like to hightlight the following before changing any setting.

Last night I scheduled a monthly re-run of the SPERPRARCH database -

Policy CBD_ORACLE_RMAN_MONTHLY which started at 5pm

I also had the database (SPERPR, SPADMIN, SPERDES2) INCR backups scheduled as normal -

Policy CBD_ORACLE_RMAN_SPER which started at 7pm

This is not our normal schedule but I need to capture a monthly of the SPERPRARCH database.

The monthly backup has no issues until the following backup piece is queued to backup

/bk_20842_1_884544978 which starts at 6:56pm and fails at 7:10pm

the following backup sets also fail

/bk_74999_1_884545211 - 7:00pm - 7:10pm

/bk_74998_1_884545211 - 7:00pm - 7:10pm

/bk_20843_1_884545324 - 7:02pm - 7:10pm

What is strange as I believe the following x2 backup pieces belong to the SPERPR database which is running in the CBD_ORACLE_RMAN_SPER policy but reported in the CBD_ORACLE_RMAN_MONTHLY policy detailed status.

/bk_74999_1_884545211 - 7:00pm - 7:10pm

/bk_74998_1_884545211 - 7:00pm - 7:10pm

And the other x2 backup pieces belong to SPERPRARCH database

/bk_20842_1_884544978 - 6:56pm - 7:10pm

/bk_20843_1_884545324 - 7:02pm - 7:10pm

So both the SPERPR and SPERPRARCH database backups fail at around the same time but there is no errors reported in Netbackup for the SPERPR database running under the CBD_ORACLE_RMAN_SPER but reported under the CBD_ORACLE_RMAN_MONTHLY which it is not part of. Possibly this is another issue however, both backups only start failing when the CBD_ORACLE_RMAN_SPER backup kicks in at 7pm. The remaining databases as always do get backed up after intial fail.

I have attached the BPRD logs from the master, dbclient logs from the host (orasperprod) and BPBRM from the media server BAKNB3.

I guess what I'm trying to ask, is it possible there is network contention due to an overloaded backup schedule. Even if the monthly is not re-run we have many backups starting at 7pm. Is it possible the media servers are overloaded?

 

 

 

 

 

 

0 Kudos

Jamba1
Level 3

‎07-08-2015 08:42 PM

Logs attached from July 8th

0 Kudos

Jamba1
Level 3

‎07-08-2015 09:09 PM

The Solaris host is closing the connection?

19:10:30.645 [12892.13084] <2> put_strlen_str: cannot write data to network:  An existing connection was forcibly closed by the remote host.
19:10:30.645 [12892.13084] <16> bpbrm send_parent_msg: could not write WROTE orasperprod_1436346129 400384 0 50406.371 0 message to OUTSOCK

0 Kudos

Pawan_Nagra_777
Level 3

‎07-08-2015 11:07 PM

Hi,

can you share the script and out file from the effected hosts.

 

 

 

0 Kudos

Marianne
Level 6
Partner    VIP    Accredited Certified

‎07-13-2015 05:22 AM

You can see in the URL for NBU 6.x OS SCL:  http://www.symantec.com/docs/TECH70729   that the doc was 'Last Updated on March 28, 2012'. Long before W2012 Release Date of 11/25/2013. 

You NEED to upgrade your NBU software to current, supported version.

NetBackup 7.x Upgrade Portal
http://www.symantec.com/docs/TECH74584 


Handy NetBackup Links
0 Kudos

Jamba1
Level 3

‎07-13-2015 06:00 PM

Not sure what you mean by the above  - need to upgrade. Is some version of software we are running not supported?

OPS Center - 7.5.0.6

Netbackup - 7.5.0.6

Unix Client - 7.1

 

 

0 Kudos