SLP Duplications Hanging

Question

&nbsp;
NBU Master: 7.1.0.2 (Windows)
Media Servers: 7.1.0.2 (Windows)
&nbsp;
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 &lt;Media Server&gt;. It’s mainly happening on two of our LTO3 drives (ACS), but has occurred on all of them.&nbsp;
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!
&nbsp;
&nbsp;
09:31:19.711 [3412.10992] &lt;2&gt; 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] &lt;2&gt; vnet_same_host: ../../libvlibs/vnet_addrinfo.c.2926: 0: name2 is empty: 0 0x00000000
09:31:19.711 [3412.10992] &lt;4&gt; bptm: emmserver_name = MASTERSERVER
09:31:19.711 [3412.10992] &lt;4&gt; bptm: emmserver_port = 1556
09:31:19.742 [3412.10992] &lt;2&gt; 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] &lt;2&gt; Orb::init: caching EndpointSelectorFactory(../Orb.cpp:839)
09:31:19.773 [3412.10992] &lt;2&gt; send_brm_msg: PID of bpxm = 3412
09:31:19.773 [3412.10992] &lt;2&gt; nbjm_media_request: Passing job control to NBJM, type UNLOAD/6
09:31:19.773 [3412.10992] &lt;2&gt; nbjm_media_request: old_media_id = NULL, media_id = ID1541
09:31:19.773 [3412.10992] &lt;2&gt; Orb::init: Created anon service name: NB_3412_959173040(../Orb.cpp:696)
09:31:19.773 [3412.10992] &lt;2&gt; Orb::init: endpointvalue is : pbxiop://1556:NB_3412_959173040(../Orb.cpp:713)
09:31:19.773 [3412.10992] &lt;2&gt; 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] &lt;2&gt; Orb::init: caching EndpointSelectorFactory(../Orb.cpp:839)
09:31:19.805 [3412.10992] &lt;2&gt; RequestInitialResources: returning
09:31:19.805 [3412.10992] &lt;2&gt; 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] &lt;2&gt; parse_resource_strings: Parsed message type 15, version 1, 21 parameters
09:31:19.805 [3412.10992] &lt;2&gt; 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] &lt;2&gt; parse_resource_strings: Parsed message type 16, version 1, 14 parameters
09:31:19.805 [3412.10992] &lt;2&gt; 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] &lt;2&gt; parse_resource_strings: Parsed message type 17, version 3, 23 parameters
09:31:19.805 [3412.10992] &lt;2&gt; parse_resource_strings: STORAGE 1 GSU_MEDIASERVER1_SL8500 20 1048576 2 1 0 0 MEDIASERVER1 MEDIASERVER1 *NULL*
09:31:19.805 [3412.10992] &lt;2&gt; parse_resource_strings: Parsed message type 18, version 1, 11 parameters
09:31:19.805 [3412.10992] &lt;2&gt; parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
09:31:19.805 [3412.10992] &lt;2&gt; parse_resource_strings: Parsed message type 21, version 0, 7 parameters
09:31:19.805 [3412.10992] &lt;2&gt; parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
09:31:19.805 [3412.10992] &lt;2&gt; parse_resource_strings: Parsed message type 22, version 0, 6 parameters
09:31:19.805 [3412.10992] &lt;2&gt; parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
09:31:19.805 [3412.10992] &lt;2&gt; parse_resource_strings: Parsed message type 23, version 0, 3 parameters
09:31:19.805 [3412.10992] &lt;2&gt; nbjm_media_request: Job control returned to BPTM
09:31:19.805 [3412.10992] &lt;2&gt; drivename_open: Called with Create 1, file BAY13
09:31:19.805 [3412.10992] &lt;2&gt; drivename_checklock: Called
09:31:19.805 [3412.10992] &lt;2&gt; drivename_checklock: File is locked
09:31:19.805 [3412.10992] &lt;2&gt; drivename_lock: lock failed (already locked)
09:31:19.805 [3412.10992] &lt;2&gt; drivename_close: Called for file BAY13
09:31:19.820 [6292.7992] &lt;2&gt; drivename_open: Called with Create 1, file BAY29
09:31:19.820 [6292.7992] &lt;2&gt; drivename_checklock: Called
09:31:19.820 [6292.7992] &lt;2&gt; drivename_checklock: File is locked
09:31:19.820 [6292.7992] &lt;2&gt; drivename_lock: lock failed (already locked)
09:31:19.820 [6292.7992] &lt;2&gt; drivename_close: Called for file BAY29
09:31:20.819 [3412.10992] &lt;2&gt; drivename_open: Called with Create 1, file BAY13
09:31:20.819 [3412.10992] &lt;2&gt; drivename_checklock: Called
09:31:20.819 [3412.10992] &lt;2&gt; drivename_checklock: File is locked
09:31:20.819 [3412.10992] &lt;2&gt; drivename_lock: lock failed (already locked)
09:31:20.819 [3412.10992] &lt;2&gt; drivename_close: Called for file BAY13
09:31:20.834 [6292.7992] &lt;2&gt; drivename_open: Called with Create 1, file BAY29
09:31:20.834 [6292.7992] &lt;2&gt; drivename_checklock: Called
09:31:20.834 [6292.7992] &lt;2&gt; drivename_checklock: File is locked
09:31:20.834 [6292.7992] &lt;2&gt; drivename_lock: lock failed (already locked)
09:31:20.834 [6292.7992] &lt;2&gt; drivename_close: Called for file BAY29
09:31:21.833 [3412.10992] &lt;2&gt; drivename_open: Called with Create 1, file BAY13
09:31:21.833 [3412.10992] &lt;2&gt; drivename_checklock: Called
09:31:21.833 [3412.10992] &lt;2&gt; drivename_checklock: File is locked
09:31:21.833 [3412.10992] &lt;2&gt; drivename_lock: lock failed (already locked)
09:31:21.833 [3412.10992] &lt;2&gt; drivename_close: Called for file BAY13
09:31:21.848 [6292.7992] &lt;2&gt; drivename_open: Called with Create 1, file BAY29
09:31:21.848 [6292.7992] &lt;2&gt; drivename_checklock: Called
09:31:21.848 [6292.7992] &lt;2&gt; drivename_checklock: File is locked
09:31:21.848 [6292.7992] &lt;2&gt; drivename_lock: lock failed (already locked)
09:31:21.848 [6292.7992] &lt;2&gt; drivename_close: Called for file BAY29
09:31:22.847 [3412.10992] &lt;2&gt; drivename_open: Called with Create 1, file BAY13
09:31:22.847 [3412.10992] &lt;2&gt; drivename_checklock: Called
09:31:22.847 [3412.10992] &lt;2&gt; drivename_checklock: File is locked
09:31:22.847 [3412.10992] &lt;2&gt; drivename_lock: lock failed (already locked)
09:31:22.847 [3412.10992] &lt;2&gt; drivename_close: Called for file BAY13
09:31:22.862 [6292.7992] &lt;2&gt; drivename_open: Called with Create 1, file BAY29
09:31:48.197 [3412.10992] &lt;2&gt; drivename_checklock: Called
09:31:48.197 [3412.10992] &lt;2&gt; drivename_checklock: File is locked
09:31:48.197 [3412.10992] &lt;2&gt; drivename_lock: lock failed (already locked)
09:31:48.197 [3412.10992] &lt;2&gt; drivename_close: Called for file BAY13
09:31:48.212 [6292.7992] &lt;2&gt; drivename_open: Called with Create 1, file BAY29
09:31:48.212 [6292.7992] &lt;2&gt; drivename_checklock: Called
09:31:48.212 [6292.7992] &lt;2&gt; drivename_checklock: File is locked
09:31:48.212 [6292.7992] &lt;2&gt; drivename_lock: lock failed (already locked)
09:31:48.212 [6292.7992] &lt;2&gt; drivename_close: Called for file BAY29
09:31:49.211 [3412.10992] &lt;2&gt; drivename_open: Called with Create 1, file BAY13
09:31:49.211 [3412.10992] &lt;2&gt; drivename_checklock: Called
09:31:49.211 [3412.10992] &lt;2&gt; drivename_checklock: File is locked
09:31:49.211 [3412.10992] &lt;2&gt; drivename_lock: lock failed (already locked)
09:31:49.211 [3412.10992] &lt;2&gt; drivename_close: Called for file BAY13
09:31:49.226 [6292.7992] &lt;2&gt; drivename_open: Called with Create 1, file BAY29
09:31:49.226 [6292.7992] &lt;2&gt; drivename_checklock: Called
09:31:49.226 [6292.7992] &lt;2&gt; drivename_checklock: File is locked
09:31:49.226 [6292.7992] &lt;2&gt; drivename_lock: lock failed (already locked)
09:31:49.226 [6292.7992] &lt;2&gt; drivename_close: Called for file BAY29
09:31:50.147 [3916.7984] &lt;2&gt; io_terminate_tape: absolute block position prior to writing empty header is 5499638, copy 2
09:31:50.147 [3916.7984] &lt;2&gt; io_write_back_header: drive index 1, empty_file, file num = 150, mpx_headers = 0, copy 2
09:31:50.147 [3916.7984] &lt;2&gt; io_close: closing D:\Program Files\Veritas\NetBackup\db\media	preq\BAY13, from bptm.c.8889
09:31:50.147 [3916.7984] &lt;2&gt; 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] &lt;2&gt; openTpreqFile: tpreq_file: D:\Program Files\Veritas\NetBackup\db\media	preq\BAY13, serial_num: HU10551FLA
09:31:50.178 [3916.7984] &lt;2&gt; get_drive_path: SCSI coordinates {5,0,0,0}, dos_path \.\Tape3, pnp_path \?\scsi#sequential&amp;ven_hp&amp;prod_ultrium_3-scsi#5&amp;1c4697cf&amp;0&amp;000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
09:31:50.178 [3916.7984] &lt;2&gt; 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] &lt;2&gt; init_tape: \.\Tape3 (SCSI coordinates {5,0,0,0}) configured with blocksize 0
09:31:50.225 [3412.10992] &lt;2&gt; drivename_open: Called with Create 1, file BAY13
09:31:50.225 [3412.10992] &lt;2&gt; drivename_checklock: Called
09:31:50.225 [3412.10992] &lt;2&gt; drivename_checklock: File is locked
09:31:50.225 [3412.10992] &lt;2&gt; drivename_lock: lock failed (already locked)
09:31:50.225 [3412.10992] &lt;2&gt; drivename_close: Called for file BAY13

rizwan84tx · Answer

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

old_mate · Answer

Hi rizwan84tx,&nbsp;
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.

Forum Discussion

SLP Duplications Hanging

Related Content

Duplications randomly appear to hang

SLP Policy Name List

SLP Duplication Operation

SLP Duplications

SLP won't start duplications

Recent Discussions

Same Media server, new storage

NBU security questions

NBInstallAnswer file CLIENT silent install

AIR replication – restart of the replication job, deduplication

Best ways to revocer a virtual domain controller