Split a log line into 2 stepts to clarify logs timings.

The log for unlock appeared way after the action happened, and subsequent locks appeared as
in violation of the lock (at first sight).

objectstore/ArchiveRequest.cpp

@@ -322,6 +322,16 @@ void ArchiveRequest::garbageCollect(const std::string &presumedOwner, AgentRefer
         commit();
         aql.release();
         auto commitUnlockQueueTime = t.secs(utils::Timer::resetCounter);
+        {
+          log::ScopedParamContainer params(lc);
+          params.add("jobObject", getAddressIfSet())
+                .add("queueObject", queueObject)
+                .add("presumedOwner", presumedOwner)
+                .add("copyNb", j->copynb())
+                .add("queueUpdateTime", queueUpdateTime)
+                .add("commitUnlockQueueTime", commitUnlockQueueTime);
+          lc.log(log::INFO, "In ArchiveRequest::garbageCollect(): requeued job.");
+        }
         timespec ts;
         // We will sleep a bit to make sure other processes can also access the queue
         // as we are very likely to be part of a tight loop.
@@ -338,11 +348,8 @@ void ArchiveRequest::garbageCollect(const std::string &presumedOwner, AgentRefer
         params.add("jobObject", getAddressIfSet())
               .add("queueObject", queueObject)
               .add("presumedOwner", presumedOwner)
-              .add("copyNb", j->copynb())
-              .add("queueUpdateTime", queueUpdateTime)
-              .add("commitUnlockQueueTime", commitUnlockQueueTime)
               .add("sleepTime", sleepTime);
-        lc.log(log::INFO, "In ArchiveRequest::garbageCollect(): requeued job.");
+        lc.log(log::INFO, "In ArchiveRequest::garbageCollect(): slept some time to not sit on the queue after GC requeueing.");
       } catch (...) {
         // We could not requeue the job: fail it.
         j->set_status(serializers::AJS_Failed);

objectstore/RetrieveRequest.cpp

@@ -152,6 +152,17 @@ jobFound:;
   Helpers::updateRetrieveQueueStatisticsCache(bestVid, jobsSummary.files, jobsSummary.bytes, jobsSummary.priority);
   rql.release();
   auto commitUnlockQueueTime = t.secs(utils::Timer::resetCounter);
+  {
+    log::ScopedParamContainer params(lc);
+    params.add("jobObject", getAddressIfSet())
+          .add("queueObject", rq.getAddressIfSet())
+          .add("copynb", bestTapeFile->copynb())
+          .add("vid", bestTapeFile->vid())
+          .add("tapeSelectionTime", tapeSelectionTime)
+          .add("queueUpdateTime", queueUpdateTime)
+          .add("commitUnlockQueueTime", commitUnlockQueueTime);
+    lc.log(log::INFO, "In RetrieveRequest::garbageCollect(): requeued the request.");
+  }
   timespec ts;
   // We will sleep a bit to make sure other processes can also access the queue
   // as we are very likely to be part of a tight loop.
@@ -170,11 +181,8 @@ jobFound:;
           .add("queueObject", rq.getAddressIfSet())
           .add("copynb", bestTapeFile->copynb())
           .add("vid", bestTapeFile->vid())
-          .add("tapeSelectionTime", tapeSelectionTime)
-          .add("queueUpdateTime", queueUpdateTime)
-          .add("commitUnlockQueueTime", commitUnlockQueueTime)
           .add("sleepTime", sleepTime);
-    lc.log(log::INFO, "In RetrieveRequest::garbageCollect(): requeued the request.");
+    lc.log(log::INFO, "In RetrieveRequest::garbageCollect(): slept some time to not sit on the queue after GC requeueing.");
   }
 }