PR25367: improve debuginfod webapi loggingfche/pr25367

Improve debuginfod logging to show webapi query results including
http status, sizes, and processing times.

Signed-off-by: Frank Ch. Eigler <fche@redhat.com>

4 files changed, 72 insertions, 11 deletions

diff --git a/debuginfod/ChangeLog b/debuginfod/ChangeLog
index b34b4d29..9eb06719 100644
--- a/debuginfod/ChangeLog
+++ b/debuginfod/ChangeLog
@@ -1,5 +1,14 @@
 2020-03-24  Frank Ch. Eigler  <fche@redhat.com>
 
+	* debuginfod.cxx (handle_buildid): In case of federated fallback
+	queries, handle errors analogously to local ENOENT/404.
+	(handle_metrics): Return a size-of-response value.
+	(handler_cb): Add code to time entire application-side processing
+	stage + response sizes + http codes, so as to emit a complete
+	httpd-flavoured log line for each webapi request.
+
+2020-03-24  Frank Ch. Eigler  <fche@redhat.com>
+
 	* debuginfod-client.c (debuginfod_query_server): Print the
 	default_progressfn terminating \n message only if that progressfn
 	is actually set.
diff --git a/debuginfod/debuginfod.cxx b/debuginfod/debuginfod.cxx
index 7c7e85eb..490169a4 100644
--- a/debuginfod/debuginfod.cxx
+++ b/debuginfod/debuginfod.cxx
@@ -853,6 +853,7 @@ conninfo (struct MHD_Connection * conn)
 
 ////////////////////////////////////////////////////////////////////////
 
+
 static void
 add_mhd_last_modified (struct MHD_Response *resp, time_t mtime)
 {
@@ -1473,8 +1474,16 @@ static struct MHD_Response* handle_buildid (const string& buildid /* unsafe */,
         }
       close (fd);
     }
-  else if (fd != -ENOSYS) // no DEBUGINFOD_URLS configured
-    throw libc_exception(-fd, "upstream debuginfod query failed");
+  else
+    switch(fd)
+      {
+      case -ENOSYS:
+        break;
+      case -ENOENT:
+        break;
+      default: // some more tricky error
+        throw libc_exception(-fd, "upstream debuginfod query failed");
+      }
 
   throw reportable_exception(MHD_HTTP_NOT_FOUND, "not found");
 }
