Hi Frank,
On Tue, 2020-03-24 at 22:12 -0400, Frank Ch. Eigler via Elfutils-devel wrote:
> 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.
This looks good and useful. Two small questions below.
> +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.
OK.
> 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");
> }
OK
> @@ -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;
> }
OK. os is a string and string.size() returns the number of bytes.
> @@ -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);
> + }
If fstat fails for whatever reason http_size isn't set (-1).
> }
> 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);
> }
In the catch case http_size might not be set (or is -1).
> +
> + 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;
> }
Should the case where http_size == -1 be handled specially?
Would it make sense to only log this if (verbose > 1) ?
>
> 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.
Looks good.
Thanks,
Mark
