SLP Duplications Hanging

[old_mate]

NBU Master: 7.1.0.2 (Windows)

Media Servers: 7.1.0.2 (Windows)

Hi all,

I’ve been having some issues with SLP duplications from PureDisk/Adv Disk - they will get to a certain bite count (sometimes) and then hang – Waiting for positioning of media ID XXX on server <Media Server>. It’s mainly happening on two of our LTO3 drives (ACS), but has occurred on all of them. 

The BPTM logs are giving me some interesting information – Can anyone give me info on the "drivename_lock: lock failed (already locked)" ouput? Or any other issues you can see in there? Many thanks!

09:31:19.711 [3412.10992] <2> bptm: INITIATING (VERBOSE = 0): -unload -dn BAY13 -dp {5,0,0,0} -dk 2000030 -m ID1541 -mk 4001871 -mds 0 -alocid 21941195 -jobid -1338190184 -jm

09:31:19.711 [3412.10992] <2> vnet_same_host: ../../libvlibs/vnet_addrinfo.c.2926: 0: name2 is empty: 0 0x00000000

09:31:19.711 [3412.10992] <4> bptm: emmserver_name = MASTERSERVER

09:31:19.711 [3412.10992] <4> bptm: emmserver_port = 1556

09:31:19.742 [3412.10992] <2> Orb::init: initializing ORB EMMlib_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -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 EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(../Orb.cpp:824)

09:31:19.742 [3412.10992] <2> Orb::init: caching EndpointSelectorFactory(../Orb.cpp:839)

09:31:19.773 [3412.10992] <2> send_brm_msg: PID of bpxm = 3412

09:31:19.773 [3412.10992] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD/6

09:31:19.773 [3412.10992] <2> nbjm_media_request: old_media_id = NULL, media_id = ID1541

09:31:19.773 [3412.10992] <2> Orb::init: Created anon service name: NB_3412_959173040(../Orb.cpp:696)

09:31:19.773 [3412.10992] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_3412_959173040(../Orb.cpp:713)

09:31:19.773 [3412.10992] <2> Orb::init: initializing ORB Default_DAEMON_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -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_3412_959173040 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(../Orb.cpp:824)

09:31:19.773 [3412.10992] <2> Orb::init: caching EndpointSelectorFactory(../Orb.cpp:839)

09:31:19.805 [3412.10992] <2> RequestInitialResources: returning

09:31:19.805 [3412.10992] <2> parse_resource_strings: MEDIADB 1 21941195 ID1541 4001871 ------ 20 1337693495 1338169789 1343280617 0 351951765 149 149 4 5 0 0 1024 0 5499638 0

09:31:19.805 [3412.10992] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters

09:31:19.805 [3412.10992] <2> parse_resource_strings: VOLUME 1 ID1541 4001871 ID1541 OFFSITE IMATION 0D98584440 24 1 0 0 3 {00000000-0000-0000-0000-000000000000} 0

09:31:19.805 [3412.10992] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters

09:31:19.805 [3412.10992] <2> parse_resource_strings: DRIVE 3 BAY13 2000030 HU10551FLA {5,0,0,0} -1 -1 -1 -1 0 3 1 12 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0

09:31:19.805 [3412.10992] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters

09:31:19.805 [3412.10992] <2> parse_resource_strings: STORAGE 1 GSU_MEDIASERVER1_SL8500 20 1048576 2 1 0 0 MEDIASERVER1 MEDIASERVER1 *NULL*

09:31:19.805 [3412.10992] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters

09:31:19.805 [3412.10992] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*

09:31:19.805 [3412.10992] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters

09:31:19.805 [3412.10992] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0

09:31:19.805 [3412.10992] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters

09:31:19.805 [3412.10992] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*

09:31:19.805 [3412.10992] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters

09:31:19.805 [3412.10992] <2> nbjm_media_request: Job control returned to BPTM

09:31:19.805 [3412.10992] <2> drivename_open: Called with Create 1, file BAY13

09:31:19.805 [3412.10992] <2> drivename_checklock: Called

09:31:19.805 [3412.10992] <2> drivename_checklock: File is locked

09:31:19.805 [3412.10992] <2> drivename_lock: lock failed (already locked)

09:31:19.805 [3412.10992] <2> drivename_close: Called for file BAY13

09:31:19.820 [6292.7992] <2> drivename_open: Called with Create 1, file BAY29

09:31:19.820 [6292.7992] <2> drivename_checklock: Called

09:31:19.820 [6292.7992] <2> drivename_checklock: File is locked

09:31:19.820 [6292.7992] <2> drivename_lock: lock failed (already locked)

09:31:19.820 [6292.7992] <2> drivename_close: Called for file BAY29

09:31:20.819 [3412.10992] <2> drivename_open: Called with Create 1, file BAY13

09:31:20.819 [3412.10992] <2> drivename_checklock: Called

09:31:20.819 [3412.10992] <2> drivename_checklock: File is locked

09:31:20.819 [3412.10992] <2> drivename_lock: lock failed (already locked)

09:31:20.819 [3412.10992] <2> drivename_close: Called for file BAY13

09:31:20.834 [6292.7992] <2> drivename_open: Called with Create 1, file BAY29

09:31:20.834 [6292.7992] <2> drivename_checklock: Called

09:31:20.834 [6292.7992] <2> drivename_checklock: File is locked

