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.