@@ -1564,7 +1573,7 @@ add_metric(const string& metric,
 
 
 static struct MHD_Response*
-handle_metrics ()
+handle_metrics (off_t* size)
 {
   stringstream o;
   {
@@ -1576,6 +1585,7 @@ handle_metrics ()
   MHD_Response* r = MHD_create_response_from_buffer (os.size(),
                                                      (void*) os.c_str(),
                                                      MHD_RESPMEM_MUST_COPY);
+  *size = os.size();
   MHD_add_response_header (r, "Content-Type", "text/plain");
   return r;
 }
@@ -1598,8 +1608,11 @@ handler_cb (void * /*cls*/,
   struct MHD_Response *r = NULL;
   string url_copy = url;
 
-  if (verbose)
-    obatched(clog) << conninfo(connection) << " " << method << " " << url << endl;
+  int rc = MHD_NO; // mhd
+  int http_code = 500;
+  off_t http_size = -1;
+  struct timeval tv_start, tv_end;
+  gettimeofday (&tv_start, NULL);
 
   try
     {
@@ -1632,12 +1645,22 @@ handler_cb (void * /*cls*/,
             }
 
           inc_metric("http_requests_total", "type", artifacttype);
-          r = handle_buildid(buildid, artifacttype, suffix, 0); // NB: don't care about result-fd
+
+          // get the resulting fd so we can report its size
+          int fd;
+          r = handle_buildid(buildid, artifacttype, suffix, &fd);
+          if (r)
+            {
+              struct stat fs;
+              if (fstat(fd, &fs) == 0)
+                http_size = fs.st_size;
+              // libmicrohttpd will close (fd);
+            }
         }
       else if (url1 == "/metrics")
         {
           inc_metric("http_requests_total", "type", "metrics");
-          r = handle_metrics();
+          r = handle_metrics(& http_size);
         }
       else
         throw reportable_exception("webapi error, unrecognized /operation");
@@ -1645,16 +1668,27 @@ handler_cb (void * /*cls*/,
       if (r == 0)
         throw reportable_exception("internal error, missing response");
 
-      int rc = MHD_queue_response (connection, MHD_HTTP_OK, r);
+      rc = MHD_queue_response (connection, MHD_HTTP_OK, r);
+      http_code = MHD_HTTP_OK;
       MHD_destroy_response (r);
-      return rc;
     }
   catch (const reportable_exception& e)
     {
       inc_metric("http_responses_total","result","error");
       e.report(clog);
-      return e.mhd_send_response (connection);
+      http_code = e.code;
+      rc = e.mhd_send_response (connection);
     }
+
+  gettimeofday (&tv_end, NULL);
+  double deltas = (tv_end.tv_sec - tv_start.tv_sec) + (tv_end.tv_usec - tv_start.tv_usec)*0.000001;
+  obatched(clog) << conninfo(connection)
+                 << ' ' << method << ' ' << url
+                 << ' ' << http_code << ' ' << http_size
+                 << ' ' << (int)(deltas*1000) << "ms"
+                 << endl;
+
+  return rc;
 }
 
 
diff --git a/tests/ChangeLog b/tests/ChangeLog
index d0d32a87..7c1c307a 100644
--- a/tests/ChangeLog
+++ b/tests/ChangeLog
@@ -1,3 +1,8 @@
+2020-03-24  Frank Ch. Eigler  <fche@redhat.com>
+
+	* run-debuginfod-find.sh: Test the more detailed debuginfod
+	webapi log format.
+
 2020-03-23  Mark Wielaard  <mark@klomp.org>
 
 	* getphdrnum.c: Include config.h.
diff --git a/tests/run-debuginfod-find.sh b/tests/run-debuginfod-find.sh
index b6413028..cbc28958 100755
--- a/tests/run-debuginfod-find.sh
+++ b/tests/run-debuginfod-find.sh
@@ -338,8 +338,9 @@ export DEBUGINFOD_CACHE_PATH=${PWD}/.client_cache2
 mkdir -p $DEBUGINFOD_CACHE_PATH
 # NB: inherits the DEBUGINFOD_URLS to the first server
 # NB: run in -L symlink-following mode for the L subdir
-env LD_LIBRARY_PATH=$ldpath ${abs_builddir}/../debuginfod/debuginfod $VERBOSE -F -U -d ${DB}_2 -p $PORT2 -L L D &
+env LD_LIBRARY_PATH=$ldpath ${abs_builddir}/../debuginfod/debuginfod $VERBOSE -F -U -d ${DB}_2 -p $PORT2 -L L D > vlog3 2>&1 &
 PID2=$!
+tempfiles vlog3
 tempfiles ${DB}_2
 wait_ready $PORT2 'ready' 1
 wait_ready $PORT2 'thread_work_total{role="traverse"}' 1
@@ -395,6 +396,11 @@ curl -s http://127.0.0.1:$PORT1/metrics | grep -q 'http_responses_total.*result.
 curl -s http://127.0.0.1:$PORT1/metrics | grep -q 'http_responses_total.*result.*fdcache'
 curl -s http://127.0.0.1:$PORT2/metrics | grep -q 'http_responses_total.*result.*upstream'
 
+# And generate a few errors into the second debuginfod's logs, for analysis just below
+curl -s http://127.0.0.1:$PORT2/badapi > /dev/null || true
+curl -s http://127.0.0.1:$PORT2/buildid/deadbeef/debuginfo > /dev/null || true
+
+
 ########################################################################
 
 # Run the tests again without the servers running. The target file should
@@ -408,6 +414,13 @@ tempfiles .debuginfod_*
 
 testrun ${abs_builddir}/debuginfod_build_id_find -e F/prog2 1
 
+# check out the debuginfod logs for the new style status lines
+# cat vlog3
+grep -q 'UA:.*XFF:.*GET /buildid/.* 200 ' vlog3
+grep -q 'UA:.*XFF:.*GET /metrics 200 ' vlog3
+grep -q 'UA:.*XFF:.*GET /badapi 503 ' vlog3
+grep -q 'UA:.*XFF:.*GET /buildid/deadbeef.* 404 ' vlog3
+
 ########################################################################
 
 # Add some files to the cache that do not fit its naming format.