commit 81b4a2e11774a59ea994663024af51ad7574f67e
author Jonathan Amsterdam <jba@google.com> Tue Dec 21 16:39:56 2021 -0500
committer Jonathan Amsterdam <jba@google.com> Wed Dec 22 14:06:59 2021 +0000
tree 756e057609c344b72bc8acfc4be479c1f72b8264
parent a16c2408ae12df6190509a33beecc866e608ac7e

internal/worker: combine structured and printf logging

Previously, the worker used structured logging almost completely:
anything that would have been a format string parameter was made a
label instead.

This led to a poor experience with the GCP logging UI.  You could see
the message of each log entry at a glance, but it took two clicks to
look at the labels. For example, when the worker created a GitHub
issue for a CVE, you'd see "created issue", but you wouldn't know the
CVE or number of the issue unless you opened the log entry.

This CL rethinks the log "frontend" -- the API that programmers
actually use to write log messages -- to allow a mix of labels
and printf-style formatting. The previous approach made it easy
to do one or the other, but not to mix both in a single log entry.
You could either write

   log.Info(message, labels...)

or

    log.Infof(format, args...)

but not both, since you can't have two "..." parameters in a function.
In this CL's design, one can write

    log.With(namesAndValues...).Infof(format, args...)

To further improve the ergonomics, the With function takes key-value
pairs rather than labels. Thus

    event.Int64("limit", int64(limit))

becomes

    log.With("limit", limit)

The performance is significantly worse, but for this server it
doesn't matter.

The CL also revisits each log message and makes a choice about whether
to display a value in the message, or to make a label out of it, or
both. As I said, putting the value in the message lets you see it at a
glance. The advantage of a label is you can easily query on it.

Most values only make sense as one or the other. For example, we'd
like to see the number of CVEs added during an update, but it doesn't
seem interesting to query the logs on that field. So that was put into
the message.

Change-Id: Iba2c70a14ea951c4d74335da6ac4e8265d652ded
Reviewed-on: https://go-review.googlesource.com/c/vulndb/+/373894
Trust: Jonathan Amsterdam <jba@google.com>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Julie Qiu <julie@golang.org>