Problems reading Enstore tapes

I have written and tested using MHVTL some Enstore-reading code. However, when trying it in the wild I am running into issues.

First caveat, things are not setup 100% correctly in that we have the tapes marked as LTO-8 in the CTA database but they are really M8 tapes being read by LTO-8 drives. I assume this doesn’t matter and that the M8 designation is just used to set the capacity at 9 TB instead of 12 TB.

As you probably know, Enstore has a similar label format to CTA. If I read the label with dd, I get 84 bytes instead of 80, so I assume the last four bytes are a checksum (it looks like it). Our labels don’t specify if there is a crc32 checksum or not, but I assume I should just set it on read-only?

Then when CTA tries to read the real block (I think), I get error like this in journalctl:

Jul 29 18:43:34 gmv18018.fnal.gov cta-taped[142940]: LVL="ERROR" PID="142940" TID="142989" MSG="In RecallReportPacker::ReportError::execute(): failing retrieve job after exception." thread="RecallReportPacker" tapeDrive="LTO8D0" tapeVid="VR5775" mountId="66" failureLog="Jul 29 18:43:34.367608 gmv18018 In DriveGeneric::readBlock: Failed ST read (with checksum) Errno=12: Cannot allocate memory" fileId="161"

Where the cannot allocate memory seems to come from the system level read (I get the same sorts of errors trying to read these back with dd). (If I don’t set the read-only crc32 mode, I get the same error without the checksum, so I can identify the code path in DriveGeneric which is being taken).

So what I am thinking is that I’ve got to get my block sizes and checksumming settings on the drive done correctly. When reading back a checksummed data block (256k) should I set the block size to 256k or 256k+4 bytes, for instance. Does the low level block reading take care of that extra 4 bytes?

In MM Jorge asked to see the output of sdparm on the tape drives and here they are:

[root@gmv18018 tmp]# lsscsi -g
[2:0:0:0]    disk    ATA      HGST HUS722T1TAL WA07  /dev/sda   /dev/sg0 
[10:0:0:0]   tape    IBM      ULT3580-TD8      N4Q0  /dev/st0   /dev/sg1 
[10:0:0:1]   mediumx IBM      03584L32         1705  /dev/sch0  /dev/sg2 
[11:0:0:0]   tape    IBM      ULT3580-TD8      N4Q0  /dev/st1   /dev/sg3 
[11:0:0:1]   mediumx IBM      03584L32         1705  /dev/sch1  /dev/sg4 
[root@gmv18018 tmp]# sdparm --page=10,240 /dev/sg1
    /dev/sg1: IBM       ULT3580-TD8       N4Q0  [tape]
Control data protection (SSC) mode page:
  LBPM        2  [cha: y, def:  0, sav:  0]
  LBPIL       4  [cha: y, def:  0, sav:  0]
  LBP_W       0  [cha: y, def:  0, sav:  0]
  LBP_R       1  [cha: y, def:  0, sav:  0]
  RBDP        0  [cha: n, def:  0, sav:  0]
[root@gmv18018 tmp]# sdparm --page=10,240 /dev/sg3
    /dev/sg3: IBM       ULT3580-TD8       N4Q0  [tape]
Control data protection (SSC) mode page:
  LBPM        0  [cha: y, def:  0, sav:  0]
  LBPIL       0  [cha: y, def:  0, sav:  0]
  LBP_W       0  [cha: y, def:  0, sav:  0]
  LBP_R       0  [cha: y, def:  0, sav:  0]
  RBDP        0  [cha: n, def:  0, sav:  0]

Thanks for any insight.

Jorge also asked about the output of dd with bs=1024:

[root@gmv18018 ~]# !982
dd if=/dev/nst0 of=/tmp/2 bs=1024
0+1 records in
0+1 records out
84 bytes (84 B) copied, 0.00673734 s, 12.5 kB/s
[root@gmv18018 ~]# dd if=/dev/nst0 of=/tmp/3 bs=1024
dd: error reading ‘/dev/nst0’: Input/output error
0+0 records in
0+0 records out
0 bytes (0 B) copied, 0.0203024 s, 0.0 kB/s
[root@gmv18018 ~]# cat /tmp/2 
VOL1VR5775                                                                     0??m/

and here’s what our tape label looks like:

[root@gmv18018 ~]# hexdump -C /tmp/2
00000000  56 4f 4c 31 56 52 35 37  37 35 20 20 20 20 20 20  |VOL1VR5775      |
00000010  20 20 20 20 20 20 20 20  20 20 20 20 20 20 20 20  |                |
*
00000040  20 20 20 20 20 20 20 20  20 20 20 20 20 20 20 30  |               0|
00000050  b7 ae 6d 2f                                       |..m/|

That 0 at byte 80 is in place of the 3 that CASTOR uses and those last 4 bytes must be the checksum

Alternatively if I use a different tape drive and a different tape I get:

[root@gmv18018 ~]# dd if=/dev/nst1 of=/tmp/test1 bs=1024
0+1 records in
0+1 records out
80 bytes (80 B) copied, 0.0140371 s, 5.7 kB/s
[root@gmv18018 ~]# dd if=/dev/nst1 of=/tmp/test2 bs=1024
dd: error reading ‘/dev/nst1’: Cannot allocate memory
0+0 records in
0+0 records out
0 bytes (0 B) copied, 0.0105415 s, 0.0 kB/s
[root@gmv18018 ~]# dd if=/dev/nst1 of=/tmp/test3 bs=1024
dd: error reading ‘/dev/nst1’: Cannot allocate memory
0+0 records in
0+0 records out
0 bytes (0 B) copied, 0.0106246 s, 0.0 kB/s
[root@gmv18018 ~]# dd if=/dev/nst1 of=/tmp/test4 bs=1024
dd: error reading ‘/dev/nst1’: Cannot allocate memory
0+0 records in
0+0 records out
0 bytes (0 B) copied, 0.0176466 s, 0.0 kB/s

which looks more similar to what I was getting with CTA with the cannot allocate memory error.

Hello Eric,
it looks like this mess is caused by Logical Block Protection: this is something we added around 2016 in CASTOR code. All CERN tapes have been repacked with LBP on all tapes before migration to CTA.
All tapes currently in CTA (imported from CASTOR or written with CTA) have been written with LBP on.

MHVTL has no such LBP support therefore all your tests on virtual tapes are immune to this kind of problems.

Similar issues of HW managed tape content could appear with tape encryption feature too…

Before we go through the details, we need some lights on enstore label/HW tape feature it uses.

Could you attach the binary dump of a tape label to this ticket (84 bytes)? I wrote some tools in the past to compute LBP blocks and perform some checks. This way I can tell you if you have a valid LBP label or not.

Does enstore support Logical Block Protection? If so how does enstore decide if a tape has LBP enabled?

Similarly for tape encryption: do you have some hardware encrypted tapes in enstore? If so how does enstore decide if a tape was written encrytped?

A simple approach would be that we decide that all enstore tapes are read without LBP: this works fine in any case if the tape has LBP or not we can read any with LBP off on the tape drive. This approach makes sense if enstore does not support LBP.

My favorite approach would be to disable LBP to read back enstore tapes (or any other not native CTA format).

Indeed when we added LBP support in CASTOR we did it for writes to tape: LBP allows us to make sure that whatever was sent to the tape drive was correctly written on the medium.

When reading back: we just read whatever is on the tape and we must deal with this. Every single file is checksummed in the namespace. Therefore if the file is corrupted on tape we will detect it at the end of its retrieval. During read LBP does not add anything more than early corruption detection as it will report a read failure when the drive tries to read the first block with wrong checksum.

For this reason I think that adding proper LBP support to read non CTA native tape formats is not really needed: the full LBP logic is not simple as it spread in various parts of the code when reading a tape (reading the label during mount, reading the label during dismount…).

Thanks Julien. The binary dump is actually there above. The first 80 bytes are VOL1 through 0 in ASCII. And then the “extra” four bytes are b7 ae 6d 2f

