Backup getting failed due to media freeze and

[pboddeti]

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

[RamNagalla]

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]

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.

[Anthony_Tsang]

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

[pboddeti]

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)

@ Marianne: Not enabled the bptm will enable the logs for it will provide later if not sorted .

[RamNagalla]

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?page=content&id=TECH178476

[pboddeti]

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]

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]

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]

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]

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 · Accepted solution]

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.. 

[Mark_Solutions]

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

[Marianne]

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.

[pboddeti]

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]

its a good news,

please mark the solution if your issue got resolved..