CcdbApi: Fixed logReading in vectoredLoadFileTomemory (AliceO2Group#1…

…2276)

* CcdbApi: Fixed logReading in vectoredLoadFileTomemory

* CcdbDownloader: Better transfer info logging

* Formatting fix

* Removed whitespace

CCDB/include/CCDB/CCDBDownloader.h

@@ -51,6 +51,7 @@ typedef struct DownloaderRequestData {
   long timestamp;
   HeaderObjectPair_t hoPair;
   std::map<std::string, std::string>* headers;
+  std::string userAgent;
 
   std::function<bool(std::string)> localContentCallback;
   bool errorflag = false;
@@ -208,6 +209,11 @@ class CCDBDownloader
    */
   void runLoop(bool noWait);
 
+  /**
+   * Returns a message describing the transfer an it's result.
+   */
+  std::string prepareLogMessage(std::string host_url, std::string userAgent, const std::string& path, long ts, const std::map<std::string, std::string>* headers, long httpCode) const;
+
   /**
    * Leaves only the protocol and host part of the url, discrading path and metadata.
    */

CCDB/src/CCDBDownloader.cxx

@@ -493,21 +493,25 @@ void CCDBDownloader::transferFinished(CURL* easy_handle, CURLcode curlCode)
       curl_easy_getinfo(easy_handle, CURLINFO_EFFECTIVE_URL, &url);
       LOG(debug) << "Transfer for " << url << " finished with code " << httpCode << "\n";
 
+      std::string currentHost = requestData->hosts[performData->hostInd];
+      std::string loggingMessage = prepareLogMessage(currentHost, requestData->userAgent, requestData->path, requestData->timestamp, requestData->headers, httpCode);
+
       // Get alternative locations for the same host
       auto locations = getLocations(&(requestData->hoPair.header));
 
       // React to received http code
-      if (404 == httpCode) {
-        LOG(error) << "Requested resource does not exist: " << url;
-      } else if (304 == httpCode) {
-        LOGP(debug, "Object exists but I am not serving it since it's already in your possession");
-        contentRetrieved = true;
-      } else if (300 <= httpCode && httpCode < 400 && performData->locInd < locations.size()) {
-        followRedirect(performData, easy_handle, locations, rescheduled, contentRetrieved);
-      } else if (200 <= httpCode && httpCode < 300) {
-        contentRetrieved = true;
+      if (200 <= httpCode && httpCode < 400) {
+        LOG(debug) << loggingMessage;
+        if (304 == httpCode) {
+          LOGP(debug, "Object exists but I am not serving it since it's already in your possession");
+          contentRetrieved = true;
+        } else if (300 <= httpCode && httpCode < 400 && performData->locInd < locations.size()) {
+          followRedirect(performData, easy_handle, locations, rescheduled, contentRetrieved);
+        } else if (200 <= httpCode && httpCode < 300) {
+          contentRetrieved = true;
+        }
       } else {
-        LOG(error) << "Error in fetching object " << url << ", curl response code:" << httpCode;
+        LOG(error) << loggingMessage;
       }
 
       // Check if content was retrieved, or scheduled to be retrieved
@@ -694,4 +698,21 @@ void CCDBDownloader::asynchSchedule(CURL* handle, size_t* requestCounter)
   // return codeVector;
 }
 
+std::string CCDBDownloader::prepareLogMessage(std::string host_url, std::string userAgent, const std::string& path, long ts, const std::map<std::string, std::string>* headers, long httpCode) const
+{
+  std::string upath{path};
+  if (headers) {
+    auto ent = headers->find("Valid-From");
+    if (ent != headers->end()) {
+      upath += "/" + ent->second;
+    }
+    ent = headers->find("ETag");
+    if (ent != headers->end()) {
+      upath += "/" + ent->second;
+    }
+  }
+  upath.erase(remove(upath.begin(), upath.end(), '\"'), upath.end());
+  return fmt::format("CcdbDownloader finished transfer {}{}{} for {} (agent_id: {}) with http code: {}", host_url, (host_url.back() == '/') ? "" : "/", upath, (ts < 0) ? getCurrentTimestamp() : ts, userAgent, httpCode);
+}
+
 } // namespace o2

CCDB/src/CcdbApi.cxx

@@ -1533,6 +1533,7 @@ void CcdbApi::scheduleDownload(RequestContext& requestContext, size_t* requestCo
   data->path = requestContext.path;
   data->timestamp = requestContext.timestamp;
   data->localContentCallback = localContentCallback;
+  data->userAgent = mUniqueAgentID;
 
   curl_easy_setopt(curl_handle, CURLOPT_URL, fullUrl.c_str());
   initCurlOptionsForRetrieve(curl_handle, (void*)(&data->hoPair), writeCallback, false);
@@ -1671,8 +1672,6 @@ void CcdbApi::vectoredLoadFileToMemory(std::vector<RequestContext>& requestConte
     // navigateSourcesAndLoadFile either retrieves file from snapshot immediately, or schedules it to be downloaded when mDownloader->runLoop is ran at a later time
     auto& requestContext = requestContexts.at(i);
     navigateSourcesAndLoadFile(requestContext, fromSnapshots.at(i), &requestCounter);
-    logReading(requestContext.path, requestContext.timestamp, &requestContext.headers,
-               fmt::format("{}{}", requestContext.considerSnapshot ? "load to memory" : "retrieve", fromSnapshots.at(i) ? " from snapshot" : ""));
   }
 
   // Download the rest
@@ -1683,12 +1682,12 @@ void CcdbApi::vectoredLoadFileToMemory(std::vector<RequestContext>& requestConte
   // Save snapshots
   for (int i = 0; i < requestContexts.size(); i++) {
     auto& requestContext = requestContexts.at(i);
+    logReading(requestContext.path, requestContext.timestamp, &requestContext.headers,
+               fmt::format("{}{}", requestContext.considerSnapshot ? "load to memory" : "retrieve", fromSnapshots.at(i) ? " from snapshot" : ""));
     if (!requestContext.dest.empty()) {
       if (requestContext.considerSnapshot && fromSnapshots.at(i) != 2) {
         saveSnapshot(requestContext);
       }
-    } else {
-      LOG(warning) << "Did not receive content for " << requestContext.path << "\n"; // Temporarily demoted to warning, since it floods the infologger
     }
   }
 }