PR25267: debuginfod status logging improvements

Mark Wielaard mark@klomp.org
Thu Mar 26 13:59:30 GMT 2020


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 <fche@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  <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.

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  <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 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


More information about the Elfutils-devel mailing list