Networker keeps going back for the same tape

Also, post a daemon.log part from which request for tape and failure can be seen.

That's strange. Can you post following:
mminfo -av -q volume= -r "volflags,%used,written,state,pool,location,volretent"

Forgot to mention, there is no dynamic drive sharing license, so I only have the use of one drive, because the other is dedicated to ndmp. Not sure if this is relevant.

I was turning off nsrauth on some clients, and was having an authentication issue until I figured out the problem, which I think accounts for those authentication errors in the log.

Here's the daemon log. I included a successful backup to volume 000016, and then the part where that tape was kicked out and 000003 was requested mysteriously. You will see toward the end of the log that the backup of client "devss" is essentially stalled right now. I am showing 92% complete in the NMC monitor, and it is going nowhere at the moment, probably because 000003 is full. Thx for looking:

04/19/07 12:38:13 nsrd: es-bu02.escreen.local:bootstrap done saving to pool 'escreen' (000016) 627 KB
04/19/07 12:38:14 nsrd: savegroup notice: Exchange Servers completed, Total 3 client(s), 1 Succeeded with warning(s), 2 Succeeded. Please see group completion details for more information.
pools supported: escreen;
04/19/07 12:38:47 nsrd: write completion notice: Writing to volume 000016 complete
04/19/07 14:20:04 nsrd: [Jukebox `Scalar24', operation 7]. Initiated operation `operation: "Label"; operation device: "\\.\Tape0"; operation response: "prompt"; operation slots: "23-23"; operation template: "Bar Code Label"; operation volume pool: "escreen"; '.
04/19/07 14:20:07 nsrd: \\.\Tape0 Eject operation in progress
04/19/07 14:22:31 nsrd: \\.\Tape0 Verify label operation in progress
04/19/07 14:49:06 nsrd: shutting down
04/19/07 14:49:06 nsrd: [Jukebox `Scalar24', operation # 7]. Operation `operation: "Label"; operation device: "\\.\Tape0"; operation response: "prompt"; operation slots: "23-23"; operation template: "Bar Code Label"; operation volume pool: "escreen"; ' did not complete before NetWorker shut down.
04/19/07 14:49:06 nsrmmdbd: media db is closed
04/19/07 14:49:06 nsrmmgd: Shut down command has been sent to all known nsrlcpd processes.
04/19/07 14:49:06 nsrmmgd: mgd_clean_remaining_op_locks: operation `Label' [id = 7] did not clean lock on slot 23.
04/19/07 14:49:06 nsrmmgd: mgd_clean_remaining_task_locks: operation `Label' [id = 7] did not clean lock on drive 0.
04/19/07 14:49:06 nsrlcpd #1: Jukebox `Scalar24' is exiting. The jukebox is no longer managed by nsrlcpd.
04/19/07 14:49:26 nsrd: successful shutdown
04/19/07 14:51:30 nsrd: server notice: started
04/19/07 14:51:30 nsrd: Warning: Could not register a deamon key with the authentication daemon. GSS Legato authentication disabled
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:30 nsrexecd: The user does not have the privileges perform the requested operation. Requester: EMCUserNone/es-bu02.escreen.local@(Unknown)
04/19/07 14:51:31 nsrmmdbd: media db is checking btrees
04/19/07 14:51:31 nsrmmdbd: media db is consistency checking the database
04/19/07 14:51:31 nsrmmdbd: media db is open for business
04/19/07 14:51:34 nsrmmgd: Starting nsrmmgd.
04/19/07 14:51:38 nsrd: NetWorker
04/19/07 14:51:38 nsrd: nw_7_3_2_jumbo.Build.386
04/19/07 14:51:38 nsrd: 386
04/19/07 14:51:38 nsrd: Sat Feb 17 12:53:09 2007
04/19/07 14:51:38 nsrd: Build arch.: nt86
04/19/07 14:51:38 nsrd: DBG=0,OPT=
04/19/07 14:51:38 nsrindexd: Running nsrck to check client file indices
04/19/07 14:51:38 nsrmmgd: Started nsrlcpd on host `es-bu02' with command line options '-s es-bu02.escreen.local -N 1 -n 1 '.
04/19/07 14:51:39 nsrd: index notice: checking index for 'devss'
04/19/07 14:51:39 nsrd: index notice: E:\Program Files\Legato\nsr\index\devss contains 536404 records occupying 55 MB
04/19/07 14:51:39 nsrd: index notice: checking index for 'mx4'
04/19/07 14:51:39 nsrd: index notice: E:\Program Files\Legato\nsr\index\mx4 contains 665 records occupying 157 KB
04/19/07 14:51:39 nsrd: index notice: checking index for 'escreen-fs01'
04/19/07 14:51:39 nsrd: index notice: E:\Program Files\Legato\nsr\index\escreen-fs01 contains 794183 records occupying 136 MB
04/19/07 14:51:39 nsrd: index notice: checking index for 'es-bu02.escreen.local'
04/19/07 14:51:39 nsrd: index notice: E:\Program Files\Legato\nsr\index\es-bu02.escreen.local contains 79762 records occupying 9238 KB
04/19/07 14:51:39 nsrd: index notice: checking index for 'escreen-ns02'
04/19/07 14:51:39 nsrd: index notice: E:\Program Files\Legato\nsr\index\escreen-ns02 contains 208465 records occupying 27 MB
04/19/07 14:51:39 nsrd: index notice: checking index for 'tempesfs01'
04/19/07 14:51:39 nsrd: index notice: E:\Program Files\Legato\nsr\index\tempesfs01 contains 960504 records occupying 167 MB
04/19/07 14:51:39 nsrd: index notice: checking index for 'esmx1'
04/19/07 14:51:39 nsrd: index notice: E:\Program Files\Legato\nsr\index\esmx1 contains 66824 records occupying 7960 KB
04/19/07 14:51:39 nsrd: index notice: checking index for 'escreenfin3'
04/19/07 14:51:40 nsrd: index notice: E:\Program Files\Legato\nsr\index\escreenfin3 contains 98665 records occupying 11 MB
04/19/07 14:51:40 nsrd: index notice: checking index for 'escreen-ra01'
04/19/07 14:51:40 nsrd: index notice: E:\Program Files\Legato\nsr\index\escreen-ra01 contains 1295177 records occupying 133 MB
04/19/07 14:51:40 nsrd: index notice: checking index for 'escreen-dc01'
04/19/07 14:51:40 nsrd: index notice: E:\Program Files\Legato\nsr\index\escreen-dc01 contains 187223 records occupying 24 MB
04/19/07 14:51:40 nsrd: index notice: checking index for 'escreenoltp4'
04/19/07 14:51:40 nsrd: index notice: E:\Program Files\Legato\nsr\index\escreenoltp4 contains 29071 records occupying 3522 KB
04/19/07 14:51:40 nsrd: index notice: Completed checking 11 client(s)
04/19/07 14:51:40 nsrlcpd #1: Starting program `nsrlcpd #1', with process ID 3500, on HOST es-bu02.escreen.local.
04/19/07 14:51:43 nsrlcpd #1: Creating Jukebox `Scalar24'
04/19/07 14:51:45 nsrlcpd #1: Configuring Jukebox `Scalar24'
04/19/07 14:51:47 nsrd: NetWork Edition
04/19/07 14:51:47 nsrd: License Summary:
04/19/07 14:51:47 nsrd: Available: sv=35, ws=0, clu=1, clu_nt=0, clu_unix=0, clu_linux=0, ndmp=1
04/19/07 14:51:47 nsrd: Borrowed: sv_borrowed=0, clu_borrowed_nt=1, clu_borrowed_unix=0, clu_borrowed_linux=0
04/19/07 14:51:47 nsrd: Remaining: sv=27, ws=0, clu=0, clu_nt=0, clu_unix=0, clu_linux=0, ndmp=0
04/19/07 14:51:47 nsrd: Connected Servers: (8)
04/19/07 14:51:47 nsrd: devss es-bu02.escreen.local escreen-dc01 escreen-fs01 escreen-ns02 escreen-ra01 escreenfin3 escreenoltp4
04/19/07 14:51:47 nsrd: Connected NT Clusters: (1)
04/19/07 14:51:47 nsrd: esmx1
04/19/07 14:51:47 nsrd: Connected NDMP: (1)
04/19/07 14:51:47 nsrd: tempesfs01
04/19/07 14:51:47 nsrd: NetWorker Module for Microsoft Exchange Server: Available=1, Remaining=1, Used=0
04/19/07 14:51:59 nsrmmd #1: Start nsrmmd #1, with PID 3924, at HOST es-bu02.escreen.local
04/19/07 14:52:01 nsrmmd #2: Start nsrmmd #2, with PID 4036, at HOST es-bu02.escreen.local
04/19/07 14:52:25 nsrd: media info: Jukebox `Scalar24' Hardware status of jukebox 'Scalar24' is 'ready'
04/19/07 16:02:14 nsrd: savegroup info: starting MiscServers (with 2 client(s))
04/19/07 16:02:18 nsrd: Operation 1 started : Load volume `000003'.
.
04/19/07 16:02:18 nsrd: media waiting event: Waiting for 1 writable volumes to backup pool 'escreen' tape(s) on es-bu02.escreen.local
04/19/07 16:02:19 nsrd: [Jukebox `Scalar24', operation # 1]. Cannot find an available nsrmmd service for operation on device '\\.\Tape0'. Try again.
04/19/07 16:02:19 nsrmmgd: Cannot find an available nsrmmd service for operation on device '\\.\Tape0'. Try again.
04/19/07 16:02:20 nsrmmd #3: Start nsrmmd #3, with PID 3336, at HOST es-bu02.escreen.local
04/19/07 16:02:22 nsrmmgd: Jukebox `Scalar24' failed to load the requested volume.
04/19/07 16:02:25 nsrd: [Jukebox `Scalar24', operation # 1]. Finished with status: retryable
04/19/07 16:02:25 nsrmmgd: RAP error: Invalid resource data.
04/19/07 16:02:25 nsrmmgd: Cannot update operation status resource (instance 1).

04/19/07 16:02:28 nsrd: Operation 2 started : Load volume `000003'.
.
04/19/07 16:02:29 nsrd: \\.\Tape0 Eject operation in progress
04/19/07 16:03:47 nsrd: \\.\Tape0 Verify label operation in progress
04/19/07 16:03:50 nsrd: \\.\Tape0 Mount operation in progress
04/19/07 16:04:52 nsrd: media event cleared: Waiting for 1 writable volumes to backup pool 'escreen' tape(s) on es-bu02.escreen.local
04/19/07 16:04:52 nsrd: devss:SYSTEM DB:\ saving to pool 'escreen' (000003)
04/19/07 16:04:52 nsrd: devss:SYSTEM FILES:\ saving to pool 'escreen' (000003)
04/19/07 16:04:52 nsrd: devss:C:\ saving to pool 'escreen' (000003)
04/19/07 16:04:52 nsrd: devss:SYSTEM STATE:\ saving to pool 'escreen' (000003)
04/19/07 16:04:55 nsrd: [Jukebox `Scalar24', operation # 2]. Finished with status: succeeded
04/19/07 16:04:55 nsrd: devss:SYSTEM STATE:\ done saving to pool 'escreen' (000003) 12 MB
04/19/07 16:04:56 nsrd: devss:SYSTEM DB:\ done saving to pool 'escreen' (000003) 164 KB
pools supported: escreen;
04/19/07 16:04:59 nsrd: escreen-fs01:SYSTEM STATE:\ saving to pool 'escreen' (000003)
04/19/07 16:04:59 nsrd: escreen-fs01:SYSTEM DB:\ saving to pool 'escreen' (000003)
04/19/07 16:05:13 nsrd: escreen-fs01:SYSTEM STATE:\ done saving to pool 'escreen' (000003) 13 MB
04/19/07 16:05:16 nsrd: escreen-fs01:SYSTEM DB:\ done saving to pool 'escreen' (000003) 843 KB
04/19/07 16:05:19 nsrd: escreen-fs01:I:\ saving to pool 'escreen' (000003)
04/19/07 16:05:19 nsrd: escreen-fs01:J:\ saving to pool 'escreen' (000003)
04/19/07 16:05:57 nsrd: devss:SYSTEM FILES:\ done saving to pool 'escreen' (000003) 230 MB
04/19/07 16:05:59 nsrd: escreen-fs01:H:\ saving to pool 'escreen' (000003)
04/19/07 16:11:46 nsrd: warning: pool `escreen' changed while server is busy.
04/19/07 16:18:35 nsrd: escreen-fs01:H:\ done saving to pool 'escreen' (000003) 2896 MB
04/19/07 16:18:45 nsrd: escreen-fs01:G:\ saving to pool 'escreen' (000003)
04/19/07 16:28:49 nsrd: escreen-fs01:G:\ done saving to pool 'escreen' (000003) 4532 MB
04/19/07 16:28:49 savegrp: job (614) host: escreen-fs01 savepoint: G:\ had ERROR indication(s) at completion.
04/19/07 16:28:49 savegrp: escreen-fs01:G:\ failed.
04/19/07 16:28:57 nsrd: escreen-fs01:E:\ saving to pool 'escreen' (000003)
04/19/07 16:39:49 nsrd: escreen-fs01:I:\ done saving to pool 'escreen' (000003) 14 GB
04/19/07 16:39:58 nsrd: escreen-fs01:C:\ saving to pool 'escreen' (000003)
04/19/07 16:44:22 nsrd: escreen-fs01:C:\ done saving to pool 'escreen' (000003) 775 MB
04/19/07 16:44:22 savegrp: job (616) host: escreen-fs01 savepoint: C:\ had WARNING indication(s) at completion.
04/19/07 16:44:25 nsrd: escreen-fs01:SYSTEM FILES:\ saving to pool 'escreen' (000003)
04/19/07 16:45:43 nsrd: escreen-fs01:SYSTEM FILES:\ done saving to pool 'escreen' (000003) 234 MB
04/19/07 16:54:10 nsrd: escreen-fs01:J:\ done saving to pool 'escreen' (000003) 21 GB
04/19/07 16:54:10 savegrp: job (611) host: escreen-fs01 savepoint: J:\ had WARNING indication(s) at completion.
04/19/07 17:00:14 nsrd: devss:C:\ done saving to pool 'escreen' (000003) 4030 MB
04/19/07 17:00:14 savegrp: job (607) host: devss savepoint: C:\ had WARNING indication(s) at completion.
04/19/07 17:00:16 nsrd: es-bu02.escreen.local:index:devss saving to pool 'escreen' (000003)
04/19/07 17:00:21 nsrd: es-bu02.escreen.local:index:devss done saving to pool 'escreen' (000003) 62 MB

Ok, here's the mminfo for volume 000003, which is the tape that keeps getting pulled in:

C:\WINDOWS\system32>mminfo -av -q volume=000003 -r "volflags,%used,written,state,pool,location,volretent"
flags (%) written pool location expires
d 100% 1191 GB escreen Scalar24 4/19/2008

What I see is that 000016 was done with accepting data and then someone decided to label tape from slot 23. Not sure why, but that thing never finished and server was restarted (was that you?). Since tape was left in messy state next backup requested new tape and the one from 23rd slot was kicked out and 000003 was loaded. You may wonder why 000003 and not 000016? It is possible that both tapes are appendable and NW will balance its decision which one to load (probably the one wild older last mount time or smaller mount count or something like that).

Question to ask really is what went wrong with labeling of tape from slot 23. What is possible, I can't be sure, is that labeling process was waiting for confirmation which never was given.

Yes, I did run a re-label and skewed that log. My bad. I will set up the scenario where I saw the problem crop up again, and capture a cleaner log sample for you.

I guess I still don't understand why at the end, when 000003 ran out of capacity, Networker didn't unmount that volume and load up a new one. I have a support call going with EMC but they haven't called me back for a day, so thought I would consult the forums.

Message was edited by:
glhooper

That is not visible from log you have pasted here, but support might have figure out by now