So if I understand you correctly, LBP-written tapes can be read back in non-LPB mode and that extra data is just not seen? This sort of matches some success I had at the end of the day with ‘dd’ and a different tape drive. I thought I had verified that the Enstore block size was 256k but instead I think it’s 1M. Reading back a file with a 1M block size lets dd read a 80 B header and a 2.7 GB file.

Unfortunately I didn’t quite have enough time to test this tape/drive combo with CTA, but I will attempt to do that later today.

Well, I’m making some progress. After upping the block size in the code and in the cta-taped.conf, I’m not getting system-level errors anymore. Now the error I’m getting is suggesting that a 0-length file is being read from tape.

Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="857" MSG="Error reading a file in TapeReadFileTask" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" vo="vo" mediaType="LTO8" tapePool="ctasystest" logicalLibrary="TS4500G1" mountType="Retrieve" labelFormat="0x02" vendor="ibm" capacityInBytes="12000000000000" fileId="161" BlockId="1" fSeq="1" dstURL="root://storagedev201.fnal.gov//eos/archive/pnfs/fs/usr/cms/WAX/11/store/mc/RunIISummer19UL17HLT/GluGluToHiggs0PL1ToZZTo2mu2tau_M125_GaSM_13TeV_MCFM701_pythia8/GEN-SIM-RAW/94X_mc2017_realistic_v15-v2/260000/3C103261-CDB7-E911-A053-0CC47AFC3D32.root?eos.lfn=fxid:21&eos.ruid=0&eos.rgid=0&eos.injection=1&eos.workflow=retrieve_written&eos.space=default&oss.asize=2769204577" isRepack="0" isVerifyOnly="0" fileBlock="1" ErrorMessage="Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" EWVSize="0"

and elsewhere

Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="858" MSG="File writing to disk failed" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0" fileId="161" dstURL="root://storagedev201.fnal.gov//eos/archive/pnfs/fs/usr/cms/WAX/11/store/mc/RunIISummer19UL17HLT/GluGluToHiggs0PL1ToZZTo2mu2tau_M125_GaSM_13TeV_MCFM701_pythia8/GEN-SIM-RAW/94X_mc2017_realistic_v15-v2/260000/3C103261-CDB7-E911-A053-0CC47AFC3D32.root?eos.lfn=fxid:21&eos.ruid=0&eos.rgid=0&eos.injection=1&eos.workflow=retrieve_written&eos.space=default&oss.asize=2769204577" fSeq="1" errorMessage="Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" readWriteTime="0.000000" checksumingTime="0.000000" waitDataTime="9.130139" waitReportingTime="0.001754" checkingErrorTime="0.000000" openingTime="0.000000" closingTime="0.000000" transferTime="0.000000" totalTime="0.000000" dataVolume="0" globalPayloadTransferSpeedMBps="0.000000" diskPerformanceMBps="0.000000" openRWCloseToTransferTimeRatio="0.000000"

At first I thought maybe my tape positioning was off, so I moved that by one file, but still get nothing read back. And there doesn’t seem to be any debugging for the really low level stuff like file positioning and the actual reading code. Any ideas?

Let me see if I can upload the full logs somehow.

