Video Screencast Help
Symantec to Separate Into Two Focused, Industry-Leading Technology Companies. Learn more.

Backup getting failed due to media freeze and

Created: 19 Nov 2012 • Updated: 30 Jan 2013 | 15 comments
This issue has been solved. See solution.

Hi i have a query , I am using netbackup version 7.5 its a fresh installation i having a issue with running the backup.

1.Medias are getting freeze after each backup and backup getting failed.

2. change journal NOT enabled error.
 
here the the log details of bptm :
 
11:38:58.892 [2312.3600] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1490)
11:38:58.907 [2312.3600] <2> send_brm_msg: PID of bpxm = 2312
11:38:58.907 [2312.3600] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD/6
11:38:58.907 [2312.3600] <2> nbjm_media_request: old_media_id = NULL, media_id = 0011L5
11:38:58.907 [2312.3600] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:594)
11:38:58.907 [2312.3600] <2> Orb::init: Created anon service name: NB_2312_112974548(Orb.cpp:697)
11:38:58.907 [2312.3600] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_2312_112974548(Orb.cpp:714)
11:38:58.907 [2312.3600] <2> Orb::init: initializing ORB Default_DAEMON_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_2312_112974548 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:825)
11:38:58.907 [2312.3600] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:840)
11:38:59.219 [2312.3600] <2> NBIORInterceptor::establish_components: DNSQuery Lookup failed for host ksdinb error:123(NBIORInterceptor.cpp:94)
11:38:59.235 [2312.3600] <2> RequestInitialResources: returning
11:38:59.235 [2312.3600] <2> parse_resource_strings: MEDIADB 1 88 0011L5 4000035 ------ 20 1353391690 0 0 0 0 0 0 3 5 0 0 0 0 0 0
11:38:59.235 [2312.3600] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
11:38:59.235 [2312.3600] <2> parse_resource_strings: VOLUME 1 0011L5 4000035 000011L5 Daily FUJIFILM AD1EE545AJ 24 8 0 1 0 {00000000-0000-0000-0000-000000000000} 0
11:38:59.235 [2312.3600] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
11:38:59.235 [2312.3600] <2> parse_resource_strings: DRIVE 3 Drive_0001 2000008 1068053265 {3,0,4,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
11:38:59.235 [2312.3600] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
11:38:59.235 [2312.3600] <2> parse_resource_strings: STORAGE 1 ksdinb_storage_unit 20 1048576 2 1 0 0 ksdinb ksdinb *NULL*
11:38:59.235 [2312.3600] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
11:38:59.235 [2312.3600] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
11:38:59.235 [2312.3600] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
11:38:59.235 [2312.3600] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
11:38:59.235 [2312.3600] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
11:38:59.235 [2312.3600] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
11:38:59.235 [2312.3600] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
11:38:59.235 [2312.3600] <2> nbjm_media_request: Job control returned to BPTM
11:38:59.235 [2312.3600] <2> drivename_open: Called with Create 1, file Drive_0001
11:38:59.235 [2312.3600] <2> drivename_checklock: Called
11:38:59.235 [2312.3600] <2> drivename_lock: lock established
11:38:59.235 [2312.3600] <4> create_tpreq_file: {3,0,4,0}
11:38:59.235 [2312.3600] <2> drivename_write: Called with mode 2
11:38:59.235 [2312.3600] <2> drivename_unlock: unlocked
11:38:59.235 [2312.3600] <2> drivename_checklock: Called
11:38:59.235 [2312.3600] <2> drivename_lock: lock established
11:38:59.235 [2312.3600] <2> openNTDevice: config_path: {3,0,4,0}, serial_num: 1068053265
11:38:59.235 [2312.3600] <2> get_drive_path: SCSI coordinates {3,0,4,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-hh5#5&2588f88a&0&000400#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
11:38:59.235 [2312.3600] <2> check_serial_num: serial number match for drive with SCSI coordinates {3,0,4,0}, dos_path \\.\Tape0, drive serial number 1068053265, expected serial number 1068053265
11:38:59.235 [2312.3600] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
11:38:59.235 [2312.3600] <2> really_tpunmount: tpunmount'ing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_Drive_0001
11:38:59.640 [2312.3600] <2> tapelib: wait_for_ltid, UnMount, timeout 2400
11:39:41.339 [2312.3600] <4> report_resource_done: VBRD 1 2312 0 Drive_0001 0011L5
11:39:41.339 [2312.3600] <2> openNTDevice: config_path: {3,0,4,0}, serial_num: 1068053265
11:39:41.339 [2312.3600] <2> get_drive_path: SCSI coordinates {3,0,4,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-hh5#5&2588f88a&0&000400#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
11:39:41.339 [2312.3600] <2> check_serial_num: serial number match for drive with SCSI coordinates {3,0,4,0}, dos_path \\.\Tape0, drive serial number 1068053265, expected serial number 1068053265
11:39:41.339 [2312.3600] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
11:39:41.339 [2312.3600] <2> tapealert_and_release: report_attr, fl1 0x00100001, fl2 0x00000000
11:39:41.339 [2312.3600] <2> tapealert_and_release: SCSI RELEASE
11:39:41.339 [2312.3600] <2> drivename_unlock: unlocked
11:39:41.339 [2312.3600] <2> drivename_close: Called for file Drive_0001
11:39:41.339 [2312.3600] <2> drivename_remove: Called
11:39:41.339 [2312.3600] <2> main: Sending [EXIT STATUS 0] to NBJM
11:39:41.339 [2312.3600] <2> bptm: EXITING with status 0 <----------
11:39:41.527 [5352.5320] <2> requestFailed: got gotCallback, jmJobStatus = [96], emmStatus = [2005000], mapped failure status to= [96]
11:39:41.527 [5352.5320] <16> RequestSpanResources: MultiResReq.cpp:2754 resource request failed [96]
11:39:41.527 [5352.5320] <2> RequestSpanResources: returning
11:39:41.527 [5352.5320] <4> nbjm_media_request: Error from RequestSpanResources, Master ksdinb, error 96, resourceAllocated 0
11:39:41.527 [5352.5320] <2> send_MDS_msg: OP_STATUS 0 88 ksdinb 8211 5 0 0 0 0 0 0 *NULL* 0
11:39:41.527 [5352.5320] <16> send_MDS_msg: Error from emmlib_handleMessage, Master ksdinb, type 12, returned error 2005023
11:39:41.527 [5352.5320] <2> send_operation_error: Decoded status = 19 from 5
11:39:41.527 [5352.5320] <2> bptm: EXITING with status 96 <----------
 
 
Bpbkar log details from client:
 
 
11:10:25.340: [1300.2276] <4> tar_backup_tfi::determineEstimate: INF - Job Tracking Estimates
11:10:25.340: [1300.2276] <4> tar_backup_tfi::determineEstimate: INF - --------------------------------------------------------------------------------
11:10:25.340: [1300.2276] <4> tar_backup_tfi::determineEstimate: INF -           Files: 152
11:10:25.340: [1300.2276] <4> tar_backup_tfi::determineEstimate: INF -         Folders: 30
11:10:25.340: [1300.2276] <4> tar_backup_tfi::determineEstimate: INF -      Bytes Data: 61232366
11:10:25.340: [1300.2276] <4> tar_backup_tfi::determineEstimate: INF -  Gigabytes Data: 0
11:10:25.340: [1300.2276] <4> tar_backup_tfi::determineEstimate: INF -     Bytes Image: 0
11:10:25.340: [1300.2276] <4> tar_backup_tfi::determineEstimate: INF - Gigabytes Image: 0
11:10:25.340: [1300.2276] <4> tar_backup_tfi::determineEstimate: INF - ================================================================================
11:10:25.340: [1300.2276] <4> dos_backup::tfs_scanstart: INF - starting scan for file directive:<C:\Drivers>
11:10:25.340: [1300.2276] <4> dos_backup::tfs_scanstart: INF - starting scan using name:<C:\Drivers>
11:10:25.340: [1300.2276] <4> dos_backup::tfs_scanstart: INF - in 'backup' mode
11:10:25.340: [1300.2276] <2> tar_base::V_vTarMsgW: INF - Enabling volume snapshots for (C:\Drivers), please wait...
11:10:25.340: [1300.2276] <4> V_DetermineMountInfo: INF - Checking Volume \\?\Volume{3e452f95-b027-11e1-85a3-806e6f6e6963}\ for '\Drivers'
11:10:25.340: [1300.2276] <4> V_DetermineMountInfo: INF -   Adding NTFS Volume C:\ ==> \\?\Volume{3e452f95-b027-11e1-85a3-806e6f6e6963}\
11:10:25.340: [1300.2276] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - ======================================================================
11:10:25.340: [1300.2276] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - Attempting to create snapshots for 'C:\Drivers'
11:10:25.340: [1300.2276] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - CREATE request: C:\Program Files\Veritas\NetBackup\bin\bpfis create -owner NBU -fso -WOFB -fim VSP -id ksdidbb_1353389975 "C:\Drivers"
11:10:31.424: [1300.2276] <4> V_Snapshot::V_Snapshot_AddMappings: INF - input parameters: 
source path:<C:\Drivers>
 snap path:<\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy16\Drivers>
mount path:<(null)>
11:10:31.424: [1300.2276] <4> V_Snapshot::V_GetSourceVolume: INF - input parameters:
 source:<C:\Drivers>
snapshot:<\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy16\Drivers>
11:10:31.424: [1300.2276] <4> V_Snapshot::V_Snapshot_AddMappings: INF - Volume Snapshot Mapping: \\?\Volume{3e452f95-b027-11e1-85a3-806e6f6e6963}\ --> GLOBALROOT\Device\HarddiskVolumeShadowCopy16
11:10:31.424: [1300.2276] <4> V_Snapshot::V_Snapshot_ParseBpfisOutput: INF - Snapshot creation, FIS_ID: ksdidbb_1353389975
11:10:31.424: [1300.2276] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - Snapshot creation was successful
11:10:31.424: [1300.2276] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - Snapshot provider: VSP
11:10:31.424: [1300.2276] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - ======================================================================
11:10:31.424: [1300.2276] <2> tar_base::V_vTarMsgW: INF - Volume snapshots enabled
11:10:31.424: [1300.2276] <4> dos_backup::_change_journal_prepare: INF - change journal previously prepared and disabled for <C:\Drivers>
11:40:24.444: [1300.2276] <16> tar_tfi::processException: 
An Exception of type [SocketWriteException] has occured at:
  Module: @(#) $Source: src/ncf/tfi/lib/TransporterRemote.cpp,v $ $Revision: 1.54 $ , Function: TransporterRemote::write[2](), Line: 321
  Module: @(#) $Source: src/ncf/tfi/lib/Packer.cpp,v $ $Revision: 1.90 $ , Function: Packer::getBuffer(), Line: 658
  Module: tar_tfi::getBuffer, Function: D:\NB\NB_7.5\src\cl\clientpc\util\tar_tfi.cpp, Line: 311
  Local Address: [::]:0
  Remote Address: [::]:0
  OS Error: 10054 (An existing connection was forcibly closed by the remote host.
)
  Expected bytes: 131072
 
11:40:24.444: [1300.2276] <2> tar_base::V_vTarMsgW: FTL - socket write failed
11:40:24.444: [1300.2276] <4> tar_backup::backup_done_state: INF - number of file directives not found: 0
11:40:24.444: [1300.2276] <4> tar_backup::backup_done_state: INF -     number of file directives found: 1
11:40:24.444: [1300.664] <4> tar_base::keepaliveThread: INF - keepalive thread terminating (reason: WAIT_OBJECT_0)
11:40:24.444: [1300.2276] <4> tar_base::stopKeepaliveThread: INF - keepalive thread has exited. (reason: WAIT_OBJECT_0)
11:40:24.444: [1300.2276] <4> tar_backup::backup_done_state: INF - ================================================================================
11:40:24.444: [1300.2276] <4> tar_backup::backup_done_state: INF - Job Tracking Statistics
11:40:24.444: [1300.2276] <4> tar_backup::backup_done_state: INF - --------------------------------------------------------------------------------
11:40:24.444: [1300.2276] <4> tar_backup::backup_done_state: INF -           Files: 12
11:40:24.444: [1300.2276] <4> tar_backup::backup_done_state: INF -         Folders: 9
11:40:24.444: [1300.2276] <4> tar_backup::backup_done_state: INF -      Bytes Data: 5978920
11:40:24.444: [1300.2276] <4> tar_backup::backup_done_state: INF -  Gigabytes Data: 0
11:40:24.444: [1300.2276] <4> tar_backup::backup_done_state: INF -     Bytes Image: 2882048
11:40:24.444: [1300.2276] <4> tar_backup::backup_done_state: INF - Gigabytes Image: 0
11:40:24.444: [1300.2276] <4> tar_backup::backup_done_state: INF - ================================================================================
11:40:24.444: [1300.2276] <2> tar_base::V_vTarMsgW: INF - EXIT STATUS 24: socket write failed
11:40:24.444: [1300.2276] <4> tar_backup::backup_done_state: INF - Not waiting for server status
11:40:24.444: [1300.2276] <4> dos_backup::tfs_reset: INF - Snapshot deletion start
11:40:24.444: [1300.2276] <4> V_Snapshot::V_Snapshot_Destroy: INF - Attempting to destroy volume snapshots: bpfis delete -id ksdidbb_1353389975 -copy 1 
11:40:29.514: [1300.2276] <4> V_Snapshot::V_Snapshot_Destroy: INF - Snapshot Destroy EXIT STATUS 0: the requested operation was successfully completed
11:40:29.514: [1300.2276] <4> OVStopCmd: INF - EXIT - status = 0
11:40:29.514: [1300.2276] <2> tar_base::V_Close: closing...
11:40:29.514: [1300.2276] <4> dos_backup::tfs_reset: INF - Snapshot deletion start
11:40:29.514: [1300.2276] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): enter - InitFlags:0x00000101
11:40:29.514: [1300.2276] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): ubs specifics: 0x001d0000
11:40:29.545: [1300.2276] <4> OVShutdown: INF - Finished process
11:40:29.545: [1300.2276] <4> WinMain: INF - Exiting C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe
11:40:31.573: [1300.2276] <4> ov_log::OVClose: INF - Closing log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\112012.LOG
 

Comments 15 CommentsJump to latest comment

RamNagalla's picture

hi 

could you please unfreeze the tapes, and trigger the backup

i would like to see the job details status wich is making the tapes freezing..

please post the job detail status which is marking tapes into frozen state.

Marianne's picture

Nagalla is right - the current bptm log only contains status 96 (no tapes).

We need to see a previous bptm log that shows media error causing it to be frozen.

Reason for media getting frozen should also be in the Job Details of the failed job as well as in Tape Logs report (select dates that matches frozen state).

If you have relevant bptm log, please post as File attachment.

Supporting Storage Foundation and VCS on Unix and Windows as well as NetBackup on Unix and Windows
Handy NBU Links

Anthony Tsang's picture

You can goto tape logs in tape reports in which it will prompt out the why the tape frozen

pboddeti's picture

I have unfreezed the tape and triggred the backup

Here is the Job details as requested.

Info nbjm(pid=5644) starting backup job (jobid=288) for client ksdidbb, policy Monthly_Bkup, schedule Full_Monthly  
20-11-2012 14:53:32 - estimated 0 Kbytes needed
20-11-2012 14:53:32 - Info nbjm(pid=5644) started backup (backupid=ksdidbb_1353403412) job for client ksdidbb, policy Monthly_Bkup, schedule Full_Monthly on storage unit ksdinb_storage_unit
20-11-2012 14:53:32 - started process bpbrm (3536)
20-11-2012 14:53:37 - Info bpbrm(pid=3536) ksdidbb is the host to backup data from     
20-11-2012 14:53:37 - Info bpbrm(pid=3536) reading file list from client        
20-11-2012 14:53:38 - connecting
20-11-2012 14:53:41 - Info bpbrm(pid=3536) starting bpbkar32 on client         
20-11-2012 14:53:41 - connected; connect time: 00:00:03
20-11-2012 14:53:42 - Info bpbkar32(pid=1496) Backup started           
20-11-2012 14:53:42 - Info bptm(pid=2664) start            
20-11-2012 14:53:43 - Info bptm(pid=2664) using 65536 data buffer size        
20-11-2012 14:53:43 - Info bptm(pid=2664) setting receive network buffer to 263168 bytes      
20-11-2012 14:53:43 - Info bptm(pid=2664) using 30 data buffers         
20-11-2012 14:53:43 - Info bptm(pid=2664) start backup           
20-11-2012 14:53:43 - Info bptm(pid=2664) backup child process is pid 4208.4272       
20-11-2012 14:53:43 - Info bptm(pid=2664) Waiting for mount of media id 0011L5 (copy 1) on server ksdinb. 
20-11-2012 14:53:43 - Info bptm(pid=4208) start            
20-11-2012 14:53:43 - mounting 0011L5
20-11-2012 14:53:44 - Info bpbkar32(pid=1496) change journal NOT enabled for <C:\Users\Default\Documents>       
20-11-2012 14:54:32 - Error bptm(pid=2664) FREEZING media id 0011L5, WORM media detected in a non-WORM pool  
20-11-2012 14:54:32 - Warning bptm(pid=2664) media id 0011L5 load operation reported an error     
20-11-2012 14:54:32 - current media 0011L5 complete, requesting next resource Any
20-11-2012 14:55:13 - Info bptm(pid=2664) Waiting for mount of media id 0012L5 (copy 1) on server ksdinb. 
20-11-2012 14:55:13 - granted resource 0012L5
20-11-2012 14:55:13 - granted resource Drive_0002
20-11-2012 14:55:13 - granted resource ksdinb_storage_unit
20-11-2012 14:55:13 - end writing
20-11-2012 14:55:13 - mounting 0012L5
20-11-2012 14:55:57 - Error bptm(pid=2664) FREEZING media id 0012L5, WORM media detected in a non-WORM pool  
20-11-2012 14:55:57 - Warning bptm(pid=2664) media id 0012L5 load operation reported an error     
20-11-2012 14:55:57 - current media 0012L5 complete, requesting next resource Any
20-11-2012 14:56:40 - Info bptm(pid=2664) Waiting for mount of media id 0013L5 (copy 1) on server ksdinb. 
20-11-2012 14:56:40 - granted resource 0013L5
20-11-2012 14:56:40 - granted resource Drive_0001
20-11-2012 14:56:40 - granted resource ksdinb_storage_unit
20-11-2012 14:56:40 - end writing
20-11-2012 14:56:40 - mounting 0013L5
20-11-2012 14:57:24 - Error bptm(pid=2664) FREEZING media id 0013L5, WORM media detected in a non-WORM pool  
20-11-2012 14:57:24 - Warning bptm(pid=2664) media id 0013L5 load operation reported an error     
20-11-2012 14:57:24 - current media 0013L5 complete, requesting next resource Any
20-11-2012 14:58:04 - Info bptm(pid=2664) Waiting for mount of media id 0014L5 (copy 1) on server ksdinb. 
20-11-2012 14:58:04 - granted resource 0014L5
20-11-2012 14:58:04 - granted resource Drive_0002
20-11-2012 14:58:04 - granted resource ksdinb_storage_unit
20-11-2012 14:58:04 - end writing
20-11-2012 14:58:04 - mounting 0014L5
20-11-2012 14:58:51 - Error bptm(pid=2664) FREEZING media id 0014L5, WORM media detected in a non-WORM pool  
20-11-2012 14:58:51 - Warning bptm(pid=2664) media id 0014L5 load operation reported an error     
20-11-2012 14:58:51 - current media 0014L5 complete, requesting next resource Any
20-11-2012 14:59:54 - Info bptm(pid=2664) Waiting for mount of media id 0015L5 (copy 1) on server ksdinb. 
20-11-2012 14:59:54 - granted resource 0015L5
20-11-2012 14:59:54 - granted resource Drive_0001
20-11-2012 14:59:54 - granted resource ksdinb_storage_unit
20-11-2012 14:59:54 - end writing
20-11-2012 14:59:54 - mounting 0015L5
20-11-2012 15:00:39 - Error bptm(pid=2664) FREEZING media id 0015L5, WORM media detected in a non-WORM pool  
20-11-2012 15:00:39 - Warning bptm(pid=2664) media id 0015L5 load operation reported an error     
20-11-2012 15:00:39 - current media 0015L5 complete, requesting next resource Any
20-11-2012 15:01:20 - Info bptm(pid=2664) Waiting for mount of media id 0019L5 (copy 1) on server ksdinb. 
20-11-2012 15:01:20 - granted resource 0019L5
20-11-2012 15:01:20 - granted resource Drive_0002
20-11-2012 15:01:20 - granted resource ksdinb_storage_unit
20-11-2012 15:01:20 - end writing
20-11-2012 15:01:20 - mounting 0019L5
20-11-2012 15:02:05 - Error bptm(pid=2664) FREEZING media id 0019L5, WORM media detected in a non-WORM pool  
20-11-2012 15:02:05 - Warning bptm(pid=2664) media id 0019L5 load operation reported an error     
20-11-2012 15:02:05 - current media 0019L5 complete, requesting next resource Any
20-11-2012 15:02:45 - Info bptm(pid=2664) Waiting for mount of media id 0018L5 (copy 1) on server ksdinb. 
20-11-2012 15:02:45 - granted resource 0018L5
20-11-2012 15:02:45 - granted resource Drive_0001
20-11-2012 15:02:45 - granted resource ksdinb_storage_unit
20-11-2012 15:02:45 - end writing
20-11-2012 15:02:45 - mounting 0018L5
20-11-2012 15:03:31 - Error bptm(pid=2664) FREEZING media id 0018L5, WORM media detected in a non-WORM pool  
20-11-2012 15:03:31 - Warning bptm(pid=2664) media id 0018L5 load operation reported an error     
20-11-2012 15:03:31 - current media 0018L5 complete, requesting next resource Any
20-11-2012 15:04:32 - Info bptm(pid=2664) Waiting for mount of media id 0017L5 (copy 1) on server ksdinb. 
20-11-2012 15:04:32 - granted resource 0017L5
20-11-2012 15:04:32 - granted resource Drive_0002
20-11-2012 15:04:32 - granted resource ksdinb_storage_unit
20-11-2012 15:04:32 - end writing
20-11-2012 15:04:32 - mounting 0017L5
20-11-2012 15:05:18 - Error bptm(pid=2664) FREEZING media id 0017L5, WORM media detected in a non-WORM pool  
20-11-2012 15:05:18 - Warning bptm(pid=2664) media id 0017L5 load operation reported an error     
20-11-2012 15:05:18 - current media 0017L5 complete, requesting next resource Any
20-11-2012 15:06:01 - Info bptm(pid=2664) Waiting for mount of media id 0016L5 (copy 1) on server ksdinb. 
20-11-2012 15:06:01 - granted resource 0016L5
20-11-2012 15:06:01 - granted resource Drive_0001
20-11-2012 15:06:01 - granted resource ksdinb_storage_unit
20-11-2012 15:06:01 - end writing
20-11-2012 15:06:01 - mounting 0016L5
20-11-2012 15:06:51 - Error bptm(pid=2664) FREEZING media id 0016L5, WORM media detected in a non-WORM pool  
20-11-2012 15:06:51 - Warning bptm(pid=2664) media id 0016L5 load operation reported an error     
20-11-2012 15:06:51 - current media 0016L5 complete, requesting next resource Any
20-11-2012 15:07:35 - Info bptm(pid=2664) Waiting for mount of media id 0020L5 (copy 1) on server ksdinb. 
20-11-2012 15:07:35 - granted resource 0020L5
20-11-2012 15:07:35 - granted resource Drive_0002
20-11-2012 15:07:35 - granted resource ksdinb_storage_unit
20-11-2012 15:07:35 - end writing
20-11-2012 15:07:35 - mounting 0020L5
20-11-2012 15:08:22 - Error bptm(pid=2664) FREEZING media id 0020L5, WORM media detected in a non-WORM pool  
20-11-2012 15:08:22 - Warning bptm(pid=2664) media id 0020L5 load operation reported an error     
20-11-2012 15:08:22 - current media 0020L5 complete, requesting next resource Any
20-11-2012 15:09:04 - Info bptm(pid=2664) EXITING with status 96 <----------        
20-11-2012 15:09:06 - Info bpbkar32(pid=1496) done. status: 96: unable to allocate new media for backup, storage unit has none available
20-11-2012 15:09:06 - end writing
unable to allocate new media for backup, storage unit has none available(96)
 
 
 
RamNagalla's picture

hear is the issue;;;;

20-11-2012 15:08:22 - Error bptm(pid=2664) FREEZING media id 0020L5, WORM media detected in a non-WORM pool  

i guess you never had a successfull backups with this tapes

check the below T/N

http://www.symantec.com/business/support/index?pag...

pboddeti's picture
Bptm logs
 
15:04:32.180 [2664.1536] <2> RequestSpanResources: returning
15:04:32.180 [2664.1536] <2> parse_resource_strings: MEDIADB 1 110 0017L5 4000040 ------ 20 1353404072 0 0 0 0 0 0 5 7 0 0 0 0 0 0
15:04:32.180 [2664.1536] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
15:04:32.180 [2664.1536] <2> parse_resource_strings: VOLUME 1 0017L5 4000040 000017L5 Monthly FUJIFILM AC65E548XY 24 8 0 7 0 {00000000-0000-0000-0000-000000000000} 0
15:04:32.180 [2664.1536] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
15:04:32.180 [2664.1536] <2> parse_resource_strings: DRIVE 3 Drive_0002 2000009 1068053277 {3,0,5,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
15:04:32.180 [2664.1536] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
15:04:32.180 [2664.1536] <2> parse_resource_strings: STORAGE 1 ksdinb_storage_unit 20 1048576 2 1 0 0 ksdinb ksdinb *NULL*
15:04:32.180 [2664.1536] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
15:04:32.180 [2664.1536] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
15:04:32.180 [2664.1536] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
15:04:32.180 [2664.1536] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
15:04:32.180 [2664.1536] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
15:04:32.180 [2664.1536] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
15:04:32.180 [2664.1536] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
15:04:32.180 [2664.1536] <2> nbjm_media_request: Job control returned to BPTM
15:04:32.180 [2664.1536] <2> drivename_open: Called with Create 1, file Drive_0002
15:04:32.180 [2664.1536] <2> drivename_checklock: Called
15:04:32.180 [2664.1536] <2> drivename_lock: lock established
15:04:32.180 [2664.1536] <2> drivename_write: Called with mode 0
15:04:32.180 [2664.1536] <2> drivename_unlock: unlocked
15:04:32.180 [2664.1536] <2> drivename_checklock: Called
15:04:32.180 [2664.1536] <2> drivename_lock: lock established
15:04:32.180 [2664.1536] <2> db_byid: search for media id 0017L5
15:04:32.211 [2664.1536] <2> send_MDS_msg: MEDIADB 1 110 0017L5 4000040 *NULL* 20 1353403412 0 0 0 0 0 0 5 7 0 16 1024 0 0 0
15:04:32.211 [2664.1536] <2> media_id_to_monitor: job_id = 288, pDstMediaId = 0017L5
15:04:32.211 [2664.1536] <2> mount_open_media: Waiting for mount of media id 0017L5 (copy 1) on server ksdinb.
15:04:32.211 [2664.1536] <2> openNTDevice: config_path: {3,0,5,0}, serial_num: 1068053277
15:04:32.211 [2664.1536] <2> get_drive_path: SCSI coordinates {3,0,5,0}, dos_path \\.\Tape1, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-hh5#5&2588f88a&0&000500#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
15:04:32.211 [2664.1536] <2> check_serial_num: serial number match for drive with SCSI coordinates {3,0,5,0}, dos_path \\.\Tape1, drive serial number 1068053277, expected serial number 1068053277
15:04:32.211 [2664.1536] <2> manage_drive_before_load: SCSI RESERVE
15:04:32.227 [2664.1536] <2> manage_drive_before_load: report_attr, fl1 0x00100001, fl2 0x00000000
15:04:32.227 [2664.1536] <2> manage_drive_before_load: write mode set to 1
15:04:33.038 [2664.1536] <2> tapelib: wait_for_ltid, Mount, timeout 0
15:05:18.855 [2664.1536] <2> openTpreqFile: tpreq_file: C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_Drive_0002, serial_num: 1068053277
15:05:18.855 [2664.1536] <2> get_drive_path: SCSI coordinates {3,0,5,0}, dos_path \\.\Tape1, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-hh5#5&2588f88a&0&000500#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
15:05:18.855 [2664.1536] <2> check_serial_num: serial number match for drive with SCSI coordinates {3,0,5,0}, dos_path \\.\Tape1, drive serial number 1068053277, expected serial number 1068053277
15:05:18.855 [2664.1536] <2> init_tape: \\.\Tape1 (SCSI coordinates {3,0,5,0}) configured with blocksize 0
15:05:18.855 [2664.1536] <2> init_tape: \\.\Tape1 (SCSI coordinates {3,0,5,0}) has compression enabled
15:05:18.855 [2664.1536] <2> io_open: SCSI RESERVE
15:05:18.871 [2664.1536] <2> manage_drive_attributes: report_attr, fl1 0x00230459, fl2 0x0000000c
15:05:18.871 [2664.1536] <2> manage_drive_attributes: WORM media is loaded
15:05:18.871 [2664.1536] <2> manage_drive_attributes: Matching medium manufacturer [FUJIFILM], sn [AC65E548XY]
15:05:18.871 [2664.1536] <2> manage_drive_attributes: Host Attributes: Vendor [SYMANTEC], Name [NetBackup BPLABEL], Version [7.5.0.3]
15:05:18.871 [2664.1536] <2> manage_drive_attributes: DateLabeled [201211200654], Barcode [000017L5], Owninghost [ksdinb]
15:05:18.871 [2664.1536] <2> manage_drive_attributes: MediaPool [scratch], MediaLabel [MEDIA=0017L5;]
15:05:18.871 [2664.1536] <2> manage_drive_attributes: encryption status: nexus scope 1, key scope 1
15:05:18.871 [2664.1536] <2> manage_drive_attributes: encryp mode 0x0, decryp mode 0x0, algorithm index 2, key instance 11
15:05:18.871 [2664.1536] <2> manage_drive_attributes: Media is protected with APPEND_ONLY
15:05:18.871 [2664.1536] <2> send_MDS_msg: MEDIADB 1 110 0017L5 4000040 *NULL* 20 1353403412 0 0 0 0 0 0 5 7 0 17 1024 0 0 0
15:05:18.886 [2664.1536] <16> manage_drive_attributes: FREEZING media id 0017L5, WORM media detected in a non-WORM pool
15:05:18.886 [2664.1536] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_Drive_0002, from bptm.c.16424
15:05:18.886 [2664.1536] <2> drivename_write: Called with mode 1
15:05:18.886 [2664.1536] <2> drivename_unlock: unlocked
pboddeti's picture

yes you are correct Nagalla, I never had a successful backup from all the inserted LTO 5 tapes.?

So do i need to use LTO -4 tapes ? what can be the fix to use LTO -5 tapes ?

RamNagalla's picture

from bptm log :-

5:05:18.871 [2664.1536] <2> manage_drive_attributes: Media is protected with APPEND_ONLY
15:05:18.871 [2664.1536] <2> send_MDS_msg: MEDIADB 1 110 0017L5 4000040 *NULL* 20 1353403412 0 0 0 0 0 0 5 7 0 17 1024 0 0 0
15:05:18.886 [2664.1536] <16> manage_drive_attributes: FREEZING media id 0017L5, WORM media detected in a non-WORM pool

i am seeting 2 possible ways..

first check to create touch file ,  to disable the Append only mode...

source :-http://www.symantec.com/business/support/index?page=content&id=TECH178719

For UNIX:

Use the touch file for Unix based machines in /usr/openv/netbackup/db/config/DISABLE_APPEND_MODE to prevent this feature from being used.

For WINDOWS:

Use the touch file for Windows based machines in %install_path%\Veritas\Netbackup\db\config\DISABLE_APPEND_MODE to prevent this feature from being used.

and then unfreeze the tapes and try backup.

if this does not work..

2nd, you need to replace the tapes with normal LTO5 tapes.

pboddeti's picture

I have unfreezed and triggred the backup after creating the touch file in the mentioned path above for windows 2008 R2 server

still the issue persist . can i try with LTO 4 tapes ?

these LTO 5 tapes are not normal ? thanks a lot for your support .

pboddeti's picture

here the job detills :

20-11-2012 18:44:42 - Info bptm(pid=4804) start backup           
20-11-2012 18:44:42 - Info bptm(pid=4804) backup child process is pid 1316.732       
20-11-2012 18:44:42 - Info bptm(pid=4804) Waiting for mount of media id 0012L5 (copy 1) on server ksdinb. 
20-11-2012 18:44:42 - Info bptm(pid=1316) start            
20-11-2012 18:44:42 - mounting 0012L5
20-11-2012 18:44:43 - Info bpbkar32(pid=2900) change journal NOT enabled for <C:\Users\Default\Documents>       
20-11-2012 18:44:45 - Error bptm(pid=4804) error requesting media, TpErrno = Robot operation failed     
20-11-2012 18:44:45 - Warning bptm(pid=4804) media id 0012L5 load operation reported an error     
20-11-2012 18:44:45 - current media 0012L5 complete, requesting next resource Any
20-11-2012 18:45:27 - Info bptm(pid=4804) Waiting for mount of media id 0012L5 (copy 1) on server ksdinb. 
20-11-2012 18:45:27 - granted resource 0012L5
20-11-2012 18:45:27 - granted resource Drive_0002
20-11-2012 18:45:27 - granted resource ksdinb_storage_unit
20-11-2012 18:45:27 - mounting 0012L5
20-11-2012 18:46:07 - Error bptm(pid=4804) FREEZING media id 0012L5, WORM media detected in a non-WORM pool  
20-11-2012 18:46:07 - Warning bptm(pid=4804) media id 0012L5 load operation reported an error     
20-11-2012 18:46:07 - current media 0012L5 complete, requesting next resource Any
RamNagalla's picture

so i guess you have the WORM tapes instead of Normal tapes.

 you need to replace your WORM LTO5 tapes with Normal LTO 5 tapes.,  you does not need to got with LTO4 tapes , you can try with the normal LTO 5 tapes.. 

SOLUTION
Mark_Solutions's picture

You device config shows them to be half height LTO5 drives so you are good to use LTO5 tapes

Whoever you purchased them from needs asking to replace them all with normal LTO5 tapes (unless you have made an error when you ordered them)

WORM stands for Write Once Ready Many so even if they had worked you could have only used them once but fortunately you drives do not support such tapes

Get them changed or get some new ones.

One other point .. the media ID shows as 0012L5 .. please set a Media ID Generation rule under the library inventory section which says that the robot has 8 didgits and a rule of 1:2:3:4:5:6 so that the first 6 digits of the barcode is used as the Media ID and not the last 6

That will give you a clean start when you get the new tapes (unfreeze and delete all current ones)

Hope this helps

Authorised Symantec Consultant

Don't forget to "Mark as Solution" if someones advice has solved your issue - and please bring back the Thumbs Up!!.

Marianne's picture

15:05:18.886 [2664.1536] <16> manage_drive_attributes: FREEZING media id 0017L5, WORM media detected in a non-WORM pool

WORM media needs special configuration.

Please find 'normal' LTO 5 cartridges to use as backup media.
Else, you need to read up in Admin Guide I on how to configure NBU in order to use WORM media.

Supporting Storage Foundation and VCS on Unix and Windows as well as NetBackup on Unix and Windows
Handy NBU Links

pboddeti's picture

Tried adding touch files in the path %install_path%\Veritas\Netbackup\db\config\

DISABLE_WORM_TAPE
DISABLE_WORM_POOLCHECK
DISABLE_APPEND_MODE
 
Re-triggred the backup the issue was not resolved.
 
As per the nagalla's 2nd option tried using the normal LTO 5 and LTO 4 tapes backup was successful.
Issue is resolved by replacing that WORM tapes.
 
Thanks a lot Nagalla, Mariane and Mark for the valuable updates.
 
 
RamNagalla's picture

its a good news,

please mark the solution if your issue got resolved..