Implement setDriveStatus and updateMountId
After mountID is assigned, we fail to set the drive status:
Apr 1 12:32:26.355093 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="In Scheduler::getNextMountDryRun(): Found a potential mount (archive)" drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11" tapePool="ctasystest" tapeVid="V01007" mountType="ARCHIVE_FOR_USER" existingMountsDistinctTypeForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="6" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="1711967546" youngestJobAge="1711967546" minArchiveRequestAge="0" getMountInfoTime="0.004631" getTapeInfoTime="0.000000" candidateSortingTime="0.001711" getTapeForWriteTime="0.002062" decisionTime="0.000044" schedulerDbTime="0.004631" catalogueTime="0.002062"
Apr 1 12:32:26.355987 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="In PostgresSchedDB::fetchMountInfo(): starting to fetch mount info." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11"
Apr 1 12:32:26.357482 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="In PostgresSchedDB::fetchMountInfo(): pushing back potential mount to the vector." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11"
Apr 1 12:32:26.357515 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="In PostgresSchedDB::fetchMountInfo(): getting drive state." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11"
Apr 1 12:32:26.358021 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="In PostgresSchedDB::fetchMountInfo(): fetched the drive register." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11" queueFetchTime="0.002023" processingTime="0.000000"
Apr 1 12:32:26.358062 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="In PostgresSchedDB::getMountInfo(): success." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11" lockSchedGlobalTime="0.000339" fetchMountInfoTime="0.002070"
Apr 1 12:32:26.358354 tpsrv01 cta-taped: LVL="DEBUG" PID="6932" TID="6932" MSG="In Scheduler::sortAndGetTapesForMountInfo(): Will consider potential mount" drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11" tapePool="ctasystest" vo="vo" mountType="ARCHIVE_FOR_USER" existingMountsDistinctTypesForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="6" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="1711967546" youngestJobAge="1711967546" minArchiveRequestAge="0" maxDrives="1" voReadMaxDrives="1" voWriteMaxDrives="1" ratioOfMountQuotaUsed="0.000000"
Apr 1 12:32:26.359890 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="In Scheduler::getNextMount(): Selected next mount (archive)" drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11" tapePool="ctasystest" tapeVid="V01007" vo="vo" mediaType="T10K500G" vendor="vendor" mountType="ARCHIVE_FOR_USER" existingMountsDistinctTypeForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="6" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="1711967546" youngestJobAge="1711967546" minArchiveRequestAge="0" getMountInfoTime="0.002634" queueTrimingTime="0.000000" getTapeInfoTime="0.000000" candidateSortingTime="0.000343" getTapeForWriteTime="0.000855" decisionTime="0.000066" mountCreationTime="0.000457" driveStatusSetTime="0.000002" schedulerDbTime="0.003093" catalogueTime="0.000855"
Apr 1 12:32:26.362628 tpsrv01 cta-taped: LVL="ERROR" PID="6932" TID="6932" MSG="Aborting cta-taped on uncaught exception. Stack trace follows." drive_name="VDSTK11" instance="CI" sched_backend="VFS" Message="Not implemented"
Apr 1 12:32:26.362677 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="0" traceFrame="/lib64/libctacommon.so.0(cta::exception::Backtrace::Backtrace(bool)+0x6b) [0x7f461ff88333]"
Apr 1 12:32:26.362699 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="1" traceFrame="/lib64/libctacommon.so.0(cta::exception::Exception::Exception(std::basic_string_view<char, std::char_traits<char> >, bool)+0x91) [0x7f461ff8934b]"
Apr 1 12:32:26.362721 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="2" traceFrame="/lib64/libctascheduler.so.0(cta::postgresscheddb::ArchiveMount::setDriveStatus(cta::common::dataStructures::DriveStatus, cta::common::dataStructures::MountType, long, std::optional<std::string> const&)+0x6a) [0x7f4621429eaa]"
Apr 1 12:32:26.362743 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="3" traceFrame="/lib64/libctascheduler.so.0(cta::ArchiveMount::setDriveStatus(cta::common::dataStructures::DriveStatus, std::optional<std::string> const&)+0x7f) [0x7f462135959b]"
Apr 1 12:32:26.362765 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="4" traceFrame="/usr/bin/cta-taped() [0x4abfb7]"
Apr 1 12:32:26.362780 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="5" traceFrame="/usr/bin/cta-taped() [0x46dbb0]"
Apr 1 12:32:26.362793 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="6" traceFrame="/usr/bin/cta-taped() [0x46a1a1]"
Apr 1 12:32:26.362807 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="7" traceFrame="/usr/bin/cta-taped() [0x491472]"
Apr 1 12:32:26.362820 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="8" traceFrame="/usr/bin/cta-taped() [0x490628]"
Apr 1 12:32:26.362833 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="9" traceFrame="/usr/bin/cta-taped() [0x45cccb]"
Apr 1 12:32:26.362847 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="10" traceFrame="/usr/bin/cta-taped() [0x45c9a2]"
Apr 1 12:32:26.362860 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="11" traceFrame="/usr/bin/cta-taped() [0x45c3bd]"
Apr 1 12:32:26.362874 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="12" traceFrame="/usr/bin/cta-taped() [0x454d05]"
Apr 1 12:32:26.362887 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="13" traceFrame="/usr/bin/cta-taped() [0x4553da]"
Apr 1 12:32:26.362901 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="14" traceFrame="/lib64/libc.so.6(__libc_start_main+0xf5) [0x7f4619b38555]"
Apr 1 12:32:26.362916 tpsrv01 cta-taped: LVL="INFO" PID="6932" TID="6932" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="15" traceFrame="/usr/bin/cta-taped() [0x454839]"
Apr 1 12:32:26.363367 tpsrv01 cta-taped: LVL="DEBUG" PID="286" TID="286" MSG="In DriveHandler::processEvent(): Got a peer disconnect: closing socket and waiting for SIGCHILD" drive_name="VDSTK11" instance="CI" sched_backend="VFS" tapeDrive="VDSTK11" Message="In SocketPair::receive(): connection reset by peer."
Apr 1 12:32:26.367014 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="In signal handler, received SIGCHLD and propagations to other handlers" drive_name="VDSTK11" instance="CI" sched_backend="VFS" signal="Child exited" senderPID="6932" senderUID="0"
Apr 1 12:32:26.367044 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Handler received SIGCHILD. Propagating to all handlers." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="signalHandler"
Apr 1 12:32:26.367057 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Propagated SIGCHILD." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="signalHandler"
Apr 1 12:32:26.367069 tpsrv01 cta-taped: LVL="DEBUG" PID="286" TID="286" MSG="In DriveHandler::processSigChild(): calling waitpid()" drive_name="VDSTK11" instance="CI" sched_backend="VFS" tapeDrive="VDSTK11"
Apr 1 12:32:26.367087 tpsrv01 cta-taped: LVL="DEBUG" PID="286" TID="286" MSG="In DriveHandler::processSigChild(): waitpid() returned 6932" drive_name="VDSTK11" instance="CI" sched_backend="VFS" tapeDrive="VDSTK11"
Apr 1 12:32:26.367101 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Drive subprocess exited. Will spawn a new one." drive_name="VDSTK11" instance="CI" sched_backend="VFS" tapeDrive="VDSTK11" pid="6932" exitCode="1"
Apr 1 12:32:26.367125 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Tape session finished" drive_name="VDSTK11" instance="CI" sched_backend="VFS" tapeDrive="VDSTK11" pid="6932" exitCode="1" killSignal="0"
Apr 1 12:32:26.367143 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Propagated SIGCHILD." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11"
Apr 1 12:32:26.367155 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Propagated SIGCHILD." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="maintenanceHandler"
Apr 1 12:32:26.367167 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Subprocess handler requested forking" drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11"
Apr 1 12:32:26.367178 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Subprocess handler will fork" drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11"
Apr 1 12:32:26.368018 tpsrv01 cta-taped: LVL="DEBUG" PID="286" TID="286" MSG="Computed new timeout" drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11" TimeoutType="" LastStateChangeTime="53307" LastHeartBeatTime="53307" LastDataMovementTime="53307" Now="53307" Timeout="9223372036"
Apr 1 12:32:26.368520 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="In child process. Running child." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11"
Apr 1 12:32:26.368718 tpsrv01 cta-taped: LVL="DEBUG" PID="6933" TID="6933" MSG="In DriveHandler::runChild(): will connect to object store backend." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11" backendPath="postgresql:postgresql://cta:cta@postgres-sched/postgres-sched"
Apr 1 12:32:26.368737 tpsrv01 cta-taped: LVL="DEBUG" PID="6933" TID="6933" MSG="In DriveHandler::runChild(): will create scheduler." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11"
Apr 1 12:32:26.368751 tpsrv01 cta-taped: LVL="DEBUG" PID="6933" TID="6933" MSG="In DriveHandler::createScheduler(): will create agent entry. Enabling leaving non-empty agent behind." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11" processName="DriveProcess-VDSTK11"
Apr 1 12:32:26.369201 tpsrv01 cta-taped: LVL="DEBUG" PID="6933" TID="6933" MSG="In DriveHandler::createCatalogue(): will get catalogue login information." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11" fileCatalogConfigFile="/etc/cta/cta-catalogue.conf" processName="DriveProcess-VDSTK11"
Apr 1 12:32:26.369401 tpsrv01 cta-taped: LVL="DEBUG" PID="6933" TID="6933" MSG="In DriveHandler::createCatalogue(): will connect to catalogue." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11" fileCatalogConfigFile="/etc/cta/cta-catalogue.conf" processName="DriveProcess-VDSTK11"
Apr 1 12:32:26.371573 tpsrv01 cta-taped: LVL="DEBUG" PID="6933" TID="6933" MSG="In DriveHandler::createScheduler(): will create scheduler." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11"
Apr 1 12:32:26.371743 tpsrv01 cta-taped: LVL="DEBUG" PID="6933" TID="6933" MSG="In DriveHandler::runChild(): will ping scheduler." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11"
Apr 1 12:32:26.379934 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="In Scheduler::ping(): success." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11" catalogueTime="0.004210" schedulerDbTime="0.003874" checkEnvironmentVariablesTime="0.000049"
Apr 1 12:32:26.380077 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Set process capabilities for using tape" drive_name="VDSTK11" instance="CI" sched_backend="VFS" capabilities="= cap_sys_rawio+ep"
Apr 1 12:32:26.380124 tpsrv01 cta-taped: LVL="DEBUG" PID="6933" TID="6933" MSG="Transition from down to up starting." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11"
Apr 1 12:32:26.382888 tpsrv01 cta-taped: LVL="DEBUG" PID="6933" TID="6933" MSG="In Scheduler::getDesiredDriveState(): checking driveName: VDSTK11 against existing: VDSTK11" drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11"
Apr 1 12:32:26.382935 tpsrv01 cta-taped: LVL="DEBUG" PID="6933" TID="6933" MSG="Desired drive state is UP." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11"
Apr 1 12:32:26.385254 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="In PostgresSchedDB::fetchMountInfo(): starting to fetch mount info." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11"
Apr 1 12:32:26.388721 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="In PostgresSchedDB::fetchMountInfo(): pushing back potential mount to the vector." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11"
Apr 1 12:32:26.388787 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="In PostgresSchedDB::fetchMountInfo(): getting drive state." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11"
Apr 1 12:32:26.389321 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="In PostgresSchedDB::fetchMountInfo(): fetched the drive register." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11" queueFetchTime="0.004053" processingTime="0.000003"
Apr 1 12:32:26.389414 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="In PostgresSchedDB::getMountInfoNoLock(): success." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11" fetchNoLockTime="0.000162" fetchMountInfoTime="0.004145"
Apr 1 12:32:26.391184 tpsrv01 cta-taped: LVL="DEBUG" PID="6933" TID="6933" MSG="In Scheduler::sortAndGetTapesForMountInfo(): Will consider potential mount" drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11" tapePool="ctasystest" vo="vo" mountType="ARCHIVE_FOR_USER" existingMountsDistinctTypesForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="6" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="1711967546" youngestJobAge="1711967546" minArchiveRequestAge="0" maxDrives="1" voReadMaxDrives="1" voWriteMaxDrives="1" ratioOfMountQuotaUsed="0.000000"
Apr 1 12:32:26.393599 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="In Scheduler::getNextMountDryRun(): Found a potential mount (archive)" drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11" tapePool="ctasystest" tapeVid="V01007" mountType="ARCHIVE_FOR_USER" existingMountsDistinctTypeForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="6" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="1711967546" youngestJobAge="1711967546" minArchiveRequestAge="0" getMountInfoTime="0.004984" getTapeInfoTime="0.000000" candidateSortingTime="0.001838" getTapeForWriteTime="0.002188" decisionTime="0.000047" schedulerDbTime="0.004984" catalogueTime="0.002188"
Apr 1 12:32:26.394520 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="In PostgresSchedDB::fetchMountInfo(): starting to fetch mount info." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11"
Apr 1 12:32:26.396005 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="In PostgresSchedDB::fetchMountInfo(): pushing back potential mount to the vector." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11"
Apr 1 12:32:26.396037 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="In PostgresSchedDB::fetchMountInfo(): getting drive state." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11"
Apr 1 12:32:26.396477 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="In PostgresSchedDB::fetchMountInfo(): fetched the drive register." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11" queueFetchTime="0.001944" processingTime="0.000001"
Apr 1 12:32:26.396528 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="In PostgresSchedDB::getMountInfo(): success." drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11" lockSchedGlobalTime="0.000355" fetchMountInfoTime="0.002002"
Apr 1 12:32:26.396838 tpsrv01 cta-taped: LVL="DEBUG" PID="6933" TID="6933" MSG="In Scheduler::sortAndGetTapesForMountInfo(): Will consider potential mount" drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11" tapePool="ctasystest" vo="vo" mountType="ARCHIVE_FOR_USER" existingMountsDistinctTypesForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="6" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="1711967546" youngestJobAge="1711967546" minArchiveRequestAge="0" maxDrives="1" voReadMaxDrives="1" voWriteMaxDrives="1" ratioOfMountQuotaUsed="0.000000"
Apr 1 12:32:26.398424 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="In Scheduler::getNextMount(): Selected next mount (archive)" drive_name="VDSTK11" instance="CI" sched_backend="VFS" thread="MainThread" tapeDrive="VDSTK11" tapePool="ctasystest" tapeVid="V01007" vo="vo" mediaType="T10K500G" vendor="vendor" mountType="ARCHIVE_FOR_USER" existingMountsDistinctTypeForThisTapepool="0" existingMountsBasicTypeForThisVo="0" bytesQueued="6" minBytesToWarrantMount="2000000" filesQueued="1" minFilesToWarrantMount="100" oldestJobAge="1711967546" youngestJobAge="1711967546" minArchiveRequestAge="0" getMountInfoTime="0.002621" queueTrimingTime="0.000000" getTapeInfoTime="0.000000" candidateSortingTime="0.000358" getTapeForWriteTime="0.000899" decisionTime="0.000074" mountCreationTime="0.000451" driveStatusSetTime="0.000002" schedulerDbTime="0.003074" catalogueTime="0.000899"
Apr 1 12:32:26.401319 tpsrv01 cta-taped: LVL="ERROR" PID="6933" TID="6933" MSG="Aborting cta-taped on uncaught exception. Stack trace follows." drive_name="VDSTK11" instance="CI" sched_backend="VFS" Message="Not implemented"
Apr 1 12:32:26.401369 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="0" traceFrame="/lib64/libctacommon.so.0(cta::exception::Backtrace::Backtrace(bool)+0x6b) [0x7f461ff88333]"
Apr 1 12:32:26.401392 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="1" traceFrame="/lib64/libctacommon.so.0(cta::exception::Exception::Exception(std::basic_string_view<char, std::char_traits<char> >, bool)+0x91) [0x7f461ff8934b]"
Apr 1 12:32:26.401414 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="2" traceFrame="/lib64/libctascheduler.so.0(cta::postgresscheddb::ArchiveMount::setDriveStatus(cta::common::dataStructures::DriveStatus, cta::common::dataStructures::MountType, long, std::optional<std::string> const&)+0x6a) [0x7f4621429eaa]"
Apr 1 12:32:26.401436 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="3" traceFrame="/lib64/libctascheduler.so.0(cta::ArchiveMount::setDriveStatus(cta::common::dataStructures::DriveStatus, std::optional<std::string> const&)+0x7f) [0x7f462135959b]"
Apr 1 12:32:26.401454 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="4" traceFrame="/usr/bin/cta-taped() [0x4abfb7]"
Apr 1 12:32:26.401468 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="5" traceFrame="/usr/bin/cta-taped() [0x46dbb0]"
Apr 1 12:32:26.401486 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="6" traceFrame="/usr/bin/cta-taped() [0x46a1a1]"
Apr 1 12:32:26.401500 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="7" traceFrame="/usr/bin/cta-taped() [0x491472]"
Apr 1 12:32:26.401513 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="8" traceFrame="/usr/bin/cta-taped() [0x490628]"
Apr 1 12:32:26.401527 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="9" traceFrame="/usr/bin/cta-taped() [0x45cccb]"
Apr 1 12:32:26.401540 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="10" traceFrame="/usr/bin/cta-taped() [0x45c9a2]"
Apr 1 12:32:26.401554 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="11" traceFrame="/usr/bin/cta-taped() [0x45c3bd]"
Apr 1 12:32:26.401567 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="12" traceFrame="/usr/bin/cta-taped() [0x454d05]"
Apr 1 12:32:26.401581 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="13" traceFrame="/usr/bin/cta-taped() [0x4553da]"
Apr 1 12:32:26.401594 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="14" traceFrame="/lib64/libc.so.6(__libc_start_main+0xf5) [0x7f4619b38555]"
Apr 1 12:32:26.401609 tpsrv01 cta-taped: LVL="INFO" PID="6933" TID="6933" MSG="Stack trace" drive_name="VDSTK11" instance="CI" sched_backend="VFS" traceFrameNumber="15" traceFrame="/usr/bin/cta-taped() [0x454839]"
Apr 1 12:32:26.402052 tpsrv01 cta-taped: LVL="DEBUG" PID="286" TID="286" MSG="In DriveHandler::processEvent(): Got a peer disconnect: closing socket and waiting for SIGCHILD" drive_name="VDSTK11" instance="CI" sched_backend="VFS" tapeDrive="VDSTK11" Message="In SocketPair::receive(): connection reset by peer."
Apr 1 12:32:26.405837 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="In signal handler, received SIGCHLD and propagations to other handlers" drive_name="VDSTK11" instance="CI" sched_backend="VFS" signal="Child exited" senderPID="6933" senderUID="0"
Apr 1 12:32:26.405931 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Handler received SIGCHILD. Propagating to all handlers." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="signalHandler"
Apr 1 12:32:26.405995 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Propagated SIGCHILD." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="signalHandler"
Apr 1 12:32:26.406039 tpsrv01 cta-taped: LVL="DEBUG" PID="286" TID="286" MSG="In DriveHandler::processSigChild(): calling waitpid()" drive_name="VDSTK11" instance="CI" sched_backend="VFS" tapeDrive="VDSTK11"
Apr 1 12:32:26.406091 tpsrv01 cta-taped: LVL="DEBUG" PID="286" TID="286" MSG="In DriveHandler::processSigChild(): waitpid() returned 6933" drive_name="VDSTK11" instance="CI" sched_backend="VFS" tapeDrive="VDSTK11"
Apr 1 12:32:26.406140 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Drive subprocess exited. Will spawn a new one." drive_name="VDSTK11" instance="CI" sched_backend="VFS" tapeDrive="VDSTK11" pid="6933" exitCode="1"
Apr 1 12:32:26.406244 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Tape session finished" drive_name="VDSTK11" instance="CI" sched_backend="VFS" tapeDrive="VDSTK11" pid="6933" exitCode="1" killSignal="0"
Apr 1 12:32:26.406270 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Propagated SIGCHILD." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11"
Apr 1 12:32:26.406283 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Propagated SIGCHILD." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="maintenanceHandler"
Apr 1 12:32:26.406295 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Subprocess handler requested forking" drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11"
Apr 1 12:32:26.406305 tpsrv01 cta-taped: LVL="INFO" PID="286" TID="286" MSG="Subprocess handler will fork" drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11"
Apr 1 12:32:26.407153 tpsrv01 cta-taped: LVL="DEBUG" PID="286" TID="286" MSG="Computed new timeout" drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11" TimeoutType="" LastStateChangeTime="53307" LastHeartBeatTime="53307" LastDataMovementTime="53307" Now="53307" Timeout="9223372036"
Apr 1 12:32:26.407462 tpsrv01 cta-taped: LVL="INFO" PID="6934" TID="6934" MSG="In child process. Running child." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11"
Apr 1 12:32:26.407684 tpsrv01 cta-taped: LVL="DEBUG" PID="6934" TID="6934" MSG="In DriveHandler::runChild(): will connect to object store backend." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11" backendPath="postgresql:postgresql://cta:cta@postgres-sched/postgres-sched"
Apr 1 12:32:26.407703 tpsrv01 cta-taped: LVL="DEBUG" PID="6934" TID="6934" MSG="In DriveHandler::runChild(): will create scheduler." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11"
Apr 1 12:32:26.407717 tpsrv01 cta-taped: LVL="DEBUG" PID="6934" TID="6934" MSG="In DriveHandler::createScheduler(): will create agent entry. Enabling leaving non-empty agent behind." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11" processName="DriveProcess-VDSTK11"
Apr 1 12:32:26.408184 tpsrv01 cta-taped: LVL="DEBUG" PID="6934" TID="6934" MSG="In DriveHandler::createCatalogue(): will get catalogue login information." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11" fileCatalogConfigFile="/etc/cta/cta-catalogue.conf" processName="DriveProcess-VDSTK11"
Apr 1 12:32:26.408402 tpsrv01 cta-taped: LVL="DEBUG" PID="6934" TID="6934" MSG="In DriveHandler::createCatalogue(): will connect to catalogue." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11" fileCatalogConfigFile="/etc/cta/cta-catalogue.conf" processName="DriveProcess-VDSTK11"
Apr 1 12:32:26.410610 tpsrv01 cta-taped: LVL="DEBUG" PID="6934" TID="6934" MSG="In DriveHandler::createScheduler(): will create scheduler." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11"
Apr 1 12:32:26.410782 tpsrv01 cta-taped: LVL="DEBUG" PID="6934" TID="6934" MSG="In DriveHandler::runChild(): will ping scheduler." drive_name="VDSTK11" instance="CI" sched_backend="VFS" SubprocessName="drive:VDSTK11"
Edited by Jaroslav Guenther