Logs part A

Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="Transition from down to up detected. Will check if a tape is in the drive." thread="MainThread" tapeDrive="LTO8D1"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="Probe found tape drive is empty" tapeDrive="LTO8D1"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="No tape detected in the drive. Proceeding with scheduling." thread="MainThread" tapeDrive="LTO8D1"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="245605" MSG="In Scheduler::sortAndGetTapesForMountInfo(): Will consider potential mount" thread="MainThread" tapeDrive="LTO8D1" tapePool="ctasystest" vo="vo" tapeVid="VR5775" mountType="RETRIEVE" existingMountsDistinctTypesForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="2769204577" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="628" youngestJobAge="628" minArchiveRequestAge="1" maxDrives="2" voReadMaxDrives="2" voWriteMaxDrives="2" ratioOfMountQuotaUsed="0.000000"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="In Scheduler::getNextMountDryRun(): Found a potential mount (retrieve)" thread="MainThread" tapeDrive="LTO8D1" tapePool="ctasystest" tapeVid="VR5775" mountType="RETRIEVE" existingMountsDistinctTypeForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="2769204577" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="628" youngestJobAge="628" minArchiveRequestAge="1" getMountInfoTime="0.022831" getTapeInfoTime="0.020332" candidateSortingTime="0.002776" getTapeForWriteTime="0.000000" decisionTime="0.000197" schedulerDbTime="0.022831" catalogueTime="0.020332"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="245605" MSG="In Scheduler::sortAndGetTapesForMountInfo(): Will consider potential mount" thread="MainThread" tapeDrive="LTO8D1" tapePool="ctasystest" vo="vo" tapeVid="VR5775" mountType="RETRIEVE" existingMountsDistinctTypesForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="2769204577" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="628" youngestJobAge="628" minArchiveRequestAge="1" maxDrives="2" voReadMaxDrives="2" voWriteMaxDrives="2" ratioOfMountQuotaUsed="0.000000"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="In Scheduler::getNextMount(): Selected next mount (retrieve)" thread="MainThread" tapeDrive="LTO8D1" tapePool="ctasystest" tapeVid="VR5775" vo="vo" mediaType="LTO8" labelFormat="0x02" vendor="ibm" mountType="RETRIEVE" existingMountsDistinctTypeForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="2769204577" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="628" youngestJobAge="628" minArchiveRequestAge="1" getMountInfoTime="0.008661" queueTrimingTime="0.000000" getTapeInfoTime="0.011466" candidateSortingTime="0.000629" getTapeForWriteTime="0.000000" decisionTime="0.000146" mountCreationTime="0.003542" driveStatusSetTime="0.000003" schedulerDbTime="0.012206" catalogueTime="0.011466"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="Got volume from client" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" tapebridgeTransId="96" mountType="Retrieve"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="RecallMemoryManager: all blocks have been created" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" blockCount="200" blockSize="1048576" totalSize="209715200"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="DiskWrite Thread created" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="DiskWrite Thread created" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="1"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="DiskWrite Thread created" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="2"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="DiskWrite Thread created" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="3"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="DiskWrite Thread created" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="4"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="DiskWrite Thread created" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="5"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="DiskWrite Thread created" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="6"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="DiskWrite Thread created" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="7"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="DiskWrite Thread created" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="8"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="DiskWrite Thread created" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="9"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="245605" MSG="Created threads in DiskWriteThreadPool::DiskWriteThreadPool" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10"
Aug 02 15:58:32 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="245605" MSG="In AgentReference::appyAction(): added object to ownership (by batch)." agentObject="DriveProcess-LTO8D1-gmv18018.fnal.gov-245605-20220802-15:54:06-0" ownedObject="RetrieveRequest-Frontend-storagedev201.fnal.gov-45076-20220729-14:59:01-0-38"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="In RootEntry::removeRetrieveQueueAndCommit(): removed retrieve queue." thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" retrieveQueueObject="RetrieveQueueToTransferForUser-VR5775-Frontend-storagedev201.fnal.gov-45076-20220729-14:59:01-0-39"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="In RootEntry::removeRetrieveQueueAndCommit(): removed retrieve queue reference." thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" queueType="jobsToTranfer"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="In ContainerTraits<RetrieveQueue,C>::trimContainerIfNeeded(): deleted empty queue" thread="MainThread" tapeDrive="LTO8D1" mountId="96" tapeVid="VR5775" queueObject="RetrieveQueueToTransferForUser-VR5775-Frontend-storagedev201.fnal.gov-45076-20220729-14:59:01-0-39"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="In Algorithms::popNextBatch(): did one round of elements retrieval." thread="MainThread" tapeDrive="LTO8D1" mountId="96" C="RetrieveQueueToTransfer" tapeVid="VR5775" containerAddress="RetrieveQueueToTransferForUser-VR5775-Frontend-storagedev201.fnal.gov-45076-20220729-14:59:01-0-39" filesAdded="1" bytesAdded="2769204577" filesBefore="0" bytesBefore="0" filesAfter="1" bytesAfter="2769204577" queueFilesBefore="1" queueBytesBefore="2769204577" queueFilesAfter="0" queueBytesAfter="0" findLockFetchQueueTime="0.001178" jobSelectionTime="0.001637" ownershipAdditionTime="0.000031" asyncUpdateLaunchTime="0.004241" asyncUpdateCompletionTime="0.005721" updateResultProcessingTime="0.000059" containerUpdateTime="0.003876" containerTrimmingTime="0.110036" containerUnlockTime="0.000016" structureProcessingTime="0.000065"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="In Algorithms::popNextBatch(): elements retrieval complete." thread="MainThread" tapeDrive="LTO8D1" mountId="96" C="RetrieveQueueToTransfer" tapeVid="VR5775" files="1" findLockFetchQueueTime="0.001178" jobSelectionTime="0.001637" ownershipAdditionTime="0.000031" asyncUpdateLaunchTime="0.004241" asyncUpdateCompletionTime="0.005721" updateResultProcessingTime="0.000059" containerUpdateTime="0.003876" containerTrimmingTime="0.110036" containerUnlockTime="0.000016" structureProcessingTime="0.000065" schedulerDbTime="0.128319" iterationCount="1"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="Fetched files to recall" thread="MainThread" tapeDrive="LTO8D1" mountId="96" requestedBytes="80000000000" requestedFiles="4000" fetchedFiles="1"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="Disk space reservation test passed, can mount tape" thread="MainThread" tapeDrive="LTO8D1" mountId="96"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="Starting tape read thread" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="857" MSG="In RecallReportPacker::reportDriveStatus(), pushing a report." thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" type="ReportDriveStatus" Status="Mount"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="858" MSG="Starting DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="860" MSG="Starting DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="2"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="Tape session started for read" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" vo="vo" mediaType="LTO8" tapePool="ctasystest" logicalLibrary="TS4500G1" mountType="Retrieve" labelFormat="0x02" vendor="ibm" capacityInBytes="12000000000000"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="861" MSG="Starting DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="3"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="859" MSG="Starting DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="1"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="864" MSG="Starting DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="6"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="862" MSG="Starting DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="4"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="863" MSG="Starting DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="5"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="865" MSG="Starting DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="7"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="Starting threads in DiskWriteThreadPool::DiskWriteThreadPool" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="866" MSG="Starting DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="8"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="867" MSG="Starting DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="9"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="Starting RecallReportPacker thread" thread="RecallReportPacker" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="869" MSG="Starting RecallTaskInjector thread" thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::WorkerThread::run(): Got a new report." thread="RecallReportPacker" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" typeId="castor::tape::tapeserver::daemon::RecallReportPacker::ReportDriveStatus"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::ReportDriveStatus::execute(): reporting drive status." thread="RecallReportPacker" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" status="Mount"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="In DriveHandler::processEvent(): changing session state" tapeDrive="LTO8D1" PreviousState="StartingUp" PreviousType="Undetermined" NewState="Scheduling" NewType="Undetermined"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" PreviousState="StartingUp" PreviousType="Undetermined" NewState="Scheduling" NewType="Undetermined" TimeoutType="StateChange" LastStateChangeTime="101260" LastHeartBeatTime="101260" LastDataMovementTime="100994" Now="101260" Timeout="101560"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="In DriveHandler::processEvent(): changing session state" tapeDrive="LTO8D1" PreviousState="Scheduling" PreviousType="Undetermined" NewState="Mounting" NewType="Retrieve"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" PreviousState="Scheduling" PreviousType="Undetermined" NewState="Mounting" NewType="Retrieve" TimeoutType="StateChange" LastStateChangeTime="101260" LastHeartBeatTime="101260" LastDataMovementTime="100994" Now="101260" Timeout="101860"
Aug 02 15:58:33 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="StateChange" LastStateChangeTime="101260" LastHeartBeatTime="101260" LastDataMovementTime="100994" Now="101260" Timeout="101860"
Aug 02 15:58:39 gmv18018.fnal.gov cta-taped[245606]: LVL="DEBUG" PID="245606" TID="245606" MSG="In MaintenanceHandler::exceptionThrowingRunChild(): About to do a maintenance pass." SubprocessName="maintenanceHandler"
Aug 02 15:58:42 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="Tape mounted for read-only access" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" vo="vo" mediaType="LTO8" tapePool="ctasystest" logicalLibrary="TS4500G1" mountType="Retrieve" labelFormat="0x02" vendor="ibm" capacityInBytes="12000000000000" drive_Slot="smc0" MCMountTime="9.028805" mode="R"
Aug 02 15:58:48 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="856" MSG="going to report" thread="Watchdog" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96"
Aug 02 15:58:48 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="StateChange" LastStateChangeTime="101260" LastHeartBeatTime="101275" LastDataMovementTime="100994" Now="101275" Timeout="101860"
Aug 02 15:58:48 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="StateChange" LastStateChangeTime="101260" LastHeartBeatTime="101275" LastDataMovementTime="100994" Now="101275" Timeout="101860"
Aug 02 15:58:48 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="856" MSG="RdbmsCatalogue::updateTapeDriveStatistics(): It didn't update statistics"
Aug 02 15:58:48 gmv18018.fnal.gov cta-taped[245606]: LVL="DEBUG" PID="245606" TID="245606" MSG="In MaintenanceHandler::exceptionThrowingRunChild(): About to do a maintenance pass." SubprocessName="maintenanceHandler"
Aug 02 15:58:52 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="Tape mounted and drive ready" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" vo="vo" mediaType="LTO8" tapePool="ctasystest" logicalLibrary="TS4500G1" mountType="Retrieve" labelFormat="0x02" vendor="ibm" capacityInBytes="12000000000000" mountTime="19.513879" tapeLoadTime="10.482791"

Part B

