Hi -
This makes debuginfod logs more useful to admins.
Author: Frank Ch. Eigler <f...@redhat.com>
Date: Tue Mar 24 21:57:59 2020 -0400
PR25367: improve debuginfod webapi logging
Improve debuginfod logging to show webapi query results including
http status, sizes, and processing times.
Signed-off-by: Frank Ch. Eigler <f...@redhat.com>
diff --git a/debuginfod/ChangeLog b/debuginfod/ChangeLog
index b34b4d2938dd..9eb06719ec0d 100644
--- a/debuginfod/ChangeLog
+++ b/debuginfod/ChangeLog
@@ -1,3 +1,12 @@
+2020-03-24 Frank Ch. Eigler <f...@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 <f...@redhat.com>
* debuginfod-client.c (debuginfod_query_server): Print the
diff --git a/debuginfod/debuginfod.cxx b/debuginfod/debuginfod.cxx
index 7c7e85eb6d14..490169a40ded 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 d0d32a87315a..7c1c307a532f 100644
--- a/tests/ChangeLog
+++ b/tests/ChangeLog
@@ -1,3 +1,8 @@
+2020-03-24 Frank Ch. Eigler <f...@redhat.com>
+
+ * run-debuginfod-find.sh: Test the more detailed debuginfod
+ webapi log format.
+
2020-03-23 Mark Wielaard <m...@klomp.org>
* getphdrnum.c: Include config.h.
diff --git a/tests/run-debuginfod-find.sh b/tests/run-debuginfod-find.sh
index b64130282d86..cbc289586536 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.
