When posting PLEASE INCLUDE YOUR SERVER platform & version. If you have recently upgraded to TSM 5.3.x, it may be IC47584.
I have a PMR open and am hoping to get a test fix shortly. While annoying, it appears to be harmless. Try cleaning up that volume by doing a MOVE DATA instead of a reclamation. If that doesn't work, see if it is continually trying to mount the same output tape. If so, mark that tape as READONLY until you get past this problem. In every case, by simply changing the combination of input/output tapes, I've been able to get past it. (But then it just pops up in another place a few days later.) I am TSM 5.2.3.0 on Windows. Wanda Prather "I/O, I/O, It's all about I/O" -(me) -----Original Message----- From: ADSM: Dist Stor Manager [mailto:[EMAIL PROTECTED] On Behalf Of Dennis Melburn W IT743 Sent: Monday, November 21, 2005 9:06 AM To: ADSM-L@VM.MARIST.EDU Subject: Errors when running Space Reclamation I have been recieving Space Reclamation Failures on my TSM server lately and I am not sure why. When I go back to the time of the events, I get the following ANR9999D log report: (sorry for the length of the report, but I figured it would be best to include it all) 11/20/2005 15:59:12 ANR8337I LTO volume A00541 mounted in drive LTODRV13 (mt4.3.1.3). (SESSION: 25342) 11/20/2005 15:59:12 ANR0510I Session 25342 opened input volume A00541. (SESSION: 25342) 11/20/2005 16:00:28 ANR9999D afmove.c(5788): ThreadId<43> Unexpected result code (45) from ssCopy. (SESSION: 25342) 11/20/2005 16:00:28 ANR9999D ThreadId<43> issued message 9999 from: (SESSION: 25342) 11/20/2005 16:00:28 (43) Context report (SESSION: 25342) 11/20/2005 16:00:29 (43) Thread SsAuxSinkThread (45) is a child thread related to: 43 (SESSION: 25342) 11/20/2005 16:00:29 (45) Generating TM Context Report: (struct=tmTxnDesc) (slots=256) (SESSION: 25342) 11/20/2005 16:00:29 (45) *** no transactions found *** (SESSION: 25342) 11/20/2005 16:00:29 (45) Generating Database Transaction Table Context: (SESSION: 25342) 11/20/2005 16:00:29 (45) *** no transactions found *** (SESSION: 25342) 11/20/2005 16:00:29 (45) Generating SM Context Report: (SESSION: 25342) 11/20/2005 16:00:29 (45) *** no sessions found *** (SESSION: 25342) 11/20/2005 16:00:29 (45) Generating AS Vol Context Report: (SESSION: 25342) 11/20/2005 16:00:29 (45) No mounted (or mount in progress) volumes. (SESSION: 25342) 11/20/2005 16:00:29 (45) Failed attempt #1 to get SSV->mutex (SESSION: 25342) 11/20/2005 16:00:29 (45) Generating ssSession Context Report: (SESSION: 25342) 11/20/2005 16:00:29 (45) No storage service sessions active. (SESSION: 25342) 11/20/2005 16:00:29 (45) Generating ssOpenSeg Context Report: (SESSION: 25342) 11/20/2005 16:00:29 (45) No storage service segments found. (SESSION: 25342) 11/20/2005 16:00:29 (45) Generating BF Copy Control Context Report: (SESSION: 25342) 11/20/2005 16:00:29 (45) No global copy control blocks. (SESSION: 25342) 11/20/2005 16:00:29 (SESSION: 25342) 11/20/2005 16:00:29 (43) Thread SsAuxSrcThread (46) is a child thread related to: 43 (SESSION: 25342) 11/20/2005 16:00:29 (46) Generating TM Context Report: (struct=tmTxnDesc) (slots=256) (SESSION: 25342) 11/20/2005 16:00:29 (46) *** no transactions found *** (SESSION: 25342) 11/20/2005 16:00:29 (46) Generating Database Transaction Table Context: (SESSION: 25342) 11/20/2005 16:00:29 (46) Tsn=0:160675859 --> Valid=1, inRollback=0, endNTA=0, State=2, Index=3, LatchCount=0, SavePoint=0, TotLogRecs=0, TotLogBytes=0, UndoLogRecs=0, UndoLogBytes=0, LogReserve=0, PageReserve=0, Elapsed=99 (secs), MinLsn=0.0.0, MaxLsn=0.0.0, LastLsn=0.0.0, UndoNextLsn=0.0.0, logWriter=False, backupTxn=False (SESSION: 25342) 11/20/2005 16:00:29 (46) Open objects: (SESSION: 25342) 11/20/2005 16:00:29 (46) name ->AF.Damaged<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:29 (46) name ->BF.Aggregate.Attributes<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:29 (46) name ->AF.Vol.Segments<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:29 (46) name ->Restore.Sessions<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:29 (46) name ->Collocation.Group.Member<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:29 (46) name ->AF.Vol.Clusters<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:29 (46) name ->AS.Volume.Status<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:29 (46) name ->AF.Segments<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:29 (46) name ->AF.Bitfiles<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:29 (46) name ->AF.Vol.Partial.Bitfiles<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:29 (46) name ->SS.Volume.Names<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:29 (46) name ->SS.Volume.Ids<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:29 (46) *** no transactions found *** (SESSION: 25342) 11/20/2005 16:00:29 (46) Generating SM Context Report: (SESSION: 25342) 11/20/2005 16:00:29 (46) *** no sessions found *** (SESSION: 25342) 11/20/2005 16:00:29 (46) Generating AS Vol Context Report: (SESSION: 25342) 11/20/2005 16:00:29 (46) Mounted (or mount in progress) volumes: (SESSION: 25342) 11/20/2005 16:00:29 (46) Volume A00541(16084) --> SessId=10414, Server=BACKUP1 Mode=Input, Use=Bitfile, ClassId=1, ClassName=LTO2CLASS, IsScratch=True, VolSeqNum=0, Pool=ORL-DMNO-TAPE(16), Allocated=False, NextSeqNum=640, PosUncertain=True, Open=True, OpenInProg=False, OpenFailed= False, MountMode=Read-only, Reuse=Remove, IsFirstMount=False, IsEmpty=False, IsNewScratch=False, PreemptAccess=False, Waiters=0, TwoSided=False, SideSeqNum=-1, status=ACTIVE (SESSION: 25342) 11/20/2005 16:00:29 (46) Failed attempt #1 to get SSV->mutex (SESSION: 25342) 11/20/2005 16:00:29 (46) Generating ssSession Context Report: (SESSION: 25342) 11/20/2005 16:00:29 (46) No storage service sessions active. (SESSION: 25342) 11/20/2005 16:00:29 (46) Generating ssOpenSeg Context Report: (SESSION: 25342) 11/20/2005 16:00:29 (46) No storage service segments found. (SESSION: 25342) 11/20/2005 16:00:29 (46) Generating BF Copy Control Context Report: (SESSION: 25342) 11/20/2005 16:00:29 (46) No global copy control blocks. (SESSION: 25342) 11/20/2005 16:00:29 (SESSION: 25342) 11/20/2005 16:00:29 (43) Thread AgentThread (41) is a grandchild thread related to: 45 (SESSION: 25342) 11/20/2005 16:00:30 (41) Generating TM Context Report: (struct=tmTxnDesc) (slots=256) (SESSION: 25342) 11/20/2005 16:00:30 (41) *** no transactions found *** (SESSION: 25342) 11/20/2005 16:00:30 (41) Generating Database Transaction Table Context: (SESSION: 25342) 11/20/2005 16:00:30 (41) Tsn=0:160675983 --> Valid=1, inRollback=0, endNTA=0, State=2, Index=0, LatchCount=0, SavePoint=0, TotLogRecs=360, TotLogBytes=81512, UndoLogRecs=350, UndoLogBytes=80952, LogReserve=0, PageReserve=0, Elapsed=11 (secs), MinLsn=1226851.241.3647, MaxLsn=1226852.20.3872, LastLsn=1226852.20.3872, UndoNextLsn=0.0.0, logWriter=False, backupTxn=False (SESSION: 25342) 11/20/2005 16:00:30 (41) Open objects: (SESSION: 25342) 11/20/2005 16:00:30 (41) name ->AF.Vol.Clusters<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:30 (41) name ->AF.Clusters<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:30 (41) name ->AF.Vol.Partial.Bitfiles<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:30 (41) name ->AF.Vol.Segments<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:30 (41) name ->AF.Segments<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:30 (41) name ->BF.Aggregate.Attributes<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:30 (41) name ->AF.Bitfiles<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:30 (41) name ->AS.Segments<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:30 (41) name ->SS.Pools<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:30 (41) name ->SS.Pool.Ids<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:30 (41) *** no transactions found *** (SESSION: 25342) 11/20/2005 16:00:30 (41) Generating SM Context Report: (SESSION: 25342) 11/20/2005 16:00:30 (41) *** no sessions found *** (SESSION: 25342) 11/20/2005 16:00:30 (41) Generating AS Vol Context Report: (SESSION: 25342) 11/20/2005 16:00:30 (41) No mounted (or mount in progress) volumes. (SESSION: 25342) 11/20/2005 16:00:30 (41) Failed attempt #1 to get SSV->mutex (SESSION: 25342) 11/20/2005 16:00:30 (41) Generating ssSession Context Report: (SESSION: 25342) 11/20/2005 16:00:30 (41) No storage service sessions active. (SESSION: 25342) 11/20/2005 16:00:30 (41) Generating ssOpenSeg Context Report: (SESSION: 25342) 11/20/2005 16:00:30 (41) No storage service segments found. (SESSION: 25342) 11/20/2005 16:00:30 (41) Generating BF Copy Control Context Report: (SESSION: 25342) 11/20/2005 16:00:30 (41) No global copy control blocks. (SESSION: 25342) 11/20/2005 16:00:30 (SESSION: 25342) 11/20/2005 16:00:30 (43) Thread AgentThread (47) is a grandchild thread related to: 46 (SESSION: 25342) 11/20/2005 16:00:30 (47) Generating TM Context Report: (struct=tmTxnDesc) (slots=256) (SESSION: 25342) 11/20/2005 16:00:30 (47) *** no transactions found *** (SESSION: 25342) 11/20/2005 16:00:30 (47) Generating Database Transaction Table Context: (SESSION: 25342) 11/20/2005 16:00:30 (47) *** no transactions found *** (SESSION: 25342) 11/20/2005 16:00:30 (47) Generating SM Context Report: (SESSION: 25342) 11/20/2005 16:00:30 (47) *** no sessions found *** (SESSION: 25342) 11/20/2005 16:00:30 (47) Generating AS Vol Context Report: (SESSION: 25342) 11/20/2005 16:00:30 (47) No mounted (or mount in progress) volumes. (SESSION: 25342) 11/20/2005 16:00:30 (47) Failed attempt #1 to get SSV->mutex (SESSION: 25342) 11/20/2005 16:00:30 (47) Generating ssSession Context Report: (SESSION: 25342) 11/20/2005 16:00:30 (47) No storage service sessions active. (SESSION: 25342) 11/20/2005 16:00:30 (47) Generating ssOpenSeg Context Report: (SESSION: 25342) 11/20/2005 16:00:30 (47) No storage service segments found. (SESSION: 25342) 11/20/2005 16:00:30 (47) Generating BF Copy Control Context Report: (SESSION: 25342) 11/20/2005 16:00:30 (47) No global copy control blocks. (SESSION: 25342) 11/20/2005 16:00:31 (SESSION: 25342) 11/20/2005 16:00:31 (43) Thread AfReclamationAgent (66) is a parent thread related to: 43 (SESSION: 25342) 11/20/2005 16:00:31 (66) Generating TM Context Report: (struct=tmTxnDesc) (slots=256) (SESSION: 25342) 11/20/2005 16:00:31 (66) slot -> 14: (SESSION: 25342) 11/20/2005 16:00:31 (66) Tsn=0:160675854, Resurrected=False, InFlight=True, Distributed=False (SESSION: 25342) 11/20/2005 16:00:31 (66) Participants=0, summaryVote=ReadOnly (SESSION: 25342) 11/20/2005 16:00:31 (66) Generating Database Transaction Table Context: (SESSION: 25342) 11/20/2005 16:00:31 (66) *** no transactions found *** (SESSION: 25342) 11/20/2005 16:00:31 (66) Generating SM Context Report: (SESSION: 25342) 11/20/2005 16:00:31 (66) *** no sessions found *** (SESSION: 25342) 11/20/2005 16:00:31 (66) Generating AS Vol Context Report: (SESSION: 25342) 11/20/2005 16:00:31 (66) No mounted (or mount in progress) volumes. (SESSION: 25342) 11/20/2005 16:00:31 (66) Generating ssSession Context Report: (SESSION: 25342) 11/20/2005 16:00:31 (66) Storage Service Sessions: (SESSION: 25342) 11/20/2005 16:00:31 (66) Session 10414 --> BufConfig=XLarge, TransBufSize=262144, SplitBuf=False, WrCount=32768, WrBufIsEmpty=False, WrBufIsFull=False, SourceRc=45, SinkRc=45, Aux_1Created=True, Aux_1Begin=False, Aux_1Idle=True, Aux_1Terminate=False, Aux_2Created=True, Aux_2Begin=False, Aux_2Idle=True, Aux_2Terminate=False (SESSION: 25342) 11/20/2005 16:00:31 (66) Leased Volumes:(SESSION: 25342) 11/20/2005 16:00:31 (66) A00541(16084)(Access)(SESSION: 25342) 11/20/2005 16:00:31 (SESSION: 25342) 11/20/2005 16:00:31 (66) Excluded VolIds:(SESSION: 25342) 11/20/2005 16:00:31 (66) 16084(SESSION: 25342) 11/20/2005 16:00:31 (SESSION: 25342) 11/20/2005 16:00:31 (66) AS Extension: WrMpClassId=1, RdMpClassId=1, ForceRelease=False. (SESSION: 25342) 11/20/2005 16:00:31 (SESSION: 25342) 11/20/2005 16:00:31 (66) Generating ssOpenSeg Context Report: (SESSION: 25342) 11/20/2005 16:00:31 (66) No storage service segments found. (SESSION: 25342) 11/20/2005 16:00:31 (66) Generating BF Copy Control Context Report: (SESSION: 25342) 11/20/2005 16:00:31 (66) No global copy control blocks. (SESSION: 25342) 11/20/2005 16:00:31 (66) procNum=501, status=Volume A00541 (storage pool ORL-DMNO-TAPE), Moved Files: 0, Moved Bytes: 0, Unreadable Files: 0, Unreadable Bytes: 0. Current Physical File (bytes): 1,350,673 Current input volume: A00541. , cancelInProgress=False (SESSION: 25342) 11/20/2005 16:00:31 (66) descr=Space Reclamation, name=SPACE RECLAMATION, cancelled=False (SESSION: 25342) 11/20/2005 16:00:31 (SESSION: 25342) 11/20/2005 16:00:31 (43) AfRclmVolumeThread : ANR9999D calling thread (SESSION: 25342) 11/20/2005 16:00:31 (43) Generating TM Context Report: (struct=tmTxnDesc) (slots=256) (SESSION: 25342) 11/20/2005 16:00:31 (43) slot -> 19: (SESSION: 25342) 11/20/2005 16:00:31 (43) Tsn=0:160675859, Resurrected=False, InFlight=True, Distributed=False (SESSION: 25342) 11/20/2005 16:00:31 (43) Participants=1, summaryVote=ReadOnly (SESSION: 25342) 11/20/2005 16:00:31 Participant DB: voteReceived=False, ackReceived=False (SESSION: 25342) 11/20/2005 16:00:31 (43) slot -> 26: (SESSION: 25342) 11/20/2005 16:00:31 (43) Tsn=0:160675866, Resurrected=False, InFlight=True, Distributed=False (SESSION: 25342) 11/20/2005 16:00:31 (43) Participants=3, summaryVote=ReadOnly (SESSION: 25342) 11/20/2005 16:00:31 Participant DB: voteReceived=False, ackReceived=False (SESSION: 25342) 11/20/2005 16:00:31 Participant BF: voteReceived=False, ackReceived=False (SESSION: 25342) 11/20/2005 16:00:31 Participant SS: voteReceived=False, ackReceived=False (SESSION: 25342) 11/20/2005 16:00:31 Locks held by Tsn=0:160675866 : (SESSION: 25342) 11/20/2005 16:00:31 Type=34040, NameSpace=16084, SummMode=xLock, Mode=xLock, Key='179.0' (SESSION: 25342) 11/20/2005 16:00:31 (43) Generating Database Transaction Table Context: (SESSION: 25342) 11/20/2005 16:00:31 (43) Tsn=0:160674098 --> Valid=1, inRollback=0, endNTA=0, State=2, Index=5, LatchCount=0, SavePoint=0, TotLogRecs=0, TotLogBytes=0, UndoLogRecs=0, UndoLogBytes=0, LogReserve=0, PageReserve=0, Elapsed=3623 (secs), MinLsn=0.0.0, MaxLsn=0.0.0, LastLsn=0.0.0, UndoNextLsn=0.0.0, logWriter=False, backupTxn=False (SESSION: 25342) 11/20/2005 16:00:31 (43) Open objects: (SESSION: 25342) 11/20/2005 16:00:31 (43) name ->Restore.Sessions<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:31 (43) name ->AF.Damaged<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:31 (43) name ->BF.Aggregate.Attributes<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:31 (43) name ->AF.Vol.Segments<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:31 (43) name ->AS.Volume.Status<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:31 (43) name ->AF.Segments<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:31 (43) name ->AF.Bitfiles<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:31 (43) name ->AF.Vol.Partial.Bitfiles<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:31 (43) name ->SS.Volume.Names<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:31 (43) name ->SS.Volume.Ids<- (sp=0) (SESSION: 25342) 11/20/2005 16:00:31 (43) *** no transactions found *** (SESSION: 25342) 11/20/2005 16:00:31 (43) Generating SM Context Report: (SESSION: 25342) 11/20/2005 16:00:31 (43) *** no sessions found *** (SESSION: 25342) 11/20/2005 16:00:31 (43) Generating AS Vol Context Report: (SESSION: 25342) 11/20/2005 16:00:31 (43) No mounted (or mount in progress) volumes. (SESSION: 25342) 11/20/2005 16:00:31 (43) Failed attempt #1 to get SSV->mutex (SESSION: 25342) 11/20/2005 16:00:31 (43) Generating ssSession Context Report: (SESSION: 25342) 11/20/2005 16:00:31 (43) No storage service sessions active. (SESSION: 25342) 11/20/2005 16:00:31 (43) Generating ssOpenSeg Context Report: (SESSION: 25342) 11/20/2005 16:00:31 (43) No storage service segments found. (SESSION: 25342) 11/20/2005 16:00:31 (43) Generating BF Copy Control Context Report: (SESSION: 25342) 11/20/2005 16:00:31 (43) No global copy control blocks. (SESSION: 25342) 11/20/2005 16:00:31 (SESSION: 25342) 11/20/2005 16:00:31 (43) End Context report (SESSION: 25342) 11/20/2005 16:00:31 ANR1092E Space reclamation is ended for volume A00541. An internal server error was detected. (SESSION: 25342) 11/20/2005 16:00:31 ANR9999D ThreadId<43> issued message 1092 from: (SESSION: 25342) 11/20/2005 16:00:31 ANR0985I Process 501 for SPACE RECLAMATION running in the BACKGROUND completed with completion state FAILURE at 16:00:31. (SESSION: 25342) 11/20/2005 16:00:31 ANR0514I Session 25342 closed volume A00541. (SESSION: 25342) 11/20/2005 16:00:31 ANR0408I Session 25352 started for server TSMLIBMGR (Windows) (Tcp/Ip) for library sharing. (SESSION: 25342) 11/20/2005 16:00:31 ANR0409I Session 25352 ended for server TSMLIBMGR (Windows). (SESSION: 25342) 11/20/2005 16:00:31 ANR0408I Session 25353 started for server TSMLIBMGR (Windows) (Tcp/Ip) for library sharing. (SESSION: 25342) 11/20/2005 16:00:31 ANR0409I Session 25353 ended for server TSMLIBMGR (Windows). (SESSION: 25342) 11/20/2005 16:00:31 ANR0408I Session 25354 started for server TSMLIBMGR (Windows) (Tcp/Ip) for library sharing. (SESSION: 25342) 11/20/2005 16:00:31 ANR0409I Session 25354 ended for server TSMLIBMGR (Windows). (SESSION: 25342) 11/20/2005 16:00:31 ANR4936I Reclamation of storage pool ORL-DMNO-TAPE has ended. Files reclaimed: 0, Bytes reclaimed: 0, Files reconstructed: 0, Unreadable files: 0. (SESSION: 25342) 11/20/2005 16:05:31 ANR8468I LTO volume A00541 dismounted from drive LTODRV13 (mt4.3.1.3) in library ADIC-TSM. (SESSION: 25342) The report is pretty much the same for other failed attempts at Space Reclamation and it occurs on a daily basis.