Aug 02 15:58:52 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="Catalogue - system modified tape - mountedForRetrieve" vid="VR5775" lastReadDrive="LTO8D1" lastReadTime="1659473932"
Aug 02 15:58:52 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="In RetrieveMount::setTapeMounted(): success." thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" vo="vo" mediaType="LTO8" tapePool="ctasystest" logicalLibrary="TS4500G1" mountType="Retrieve" labelFormat="0x02" vendor="ibm" capacityInBytes="12000000000000" catalogueTime="0.003840"
Aug 02 15:58:52 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="Drive encryption not enabled for this mount" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" vo="vo" mediaType="LTO8" tapePool="ctasystest" logicalLibrary="TS4500G1" mountType="Retrieve" labelFormat="0x02" vendor="ibm" capacityInBytes="12000000000000" encryption="off"
Aug 02 15:58:57 gmv18018.fnal.gov cta-taped[245606]: LVL="DEBUG" PID="245606" TID="245606" MSG="In MaintenanceHandler::exceptionThrowingRunChild(): About to do a maintenance pass." SubprocessName="maintenanceHandler"
Aug 02 15:58:57 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="869" MSG="Error while fetching the limitUDS for RAO enterprise drive. Will run a CTA RAO." thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96" exceptionMessage="SCSI error in DriveGeneric::getLimitUDS status=0x2 host_status=0 driver_status=0x8: SCSI command failed with status CHECK CONDITION: Sense Information: Illegal Request: Invalid field in cdb"
Aug 02 15:58:57 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="869" MSG="Performing RAO reordering" thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="Tape read session session without LBP successfully started" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" vo="vo" mediaType="LTO8" tapePool="ctasystest" logicalLibrary="TS4500G1" mountType="Retrieve" labelFormat="0x02" vendor="ibm" capacityInBytes="12000000000000" positionTime="5.410211" useLbp="1" detectedLbp="0"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245605]: LVL="WARN" PID="245605" TID="869" MSG="In RAOManager::queryRAO(), failed to instanciate the RAO algorithm, will perform a linear RAO." thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96" errorMsg="In InterpolationFilePositionEstimator::checkMediaTypeConsistency(), the media type (LTO8) associated to the tape does not give informations about the minLPos and maxLPos." raoAlgorithmName="sltf" raoAlgorithmOptions="cost_heuristic_name:cta" useRAO="1" vid="VR5775"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="869" MSG="In RAOManager::queryRAO(), successfully performed RAO." thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96" executedRAOAlgorithm="linear" vectorInitializationTime="0.000033" vectorSortingTime="0.000119" RAOAlgorithmTime="0.000157" totalTime="0.112583"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="869" MSG="In RecallTaskInjector::reserveSpaceForNextJobBatch(): Disk space reservation for next job batch succeeded" thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="869" MSG="Created tasks for recalling a file" thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="869" MSG="Recall order of FSEQs using RAO: 1" thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="869" MSG="Finished processing batch of recall tasks from client" thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96" nbFile="1"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="857" MSG="In RecallReportPacker::reportDriveStatus(), pushing a report." thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" vo="vo" mediaType="LTO8" tapePool="ctasystest" logicalLibrary="TS4500G1" mountType="Retrieve" labelFormat="0x02" vendor="ibm" capacityInBytes="12000000000000" type="ReportDriveStatus" Status="Transfer"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::WorkerThread::run(): Got a new report." thread="RecallReportPacker" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" typeId="castor::tape::tapeserver::daemon::RecallReportPacker::ReportDriveStatus"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="869" MSG="RecallJobInjector:run: about to call client interface" thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::ReportDriveStatus::execute(): reporting drive status." thread="RecallReportPacker" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" status="Transfer"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="In DriveHandler::processEvent(): changing session state" tapeDrive="LTO8D1" PreviousState="Mounting" PreviousType="Retrieve" NewState="Running" NewType="Retrieve"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" PreviousState="Mounting" PreviousType="Retrieve" NewState="Running" NewType="Retrieve" TimeoutType="Heartbeat" LastStateChangeTime="101285" LastHeartBeatTime="101285" LastDataMovementTime="101285" Now="101285" Timeout="101345"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="869" MSG="No files left to recall on the queue or in the injector" thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96" transactionId="96"
Aug 02 15:58:58 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="869" MSG="Performing RAO reordering" thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96" transactionId="96"
Aug 02 15:59:03 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="856" MSG="going to report" thread="Watchdog" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96"
Aug 02 15:59:03 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="Heartbeat" LastStateChangeTime="101285" LastHeartBeatTime="101290" LastDataMovementTime="101285" Now="101290" Timeout="101350"
Aug 02 15:59:03 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="Heartbeat" LastStateChangeTime="101285" LastHeartBeatTime="101290" LastDataMovementTime="101285" Now="101290" Timeout="101350"
Aug 02 15:59:06 gmv18018.fnal.gov cta-taped[245606]: LVL="DEBUG" PID="245606" TID="245606" MSG="In MaintenanceHandler::exceptionThrowingRunChild(): About to do a maintenance pass." SubprocessName="maintenanceHandler"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="857" MSG="Successfully opened the tape file" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" vo="vo" mediaType="LTO8" tapePool="ctasystest" logicalLibrary="TS4500G1" mountType="Retrieve" labelFormat="0x02" vendor="ibm" capacityInBytes="12000000000000" fileId="161" BlockId="1" fSeq="1" dstURL="root://storagedev201.fnal.gov//eos/archive/pnfs/fs/usr/cms/WAX/11/store/mc/RunIISummer19UL17HLT/GluGluToHiggs0PL1ToZZTo2mu2tau_M125_GaSM_13TeV_MCFM701_pythia8/GEN-SIM-RAW/94X_mc2017_realistic_v15-v2/260000/3C103261-CDB7-E911-A053-0CC47AFC3D32.root?eos.lfn=fxid:21&eos.ruid=0&eos.rgid=0&eos.injection=1&eos.workflow=retrieve_written&eos.space=default&oss.asize=2769204577" isRepack="0" isVerifyOnly="0"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="Timed free memory" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" vo="vo" mediaType="LTO8" tapePool="ctasystest" logicalLibrary="TS4500G1" mountType="Retrieve" labelFormat="0x02" vendor="ibm" capacityInBytes="12000000000000" fileId="161" BlockId="1" fSeq="1" dstURL="root://storagedev201.fnal.gov//eos/archive/pnfs/fs/usr/cms/WAX/11/store/mc/RunIISummer19UL17HLT/GluGluToHiggs0PL1ToZZTo2mu2tau_M125_GaSM_13TeV_MCFM701_pythia8/GEN-SIM-RAW/94X_mc2017_realistic_v15-v2/260000/3C103261-CDB7-E911-A053-0CC47AFC3D32.root?eos.lfn=fxid:21&eos.ruid=0&eos.rgid=0&eos.injection=1&eos.workflow=retrieve_written&eos.space=default&oss.asize=2769204577" isRepack="0" isVerifyOnly="0"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="WARN" PID="245605" TID="869" MSG="In RAOManager::queryRAO(), failed to instanciate the RAO algorithm, will perform a linear RAO." thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96" transactionId="96" errorMsg="In InterpolationFilePositionEstimator::checkMediaTypeConsistency(), the media type (LTO8) associated to the tape does not give informations about the minLPos and maxLPos." raoAlgorithmName="sltf" raoAlgorithmOptions="cost_heuristic_name:cta" useRAO="1" vid="VR5775"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="869" MSG="In RAOManager::queryRAO(), successfully performed RAO." thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96" transactionId="96" executedRAOAlgorithm="linear" vectorInitializationTime="0.000005" vectorSortingTime="0.000025" RAOAlgorithmTime="0.000034" totalTime="9.005544"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="869" MSG="In RecallTaskInjector::reserveSpaceForNextJobBatch(): Disk space reservation for next job batch succeeded" thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96" transactionId="96"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="869" MSG="Recall order of FSEQs using RAO:" thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96" transactionId="96"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="869" MSG="Finished processing batch of recall tasks from client" thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96" transactionId="96" nbFile="0"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="869" MSG="No more file to recall: triggering the end of session." thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96" transactionId="96"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="869" MSG="Finishing RecallTaskInjector thread" thread="RecallTaskInjector" tapeDrive="LTO8D1" mountId="96"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="863" MSG="DiskWriteWorkerThread exiting: no more work" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="5"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="859" MSG="DiskWriteWorkerThread exiting: no more work" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="1"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="864" MSG="DiskWriteWorkerThread exiting: no more work" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="6"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="865" MSG="DiskWriteWorkerThread exiting: no more work" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="7"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="860" MSG="DiskWriteWorkerThread exiting: no more work" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="2"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="862" MSG="DiskWriteWorkerThread exiting: no more work" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="4"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="861" MSG="DiskWriteWorkerThread exiting: no more work" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="3"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="866" MSG="DiskWriteWorkerThread exiting: no more work" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="8"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="867" MSG="DiskWriteWorkerThread exiting: no more work" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="9"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="865" MSG="Finishing DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="7" threadReadWriteTime="0.000000" threadChecksumingTime="0.000000" threadWaitDataTime="0.000000" threadWaitReportingTime="0.000000" threadCheckingErrorTime="0.000000" threadOpeningTime="0.000000" threadClosingTime="0.000000" threadTransferTime="0.000000" threadTotalTime="33.978818" threadDataVolume="0" threadFileCount="0" threadGlobalPayloadTransferSpeedMBps="0.000000" threadAverageDiskPerformanceMBps="0.000000" threadOpenRWCloseToTransferTimeRatio="0.000000"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="863" MSG="Finishing DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="5" threadReadWriteTime="0.000000" threadChecksumingTime="0.000000" threadWaitDataTime="0.000000" threadWaitReportingTime="0.000000" threadCheckingErrorTime="0.000000" threadOpeningTime="0.000000" threadClosingTime="0.000000" threadTransferTime="0.000000" threadTotalTime="33.978843" threadDataVolume="0" threadFileCount="0" threadGlobalPayloadTransferSpeedMBps="0.000000" threadAverageDiskPerformanceMBps="0.000000" threadOpenRWCloseToTransferTimeRatio="0.000000"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="862" MSG="Finishing DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="4" threadReadWriteTime="0.000000" threadChecksumingTime="0.000000" threadWaitDataTime="0.000000" threadWaitReportingTime="0.000000" threadCheckingErrorTime="0.000000" threadOpeningTime="0.000000" threadClosingTime="0.000000" threadTransferTime="0.000000" threadTotalTime="33.978959" threadDataVolume="0" threadFileCount="0" threadGlobalPayloadTransferSpeedMBps="0.000000" threadAverageDiskPerformanceMBps="0.000000" threadOpenRWCloseToTransferTimeRatio="0.000000"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="866" MSG="Finishing DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="8" threadReadWriteTime="0.000000" threadChecksumingTime="0.000000" threadWaitDataTime="0.000000" threadWaitReportingTime="0.000000" threadCheckingErrorTime="0.000000" threadOpeningTime="0.000000" threadClosingTime="0.000000" threadTransferTime="0.000000" threadTotalTime="33.978733" threadDataVolume="0" threadFileCount="0" threadGlobalPayloadTransferSpeedMBps="0.000000" threadAverageDiskPerformanceMBps="0.000000" threadOpenRWCloseToTransferTimeRatio="0.000000"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="860" MSG="Finishing DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="2" threadReadWriteTime="0.000000" threadChecksumingTime="0.000000" threadWaitDataTime="0.000000" threadWaitReportingTime="0.000000" threadCheckingErrorTime="0.000000" threadOpeningTime="0.000000" threadClosingTime="0.000000" threadTransferTime="0.000000" threadTotalTime="33.979592" threadDataVolume="0" threadFileCount="0" threadGlobalPayloadTransferSpeedMBps="0.000000" threadAverageDiskPerformanceMBps="0.000000" threadOpenRWCloseToTransferTimeRatio="0.000000"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="864" MSG="Finishing DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="6" threadReadWriteTime="0.000000" threadChecksumingTime="0.000000" threadWaitDataTime="0.000000" threadWaitReportingTime="0.000000" threadCheckingErrorTime="0.000000" threadOpeningTime="0.000000" threadClosingTime="0.000000" threadTransferTime="0.000000" threadTotalTime="33.978938" threadDataVolume="0" threadFileCount="0" threadGlobalPayloadTransferSpeedMBps="0.000000" threadAverageDiskPerformanceMBps="0.000000" threadOpenRWCloseToTransferTimeRatio="0.000000"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="861" MSG="Finishing DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="3" threadReadWriteTime="0.000000" threadChecksumingTime="0.000000" threadWaitDataTime="0.000000" threadWaitReportingTime="0.000000" threadCheckingErrorTime="0.000000" threadOpeningTime="0.000000" threadClosingTime="0.000000" threadTransferTime="0.000000" threadTotalTime="33.979210" threadDataVolume="0" threadFileCount="0" threadGlobalPayloadTransferSpeedMBps="0.000000" threadAverageDiskPerformanceMBps="0.000000" threadOpenRWCloseToTransferTimeRatio="0.000000"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="867" MSG="Finishing DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="9" threadReadWriteTime="0.000000" threadChecksumingTime="0.000000" threadWaitDataTime="0.000000" threadWaitReportingTime="0.000000" threadCheckingErrorTime="0.000000" threadOpeningTime="0.000000" threadClosingTime="0.000000" threadTransferTime="0.000000" threadTotalTime="33.978733" threadDataVolume="0" threadFileCount="0" threadGlobalPayloadTransferSpeedMBps="0.000000" threadAverageDiskPerformanceMBps="0.000000" threadOpenRWCloseToTransferTimeRatio="0.000000"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="859" MSG="Finishing DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="1" threadReadWriteTime="0.000000" threadChecksumingTime="0.000000" threadWaitDataTime="0.000000" threadWaitReportingTime="0.000000" threadCheckingErrorTime="0.000000" threadOpeningTime="0.000000" threadClosingTime="0.000000" threadTransferTime="0.000000" threadTotalTime="33.979085" threadDataVolume="0" threadFileCount="0" threadGlobalPayloadTransferSpeedMBps="0.000000" threadAverageDiskPerformanceMBps="0.000000" threadOpenRWCloseToTransferTimeRatio="0.000000"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="857" MSG="Error reading a file in TapeReadFileTask" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" vo="vo" mediaType="LTO8" tapePool="ctasystest" logicalLibrary="TS4500G1" mountType="Retrieve" labelFormat="0x02" vendor="ibm" capacityInBytes="12000000000000" fileId="161" BlockId="1" fSeq="1" dstURL="root://storagedev201.fnal.gov//eos/archive/pnfs/fs/usr/cms/WAX/11/store/mc/RunIISummer19UL17HLT/GluGluToHiggs0PL1ToZZTo2mu2tau_M125_GaSM_13TeV_MCFM701_pythia8/GEN-SIM-RAW/94X_mc2017_realistic_v15-v2/260000/3C103261-CDB7-E911-A053-0CC47AFC3D32.root?eos.lfn=fxid:21&eos.ruid=0&eos.rgid=0&eos.injection=1&eos.workflow=retrieve_written&eos.space=default&oss.asize=2769204577" isRepack="0" isVerifyOnly="0" fileBlock="1" ErrorMessage="Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" EWVSize="0"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="857" MSG="No more files to read from tape" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" vo="vo" mediaType="LTO8" tapePool="ctasystest" logicalLibrary="TS4500G1" mountType="Retrieve" labelFormat="0x02" vendor="ibm" capacityInBytes="12000000000000"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="858" MSG="Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0" fileId="161" dstURL="root://storagedev201.fnal.gov//eos/archive/pnfs/fs/usr/cms/WAX/11/store/mc/RunIISummer19UL17HLT/GluGluToHiggs0PL1ToZZTo2mu2tau_M125_GaSM_13TeV_MCFM701_pythia8/GEN-SIM-RAW/94X_mc2017_realistic_v15-v2/260000/3C103261-CDB7-E911-A053-0CC47AFC3D32.root?eos.lfn=fxid:21&eos.ruid=0&eos.rgid=0&eos.injection=1&eos.workflow=retrieve_written&eos.space=default&oss.asize=2769204577" fSeq="1" received_archiveFileID="161" expected_NSBLOCKId="0" received_NSBLOCKId="-1" failed_Status="1"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="857" MSG="In RecallReportPacker::reportDriveStatus(), pushing a report." thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" type="ReportDriveStatus" Status="CleanUp"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="857" MSG="Starting read session cleanup. Signalled end of session to task injector." thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::WorkerThread::run(): Got a new report." thread="RecallReportPacker" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" typeId="castor::tape::tapeserver::daemon::RecallReportPacker::ReportDriveStatus"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::ReportDriveStatus::execute(): reporting drive status." thread="RecallReportPacker" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" status="CleanUp"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="858" MSG="File writing to disk failed" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0" fileId="161" dstURL="root://storagedev201.fnal.gov//eos/archive/pnfs/fs/usr/cms/WAX/11/store/mc/RunIISummer19UL17HLT/GluGluToHiggs0PL1ToZZTo2mu2tau_M125_GaSM_13TeV_MCFM701_pythia8/GEN-SIM-RAW/94X_mc2017_realistic_v15-v2/260000/3C103261-CDB7-E911-A053-0CC47AFC3D32.root?eos.lfn=fxid:21&eos.ruid=0&eos.rgid=0&eos.injection=1&eos.workflow=retrieve_written&eos.space=default&oss.asize=2769204577" fSeq="1" errorMessage="Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" readWriteTime="0.000000" checksumingTime="0.000000" waitDataTime="9.130139" waitReportingTime="0.001754" checkingErrorTime="0.000000" openingTime="0.000000" closingTime="0.000000" transferTime="0.000000" totalTime="0.000000" dataVolume="0" globalPayloadTransferSpeedMBps="0.000000" diskPerformanceMBps="0.000000" openRWCloseToTransferTimeRatio="0.000000"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="858" MSG="Stack trace" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0" fSeq="1" errorMessage="Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" traceFrameNumber="0" traceFrame="/lib64/libctacommon.so.0(cta::exception::Backtrace::Backtrace(bool)+0x69) [0x7f2ec3507cbd]"

