[cta-taped] Added logging for the time the drive takes to load a tape

ReleaseNotes.md

@@ -4,7 +4,9 @@
 
 ### Features
 
+- Upgraded EOS to 4.8.35-1
 - cta/CTA#954 The drive is put down if the CleanerSession fails to eject the tape from it after a shutdown
+- cta/CTA#945 The timeout for tape load action is now configurable
 
 ### Bug fixes
 

cta.spec.in

@@ -492,7 +492,9 @@ Currently contains a helper for the client-ar script, which should be installed
 
 %changelog
 * Thu Jan 07 2021 julien.leduc (at) cern.ch - 3.1-14
+- Upgraded EOS to 4.8.35-1
 - cta/CTA#954 The drive is put down if the CleanerSession fails to eject the tape from it after a shutdown
+- cta/CTA#945 The timeout for tape load action is now configurable
 - cta/CTA#957 The state of the successful Archive for repack jobs is now changed before being queued for reporting
 - cta/CTA#958 The RepackRequest garbage collection now changes the owner of the garbage collected RepackRequest.
 * Thu Jan 07 2021 julien.leduc (at) cern.ch - 3.1-13

tapeserver/castor/tape/tapeserver/daemon/TapeReadSingleThread.cpp

@@ -253,13 +253,16 @@ void castor::tape::tapeserver::daemon::TapeReadSingleThread::run() {
       m_logContext.log(cta::log::INFO, "Tape session started");
       mountTapeReadOnly();
       currentErrorToCount = "Error_tapeLoad";
+      cta::utils::Timer tapeLoadTimer;
       waitForDrive();
+      double tapeLoadTime = tapeLoadTimer.secs();
       currentErrorToCount = "Error_checkingTapeAlert";
       logTapeAlerts();
       m_stats.mountTime += timer.secs(cta::utils::Timer::resetCounter);
       {
         cta::log::ScopedParamContainer scoped(m_logContext);
         scoped.add("mountTime", m_stats.mountTime);
+        scoped.add("tapeLoadTime",tapeLoadTime);
         m_logContext.log(cta::log::INFO, "Tape mounted and drive ready");
       }
       m_retrieveMount.setTapeMounted(m_logContext);

tapeserver/castor/tape/tapeserver/daemon/TapeSingleThreadInterface.hpp

@@ -151,14 +151,16 @@ protected:
    * case of timeout)
    */
   void waitForDrive(){
+    cta::utils::Timer tapeLoadTime;
     try{
-      cta::utils::Timer timer;
       // wait tapeLoadTimeout seconds for drive to be ready (the mount call is synchronous, so this just the load operation.
       m_drive.waitUntilReady(m_tapeLoadTimeout);
-      cta::log::LogContext::ScopedParam sp0(m_logContext, cta::log::Param("loadTime", timer.secs()));
     }catch(const cta::exception::Exception& e){
-      cta::log::LogContext::ScopedParam sp01(m_logContext, cta::log::Param("exceptionMessage", e.getMessageValue()));
-      m_logContext.log(cta::log::INFO, "Got timeout or error while waiting for drive to be ready.");
+      cta::log::ScopedParamContainer spc(m_logContext);
+      spc.add("exceptionMessage",e.getMessageValue())
+         .add("configuredTapeLoadTimeout",m_tapeLoadTimeout)
+         .add("tapeLoadTime",tapeLoadTime.secs());
+      m_logContext.log(cta::log::ERR, "Got timeout or error while waiting for drive to be ready.");
       throw;
     }
   }

tapeserver/castor/tape/tapeserver/daemon/TapeWriteSingleThread.cpp

@@ -327,7 +327,9 @@ void castor::tape::tapeserver::daemon::TapeWriteSingleThread::run() {
       m_logContext.log(cta::log::INFO, "Tape session started");
       mountTapeReadWrite();
       currentErrorToCount = "Error_tapeLoad";
+      cta::utils::Timer tapeLoadTimer;
       waitForDrive();
+      double tapeLoadTime = tapeLoadTimer.secs();
       currentErrorToCount = "Error_checkingTapeAlert";
       if(logAndCheckTapeAlertsForWrite()) {
         throw cta::exception::Exception("Aborting migration session in"
@@ -341,6 +343,7 @@ void castor::tape::tapeserver::daemon::TapeWriteSingleThread::run() {
       {
         cta::log::ScopedParamContainer scoped(m_logContext);
         scoped.add("mountTime", m_stats.mountTime);
+        scoped.add("tapeLoadTime",tapeLoadTime);
         m_logContext.log(cta::log::INFO, "Tape mounted and drive ready");
       }
       m_archiveMount.setTapeMounted(m_logContext);