09:31:20.834 [6292.7992] <2> drivename_lock: lock failed (already locked)

09:31:20.834 [6292.7992] <2> drivename_close: Called for file BAY29

09:31:21.833 [3412.10992] <2> drivename_open: Called with Create 1, file BAY13

09:31:21.833 [3412.10992] <2> drivename_checklock: Called

09:31:21.833 [3412.10992] <2> drivename_checklock: File is locked

09:31:21.833 [3412.10992] <2> drivename_lock: lock failed (already locked)

09:31:21.833 [3412.10992] <2> drivename_close: Called for file BAY13

09:31:21.848 [6292.7992] <2> drivename_open: Called with Create 1, file BAY29

09:31:21.848 [6292.7992] <2> drivename_checklock: Called

09:31:21.848 [6292.7992] <2> drivename_checklock: File is locked

09:31:21.848 [6292.7992] <2> drivename_lock: lock failed (already locked)

09:31:21.848 [6292.7992] <2> drivename_close: Called for file BAY29

09:31:22.847 [3412.10992] <2> drivename_open: Called with Create 1, file BAY13

09:31:22.847 [3412.10992] <2> drivename_checklock: Called

09:31:22.847 [3412.10992] <2> drivename_checklock: File is locked

09:31:22.847 [3412.10992] <2> drivename_lock: lock failed (already locked)

09:31:22.847 [3412.10992] <2> drivename_close: Called for file BAY13

09:31:22.862 [6292.7992] <2> drivename_open: Called with Create 1, file BAY29

09:31:48.197 [3412.10992] <2> drivename_checklock: Called

09:31:48.197 [3412.10992] <2> drivename_checklock: File is locked

09:31:48.197 [3412.10992] <2> drivename_lock: lock failed (already locked)

09:31:48.197 [3412.10992] <2> drivename_close: Called for file BAY13

09:31:48.212 [6292.7992] <2> drivename_open: Called with Create 1, file BAY29

09:31:48.212 [6292.7992] <2> drivename_checklock: Called

09:31:48.212 [6292.7992] <2> drivename_checklock: File is locked

09:31:48.212 [6292.7992] <2> drivename_lock: lock failed (already locked)

09:31:48.212 [6292.7992] <2> drivename_close: Called for file BAY29

09:31:49.211 [3412.10992] <2> drivename_open: Called with Create 1, file BAY13

09:31:49.211 [3412.10992] <2> drivename_checklock: Called

09:31:49.211 [3412.10992] <2> drivename_checklock: File is locked

09:31:49.211 [3412.10992] <2> drivename_lock: lock failed (already locked)

09:31:49.211 [3412.10992] <2> drivename_close: Called for file BAY13

09:31:49.226 [6292.7992] <2> drivename_open: Called with Create 1, file BAY29

09:31:49.226 [6292.7992] <2> drivename_checklock: Called

09:31:49.226 [6292.7992] <2> drivename_checklock: File is locked

09:31:49.226 [6292.7992] <2> drivename_lock: lock failed (already locked)

09:31:49.226 [6292.7992] <2> drivename_close: Called for file BAY29

09:31:50.147 [3916.7984] <2> io_terminate_tape: absolute block position prior to writing empty header is 5499638, copy 2

09:31:50.147 [3916.7984] <2> io_write_back_header: drive index 1, empty_file, file num = 150, mpx_headers = 0, copy 2

09:31:50.147 [3916.7984] <2> io_close: closing D:\Program Files\Veritas\NetBackup\db\media\tpreq\BAY13, from bptm.c.8889

09:31:50.147 [3916.7984] <2> send_MDS_msg: MEDIADB 1 21941195 ID1541 4001871 *NULL* 20 1337693495 1338194570 1343280617 0 351951765 149 149 4 5 0 0 1024 0 5499638 0

09:31:50.162 [3916.7984] <2> openTpreqFile: tpreq_file: D:\Program Files\Veritas\NetBackup\db\media\tpreq\BAY13, serial_num: HU10551FLA

09:31:50.178 [3916.7984] <2> get_drive_path: SCSI coordinates {5,0,0,0}, dos_path \\.\Tape3, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_3-scsi#5&1c4697cf&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}

09:31:50.178 [3916.7984] <2> check_serial_num: serial number match for drive with SCSI coordinates {5,0,0,0}, dos_path \\.\Tape3, drive serial number HU10551FLA, expected serial number HU10551FLA

09:31:50.209 [3916.7984] <2> init_tape: \\.\Tape3 (SCSI coordinates {5,0,0,0}) configured with blocksize 0

09:31:50.225 [3412.10992] <2> drivename_open: Called with Create 1, file BAY13

09:31:50.225 [3412.10992] <2> drivename_checklock: Called

09:31:50.225 [3412.10992] <2> drivename_checklock: File is locked

09:31:50.225 [3412.10992] <2> drivename_lock: lock failed (already locked)

09:31:50.225 [3412.10992] <2> drivename_close: Called for file BAY13

[rizwan84tx]

Are the drives shared to anyother media server? Could be another media server has reserved the drives.

[old_mate]

Hi rizwan84tx, 

Thanks for the reply.

Yes the drives are shared between 2 media servers. The thing is though that data will start to be duplicated, and then just stop. Seems strange that the other media server would be able to override the reservation...

We have a case raised with Symantec so hopefully they'll be able to shed some light on the situation.