From 6517cda5181f8267d4b8da05cdc681ad6f39eb4b Mon Sep 17 00:00:00 2001
From: Cedric Caffy <cedric.caffy@cern.ch>
Date: Fri, 15 Jan 2021 12:25:34 +0100
Subject: [PATCH] [cta-taped] Added logging for the time the drive takes to
 load a tape

---
 ReleaseNotes.md                                        |  2 ++
 cta.spec.in                                            |  2 ++
 .../tape/tapeserver/daemon/TapeReadSingleThread.cpp    |  3 +++
 .../tapeserver/daemon/TapeSingleThreadInterface.hpp    | 10 ++++++----
 .../tape/tapeserver/daemon/TapeWriteSingleThread.cpp   |  3 +++
 5 files changed, 16 insertions(+), 4 deletions(-)

diff --git a/ReleaseNotes.md b/ReleaseNotes.md
index 65d578b3d1..76d35ffc34 100644
--- a/ReleaseNotes.md
+++ b/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
 
diff --git a/cta.spec.in b/cta.spec.in
index 34eed5927c..4bd787b035 100644
--- a/cta.spec.in
+++ b/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
diff --git a/tapeserver/castor/tape/tapeserver/daemon/TapeReadSingleThread.cpp b/tapeserver/castor/tape/tapeserver/daemon/TapeReadSingleThread.cpp
index f4d87a3853..e964579a42 100644
--- a/tapeserver/castor/tape/tapeserver/daemon/TapeReadSingleThread.cpp
+++ b/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);
diff --git a/tapeserver/castor/tape/tapeserver/daemon/TapeSingleThreadInterface.hpp b/tapeserver/castor/tape/tapeserver/daemon/TapeSingleThreadInterface.hpp
index 4cb73032f8..5efa283b09 100644
--- a/tapeserver/castor/tape/tapeserver/daemon/TapeSingleThreadInterface.hpp
+++ b/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;
     }
   }
diff --git a/tapeserver/castor/tape/tapeserver/daemon/TapeWriteSingleThread.cpp b/tapeserver/castor/tape/tapeserver/daemon/TapeWriteSingleThread.cpp
index f4cf3489b9..fea50ba212 100644
--- a/tapeserver/castor/tape/tapeserver/daemon/TapeWriteSingleThread.cpp
+++ b/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);
-- 
GitLab