And the final part

Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="858" MSG="Stack trace" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0" fSeq="1" errorMessage="Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" traceFrameNumber="1" traceFrame="/lib64/libctacommon.so.0(cta::exception::Exception::Exception(std::string const&, bool)+0x89) [0x7f2ec3509521]"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="858" MSG="Stack trace" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0" fSeq="1" errorMessage="Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" traceFrameNumber="2" traceFrame="/usr/bin/cta-taped() [0x51bdca]"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="858" MSG="Stack trace" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0" fSeq="1" errorMessage="Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" traceFrameNumber="3" traceFrame="/usr/bin/cta-taped() [0x51a79c]"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="858" MSG="Stack trace" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0" fSeq="1" errorMessage="Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" traceFrameNumber="4" traceFrame="/usr/bin/cta-taped() [0x51ee05]"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="858" MSG="Stack trace" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0" fSeq="1" errorMessage="Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" traceFrameNumber="5" traceFrame="/lib64/libctacommon.so.0(cta::threading::Thread::pthread_runner(void*)+0xef) [0x7f2ec352f333]"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="858" MSG="Stack trace" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0" fSeq="1" errorMessage="Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" traceFrameNumber="6" traceFrame="/lib64/libpthread.so.0(+0x7ea5) [0x7f2ec31eaea5]"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="858" MSG="Stack trace" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0" fSeq="1" errorMessage="Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" traceFrameNumber="7" traceFrame="/lib64/libc.so.6(clone+0x6d) [0x7f2ebd0f7b0d]"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="858" MSG="In RecallReportPacker::reportFailedJob(), pushing a report." thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0" fSeq="1" errorMessage="Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" type="ReportError"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="858" MSG="Task failed: counting another error for this session" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0" errorCount="1"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="858" MSG="DiskWriteWorkerThread exiting: no more work" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="858" MSG="Finishing DiskWriteWorkerThread" thread="DiskWrite" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10" threadID="0" threadReadWriteTime="0.000000" threadChecksumingTime="0.000000" threadWaitDataTime="9.130139" threadWaitReportingTime="0.001754" threadCheckingErrorTime="0.000000" threadOpeningTime="0.000000" threadClosingTime="0.000000" threadTransferTime="0.000000" threadTotalTime="34.077580" threadDataVolume="0" threadFileCount="0" threadGlobalPayloadTransferSpeedMBps="0.000000" threadAverageDiskPerformanceMBps="0.000000" threadOpenRWCloseToTransferTimeRatio="0.000000"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::WorkerThread::run(): Got a new report." thread="RecallReportPacker" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" typeId="castor::tape::tapeserver::daemon::RecallReportPacker::ReportError"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="868" MSG="In RecallReportPacker::ReportError::execute(): failing retrieve job after exception." thread="RecallReportPacker" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" failureLog="Aug  2 15:59:07.180257 gmv18018 Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" fileId="161"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="All DiskWriteThreadPool threads are now complete" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="Logging mount general statistics" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" driveManufacturer="IBM" driveType="ULT3580-TD8" firmwareVersion="N4Q0" serialNumber="00078D2BB1" mountTotalNonMediumErrorCounts="0"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="SCSI Statistics could not be acquired from drive" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" driveManufacturer="IBM" driveType="ULT3580-TD8" firmwareVersion="N4Q0" serialNumber="00078D2BB1"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="SCSI Statistics could not be acquired from drive" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" driveManufacturer="IBM" driveType="ULT3580-TD8" firmwareVersion="N4Q0" serialNumber="00078D2BB1"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="857" MSG="In RecallReportPacker::reportDriveStatus(), pushing a report." thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" type="ReportDriveStatus" Status="Unload"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="868" MSG="In Helpers::getLockedAndFetchedQueue<RetrieveQueue>(): Successfully found and locked a retrieve queue." thread="RecallReportPacker" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" attemptNb="1" queueName="VR5775" queueType="jobsToTranfer" queueObject="RetrieveQueueToTransferForUser-VR5775-DriveProcess-LTO8D1-gmv18018.fnal.gov-245605-20220802-15:54:06-0-0" rootFetchNoLockTime="0.000222" rootRelockExclusiveTime="0.015893" rootRefetchTime="0.000194" addOrGetQueueandCommitTime="0.017609" rootUnlockExclusiveTime="0.000761" queueLockTime="0.000785" queueFetchTime="0.001659"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="Heartbeat" LastStateChangeTime="101285" LastHeartBeatTime="101294" LastDataMovementTime="101285" Now="101294" Timeout="101354"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="Heartbeat" LastStateChangeTime="101285" LastHeartBeatTime="101294" LastDataMovementTime="101285" Now="101294" Timeout="101354"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In AgentReference::appyAction(): removed object from ownership (by batch)." agentObject="DriveProcess-LTO8D1-gmv18018.fnal.gov-245605-20220802-15:54:06-0" ownedObject="RetrieveRequest-Frontend-storagedev201.fnal.gov-45076-20220729-14:59:01-0-38"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="868" MSG="In ContainerAlgorithms::referenceAndSwitchOwnership(): Requeued a batch of elements." thread="RecallReportPacker" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" C="RetrieveQueueToTransfer" containerAddress="RetrieveQueueToTransferForUser-VR5775-DriveProcess-LTO8D1-gmv18018.fnal.gov-245605-20220802-15:54:06-0-0" queueFilesBefore="0" queueBytesBefore="0" queueFilesAfter="1" queueBytesAfter="2769204577" queueLockFetchTime="0.037594" queueProcessAndCommitTime="0.008807" asyncUpdateLaunchTime="0.000161" asyncUpdateCompletionTime="0.015771" requestsUpdatingTime="0.000082" queueUnlockTime="0.001288"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="868" MSG="In RetrieveJob::failTransfer(): requeued job for (potentially in-mount) retry." thread="RecallReportPacker" tapeDrive="LTO8D1" mountId="96" fileId="161" copyNb="1" failureReason="Aug  2 15:59:07.180257 gmv18018 Checksum value (blob) expected=0xfeb896d9 actual=0x00000001" requestObject="RetrieveRequest-Frontend-storagedev201.fnal.gov-45076-20220729-14:59:01-0-38" retriesWithinMount="1" maxRetriesWithinMount="3" totalRetries="1" maxTotalRetries="6"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="868" MSG="In OStoreDB::RetrieveJob::~RetrieveJob(): will leave the job owned after destruction." agentObject="DriveProcess-LTO8D1-gmv18018.fnal.gov-245605-20220802-15:54:06-0" jobObject="RetrieveRequest-Frontend-storagedev201.fnal.gov-45076-20220729-14:59:01-0-38"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::WorkerThread::run(): Got a new report." thread="RecallReportPacker" tapeDrive="LTO8D1" mountId="96" typeId="castor::tape::tapeserver::daemon::RecallReportPacker::ReportDriveStatus"
Aug 02 15:59:07 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::ReportDriveStatus::execute(): reporting drive status." thread="RecallReportPacker" tapeDrive="LTO8D1" mountId="96" status="Unload"
Aug 02 15:59:15 gmv18018.fnal.gov cta-taped[245606]: LVL="DEBUG" PID="245606" TID="245606" MSG="In MaintenanceHandler::exceptionThrowingRunChild(): About to do a maintenance pass." SubprocessName="maintenanceHandler"
Aug 02 15:59:18 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="856" MSG="going to report" thread="Watchdog" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96"
Aug 02 15:59:18 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="Heartbeat" LastStateChangeTime="101285" LastHeartBeatTime="101305" LastDataMovementTime="101285" Now="101305" Timeout="101365"
Aug 02 15:59:18 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="Heartbeat" LastStateChangeTime="101285" LastHeartBeatTime="101305" LastDataMovementTime="101285" Now="101305" Timeout="101365"
Aug 02 15:59:18 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="856" MSG="RdbmsCatalogue::updateTapeDriveStatistics(): It didn't update statistics"
Aug 02 15:59:18 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="Heartbeat" LastStateChangeTime="101285" LastHeartBeatTime="101305" LastDataMovementTime="101285" Now="101305" Timeout="101365"
Aug 02 15:59:24 gmv18018.fnal.gov cta-taped[245606]: LVL="DEBUG" PID="245606" TID="245606" MSG="In MaintenanceHandler::exceptionThrowingRunChild(): About to do a maintenance pass." SubprocessName="maintenanceHandler"
Aug 02 15:59:33 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="856" MSG="going to report" thread="Watchdog" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96"
Aug 02 15:59:33 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="Heartbeat" LastStateChangeTime="101285" LastHeartBeatTime="101320" LastDataMovementTime="101285" Now="101320" Timeout="101380"
Aug 02 15:59:33 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="Heartbeat" LastStateChangeTime="101285" LastHeartBeatTime="101320" LastDataMovementTime="101285" Now="101320" Timeout="101380"
Aug 02 15:59:33 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="856" MSG="RdbmsCatalogue::updateTapeDriveStatistics(): It didn't update statistics"
Aug 02 15:59:33 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="Heartbeat" LastStateChangeTime="101285" LastHeartBeatTime="101320" LastDataMovementTime="101285" Now="101320" Timeout="101380"
Aug 02 15:59:33 gmv18018.fnal.gov cta-taped[245606]: LVL="DEBUG" PID="245606" TID="245606" MSG="In MaintenanceHandler::exceptionThrowingRunChild(): About to do a maintenance pass." SubprocessName="maintenanceHandler"
Aug 02 15:59:40 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="TapeReadSingleThread: Tape unloaded" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96"
Aug 02 15:59:40 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="857" MSG="In RecallReportPacker::reportDriveStatus(), pushing a report." thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" type="ReportDriveStatus" Status="Unmount"
Aug 02 15:59:40 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::WorkerThread::run(): Got a new report." thread="RecallReportPacker" tapeDrive="LTO8D1" mountId="96" typeId="castor::tape::tapeserver::daemon::RecallReportPacker::ReportDriveStatus"
Aug 02 15:59:40 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::ReportDriveStatus::execute(): reporting drive status." thread="RecallReportPacker" tapeDrive="LTO8D1" mountId="96" status="Unmount"
Aug 02 15:59:40 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="In DriveHandler::processEvent(): changing session state" tapeDrive="LTO8D1" PreviousState="Running" PreviousType="Retrieve" NewState="Unmounting" NewType="Retrieve"
Aug 02 15:59:40 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" PreviousState="Running" PreviousType="Retrieve" NewState="Unmounting" NewType="Retrieve" TimeoutType="StateChange" LastStateChangeTime="101328" LastHeartBeatTime="101328" LastDataMovementTime="101285" Now="101328" Timeout="101928"
Aug 02 15:59:42 gmv18018.fnal.gov cta-taped[245606]: LVL="DEBUG" PID="245606" TID="245606" MSG="In MaintenanceHandler::exceptionThrowingRunChild(): About to do a maintenance pass." SubprocessName="maintenanceHandler"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="TapeReadSingleThread : tape unmounted" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="857" MSG="In RecallReportPacker::reportDriveStatus(), pushing a report." thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" type="ReportDriveStatus" Status="DrainToDisk"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::WorkerThread::run(): Got a new report." thread="RecallReportPacker" tapeDrive="LTO8D1" mountId="96" typeId="castor::tape::tapeserver::daemon::RecallReportPacker::ReportDriveStatus"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::ReportDriveStatus::execute(): reporting drive status." thread="RecallReportPacker" tapeDrive="LTO8D1" mountId="96" status="DrainToDisk"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="In DriveHandler::processEvent(): changing session state" tapeDrive="LTO8D1" PreviousState="Unmounting" PreviousType="Retrieve" NewState="DrainingToDisk" NewType="Retrieve"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="857" MSG="Tape thread complete" thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" type="read" mountTime="19.513879" positionTime="5.410211" waitInstructionsTime="0.152695" readWriteTime="0.000000" waitFreeMemoryTime="0.000000" waitReportingTime="0.001068" unloadTime="33.602091" unmountTime="6.407405" encryptionControlTime="0.005821" transferTime="0.153763" totalTime="74.085451" dataVolume="0" headerVolume="0" files="0" payloadTransferSpeedMBps="0.000000" driveTransferSpeedMBps="0.000000" status="success"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" PreviousState="Unmounting" PreviousType="Retrieve" NewState="DrainingToDisk" NewType="Retrieve" TimeoutType="Heartbeat" LastStateChangeTime="101334" LastHeartBeatTime="101334" LastDataMovementTime="101285" Now="101334" Timeout="101394"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="857" MSG="In RecallReportPacker::reportEndOfSessionWithErrors(), pushing a report." thread="TapeRead" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" type="ReportEndofSessionWithErrors" mountTime="19.513879" positionTime="5.410211" waitInstructionsTime="0.152695" readWriteTime="0.000000" waitFreeMemoryTime="0.000000" waitReportingTime="0.001068" unloadTime="33.602091" unmountTime="6.407405" encryptionControlTime="0.005821" transferTime="0.153763" totalTime="74.085451" dataVolume="0" headerVolume="0" files="0" payloadTransferSpeedMBps="0.000000" driveTransferSpeedMBps="0.000000" status="success"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::WorkerThread::run(): Got a new report." thread="RecallReportPacker" tapeDrive="LTO8D1" mountId="96" typeId="castor::tape::tapeserver::daemon::RecallReportPacker::ReportEndofSessionWithErrors" goingToEnd="true"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245605]: LVL="ERROR" PID="245605" TID="868" MSG="End of recall session with error(s)" thread="RecallReportPacker" tapeDrive="LTO8D1" mountId="96" errorCode="666"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="Heartbeat" LastStateChangeTime="101334" LastHeartBeatTime="101334" LastDataMovementTime="101285" Now="101334" Timeout="101394"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In cta::RetrieveMount::flushAsyncSuccessReports(): deleted complete retrieve jobs." thread="RecallReportPacker" tapeDrive="LTO8D1" mountId="96" successfulRetrieveJobs="0" files="0" bytes="0" waitUpdateCompletionTime="0.000018" jobBatchFinishingTime="0.019568" schedulerDbTime="0.019611"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="In RecallReportPacker::WorkerThread::run(): all disk threads are finished, telling the mount that Disk threads are complete" thread="RecallReportPacker" tapeDrive="LTO8D1" mountId="96"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="868" MSG="Finishing RecallReportPacker thread" thread="RecallReportPacker" tapeDrive="LTO8D1" mountId="96"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" tapeDrive="LTO8D1" TimeoutType="Heartbeat" LastStateChangeTime="101334" LastHeartBeatTime="101335" LastDataMovementTime="101285" Now="101335" Timeout="101395"
Aug 02 15:59:47 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="856" MSG="RdbmsCatalogue::updateTapeDriveStatistics(): It didn't update statistics"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="In Scheduler::getDriveState(): success." thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" schedulerDbTime="0.001553"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245605]: LVL="DEBUG" PID="245605" TID="245605" MSG="Deleted threads in DiskWriteThreadPool::~DiskWriteThreadPool" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96" threadCount="10"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="RecallMemoryManager destruction : all memory blocks have been deleted" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="96"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245605]: LVL="INFO" PID="245605" TID="245605" MSG="In Agent::removeAndUnregisterSelf(): Removed agent object." agentObject="DriveProcess-LTO8D1-gmv18018.fnal.gov-245605-20220802-15:54:06-0"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="In DriveHandler::processEvent(): Got a peer disconnect: closing socket and waiting for SIGCHILD" tapeDrive="LTO8D1" Message="In SocketPair::receive(): connection reset by peer."
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="In signal handler, received SIGCHLD and propagations to other handlers" signal="Child exited" senderPID="245605" senderUID="0"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="Handler received SIGCHILD. Propagating to all handlers." SubprocessName="signalHandler"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="Propagated SIGCHILD." SubprocessName="signalHandler"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="Propagated SIGCHILD." SubprocessName="drive:LTO8D0"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="Drive subprocess exited. Will spawn a new one." tapeDrive="LTO8D1" pid="245605" exitCode="0"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="Tape session finished" tapeVid="VR5775" mountType="Retrieve" mountId="96" volReqId="96" tapeDrive="LTO8D1" vendor="ibm" vo="vo" mediaType="LTO8" tapePool="ctasystest" logicalLibrary="TS4500G1" capacityInBytes="12000000000000" Error_tapeReadData="1" wasTapeMounted="1" mountTime="19.513879" positionTime="5.410211" waitInstructionsTime="0.152695" waitFreeMemoryTime="0.000000" waitDataTime="0.000000" waitReportingTime="0.001068" checksumingTime="0.000000" readWriteTime="0.000000" flushTime="0.000000" unloadTime="33.602091" unmountTime="6.407405" encryptionControlTime="0.005821" transferTime="0.153763" totalTime="74.085451" deliveryTime="34.217556" drainingTime="0.000000" dataVolume="0" filesCount="0" headerVolume="0" payloadTransferSpeedMBps="0.000000" driveTransferSpeedMBps="0.000000" repackFilesCount="0" userFilesCount="0" verifiedFilesCount="0" repackBytesCount="0" userBytesCount="0" verifiedBytesCount="0" status="failure"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="Propagated SIGCHILD." SubprocessName="drive:LTO8D1"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="Propagated SIGCHILD." SubprocessName="maintenanceHandler"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="Subprocess handler requested forking" SubprocessName="drive:LTO8D1"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245603]: LVL="INFO" PID="245603" TID="245603" MSG="Subprocess handler will fork" SubprocessName="drive:LTO8D1"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[245603]: LVL="DEBUG" PID="245603" TID="245603" MSG="Computed new timeout" SubprocessName="drive:LTO8D1" TimeoutType="Heartbeat" LastStateChangeTime="101335" LastHeartBeatTime="101335" LastDataMovementTime="101335" Now="101335" Timeout="9223372036"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[1073]: LVL="INFO" PID="1073" TID="1073" MSG="In child process. Running child." SubprocessName="drive:LTO8D1"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[1073]: LVL="DEBUG" PID="1073" TID="1073" MSG="In DriveHandler::runChild(): will connect to object store backend." SubprocessName="drive:LTO8D1" backendPath="/mnt/nfs/objectstore"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[1073]: LVL="DEBUG" PID="1073" TID="1073" MSG="In DriveHandler::runChild(): will create agent entry. Enabling leaving non-empty agent behind." SubprocessName="drive:LTO8D1" processName="DriveProcess-LTO8D1"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[1073]: LVL="DEBUG" PID="1073" TID="1073" MSG="In DriveHandler::createCatalogue(): will get catalogue login information." SubprocessName="drive:LTO8D1" fileCatalogConfigFile="/etc/cta/cta-catalogue.conf" caller="DriveHandler::runChild()"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[1073]: LVL="DEBUG" PID="1073" TID="1073" MSG="In DriveHandler::createCatalogue(): will connect to catalogue." SubprocessName="drive:LTO8D1" fileCatalogConfigFile="/etc/cta/cta-catalogue.conf" caller="DriveHandler::runChild()"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[1073]: LVL="DEBUG" PID="1073" TID="1073" MSG="In DriveHandler::runChild(): will create scheduler." SubprocessName="drive:LTO8D1"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[1073]: LVL="DEBUG" PID="1073" TID="1073" MSG="In DriveHandler::runChild(): will ping scheduler." SubprocessName="drive:LTO8D1"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[1073]: LVL="INFO" PID="1073" TID="1073" MSG="In Scheduler::ping(): success." SubprocessName="drive:LTO8D1" catalogueTime="0.033009" schedulerDbTime="0.000671" checkEnvironmentVariablesTime="0.000118"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[1073]: LVL="INFO" PID="1073" TID="1073" MSG="Set process capabilities for using tape" capabilities="= cap_sys_rawio+ep"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[1073]: LVL="DEBUG" PID="1073" TID="1073" MSG="In Scheduler::sortAndGetTapesForMountInfo(): Will consider potential mount" thread="MainThread" tapeDrive="LTO8D1" tapePool="ctasystest" vo="vo" tapeVid="VR5775" mountType="RETRIEVE" existingMountsDistinctTypesForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="2769204577" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="41" youngestJobAge="41" minArchiveRequestAge="1" maxDrives="2" voReadMaxDrives="2" voWriteMaxDrives="2" ratioOfMountQuotaUsed="0.000000"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[1073]: LVL="INFO" PID="1073" TID="1073" MSG="In Scheduler::getNextMountDryRun(): Found a potential mount (retrieve)" thread="MainThread" tapeDrive="LTO8D1" tapePool="ctasystest" tapeVid="VR5775" mountType="RETRIEVE" existingMountsDistinctTypeForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="2769204577" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="41" youngestJobAge="41" minArchiveRequestAge="1" getMountInfoTime="0.020779" getTapeInfoTime="0.023694" candidateSortingTime="0.003805" getTapeForWriteTime="0.000000" decisionTime="0.000242" schedulerDbTime="0.020779" catalogueTime="0.023694"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[1073]: LVL="DEBUG" PID="1073" TID="1073" MSG="In Scheduler::sortAndGetTapesForMountInfo(): Will consider potential mount" thread="MainThread" tapeDrive="LTO8D1" tapePool="ctasystest" vo="vo" tapeVid="VR5775" mountType="RETRIEVE" existingMountsDistinctTypesForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="2769204577" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="41" youngestJobAge="41" minArchiveRequestAge="1" maxDrives="2" voReadMaxDrives="2" voWriteMaxDrives="2" ratioOfMountQuotaUsed="0.000000"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[1073]: LVL="INFO" PID="1073" TID="1073" MSG="In Scheduler::getNextMount(): Selected next mount (retrieve)" thread="MainThread" tapeDrive="LTO8D1" tapePool="ctasystest" tapeVid="VR5775" vo="vo" mediaType="LTO8" labelFormat="0x02" vendor="ibm" mountType="RETRIEVE" existingMountsDistinctTypeForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="2769204577" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="41" youngestJobAge="41" minArchiveRequestAge="1" getMountInfoTime="0.012675" queueTrimingTime="0.000000" getTapeInfoTime="0.013376" candidateSortingTime="0.000680" getTapeForWriteTime="0.000000" decisionTime="0.000147" mountCreationTime="0.015514" driveStatusSetTime="0.000003" schedulerDbTime="0.028192" catalogueTime="0.013376"
Aug 02 15:59:48 gmv18018.fnal.gov cta-taped[1073]: LVL="INFO" PID="1073" TID="1073" MSG="Got volume from client" thread="MainThread" tapeDrive="LTO8D1" tapeVid="VR5775" mountId="97" tapebridgeTransId="97" mountType="Retrieve"

I found the problem. A small but deadly bug in the CPIO header reading code. We’re able to recall Enstore files now.

1 Like