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>

cmd/worker/main.go

@@ -21,7 +21,6 @@ import (
 	"text/tabwriter"
 	"time"
 
-	"golang.org/x/exp/event"
 	"golang.org/x/vulndb/internal/gitrepo"
 	"golang.org/x/vulndb/internal/worker"
 	"golang.org/x/vulndb/internal/worker/log"
@@ -85,10 +84,7 @@ func main() {
 	}
 
 	ctx := log.WithLineLogger(context.Background())
-	log.Info(ctx, "config",
-		event.String("Project", cfg.Project),
-		event.String("Namespace", cfg.Namespace),
-		event.String("IssueRepo", cfg.IssueRepo))
+	log.Infof(ctx, "config: project=%s, namespace=%s, issueRepo=%s", cfg.Project, cfg.Namespace, cfg.IssueRepo)
 
 	var err error
 	cfg.Store, err = store.NewFireStore(ctx, cfg.Project, cfg.Namespace)

internal/worker/log/log.go

@@ -10,8 +10,10 @@ import (
 	"fmt"
 	"io"
 	"os"
+	"reflect"
 	"strings"
 	"sync"
+	"time"
 
 	"golang.org/x/exp/event"
 	"golang.org/x/exp/event/severity"
@@ -59,42 +61,75 @@ func (h *lineHandler) Event(ctx context.Context, ev *event.Event) context.Contex
 	return ctx
 }
 
-// Debug emits one log event at the Debug severity.
-func Debug(ctx context.Context, message string, labels ...event.Label) {
-	event.Log(ctx, message, append(labels, severity.Debug.Label())...)
+type Labels []event.Label
+
+func With(kvs ...interface{}) Labels {
+	return Labels(nil).With(kvs...)
 }
 
-// Info emits one log event at the Info severity.
-func Info(ctx context.Context, message string, labels ...event.Label) {
-	event.Log(ctx, message, append(labels, severity.Info.Label())...)
+func (ls Labels) With(kvs ...interface{}) Labels {
+	if len(kvs)%2 != 0 {
+		panic("args must be key-value pairs")
+	}
+	for i := 0; i < len(kvs); i += 2 {
+		ls = append(ls, pairToLabel(kvs[i].(string), kvs[i+1]))
+	}
+	return ls
 }
 
-// Warning emits one log event at the Warning severity.
-func Warning(ctx context.Context, message string, labels ...event.Label) {
-	event.Log(ctx, message, append(labels, severity.Warning.Label())...)
+func pairToLabel(name string, value interface{}) event.Label {
+	if d, ok := value.(time.Duration); ok {
+		return event.Duration(name, d)
+	}
+	v := reflect.ValueOf(value)
+	switch v.Kind() {
+	case reflect.String:
+		return event.String(name, v.String())
+	case reflect.Bool:
+		return event.Bool(name, v.Bool())
+	case reflect.Int, reflect.Int8, reflect.Int16, reflect.Int32, reflect.Int64:
+		return event.Int64(name, v.Int())
+	case reflect.Uint, reflect.Uint8, reflect.Uint16, reflect.Uint32, reflect.Uint64, reflect.Uintptr:
+		return event.Uint64(name, v.Uint())
+	case reflect.Float32, reflect.Float64:
+		return event.Float64(name, v.Float())
+	default:
+		return event.Value(name, value)
+	}
 }
 
-// Error emits one log event at the Error severity.
-func Error(ctx context.Context, message string, labels ...event.Label) {
-	event.Log(ctx, message, append(labels, severity.Error.Label())...)
+func (l Labels) logf(ctx context.Context, s severity.Level, format string, args ...interface{}) {
+	event.Log(ctx, fmt.Sprintf(format, args...), append(l, s.Label())...)
+}
+
+func (l Labels) Debugf(ctx context.Context, format string, args ...interface{}) {
+	l.logf(ctx, severity.Debug, format, args...)
+}
+
+func (l Labels) Infof(ctx context.Context, format string, args ...interface{}) {
+	l.logf(ctx, severity.Info, format, args...)
+}
+
+func (l Labels) Warningf(ctx context.Context, format string, args ...interface{}) {
+	l.logf(ctx, severity.Warning, format, args...)
+}
+
+func (l Labels) Errorf(ctx context.Context, format string, args ...interface{}) {
+	l.logf(ctx, severity.Error, format, args...)
 }
 
-// Debugf logs a formatted message with no labels at the Debug severity.
 func Debugf(ctx context.Context, format string, args ...interface{}) {
-	Debug(ctx, fmt.Sprintf(format, args...))
+	Labels(nil).logf(ctx, severity.Debug, format, args...)
 }
 
-// Infof logs a formatted message with no labels at the Info severity.
 func Infof(ctx context.Context, format string, args ...interface{}) {
-	Info(ctx, fmt.Sprintf(format, args...))
+	Labels(nil).logf(ctx, severity.Info, format, args...)
 }
 
-// Warningf logs a formatted message with no labels at the Warning severity.
 func Warningf(ctx context.Context, format string, args ...interface{}) {
-	Warning(ctx, fmt.Sprintf(format, args...))
+	Labels(nil).logf(ctx, severity.Warning, format, args...)
 }
 
-// Errorf logs a formatted message with no labels at the Error severity.
 func Errorf(ctx context.Context, format string, args ...interface{}) {
-	Error(ctx, fmt.Sprintf(format, args...))
+	Labels(nil).logf(ctx, severity.Error, format, args...)
 }

internal/worker/server.go

@@ -18,7 +18,6 @@ import (
 
 	"cloud.google.com/go/errorreporting"
 	"github.com/google/safehtml/template"
-	"golang.org/x/exp/event"
 	"golang.org/x/sync/errgroup"
 	"golang.org/x/vulndb/internal/derrors"
 	"golang.org/x/vulndb/internal/gitrepo"
@@ -60,9 +59,9 @@ func NewServer(ctx context.Context, cfg Config) (_ *Server, err error) {
 			return nil, err
 		}
 		s.issueClient = NewGithubIssueClient(owner, repoName, cfg.GitHubAccessToken)
-		log.Info(ctx, "issue creation enabled", event.String("repo", cfg.IssueRepo))
+		log.Infof(ctx, "issue creation enabled for repo %s", cfg.IssueRepo)
 	} else {
-		log.Info(ctx, "issue creation disabled")
+		log.Infof(ctx, "issue creation disabled")
 	}
 
 	s.indexTemplate, err = parseTemplate(staticPath, template.TrustedSourceFromConstant("index.tmpl"))
@@ -92,17 +91,17 @@ func (s *Server) handle(_ context.Context, pattern string, handler func(w http.R
 		ctx := log.WithGCPJSONLogger(r.Context(), traceID)
 		r = r.WithContext(ctx)
 
-		log.Info(ctx, "request start",
-			event.Value("httpRequest", r))
+		log.With("httpRequest", r).Infof(ctx, "starting %s", r.URL.Path)
 
 		w2 := &responseWriter{ResponseWriter: w}
 		if err := handler(w2, r); err != nil {
 			s.serveError(ctx, w2, r, err)
 		}
 
-		log.Info(ctx, "request end",
-			event.Duration("latency", time.Since(start)),
-			event.Int64("status", translateStatus(w2.status)))
+		log.With(
+			"latency", time.Since(start),
+			"status", translateStatus(w2.status)).
+			Infof(ctx, "request end")
 	})
 }
 
@@ -121,7 +120,7 @@ func (s *Server) serveError(ctx context.Context, w http.ResponseWriter, _ *http.
 		serr = &serverError{status: http.StatusInternalServerError, err: err}
 	}
 	if serr.status == http.StatusInternalServerError {
-		log.Error(ctx, serr.err.Error())
+		log.Errorf(ctx, serr.err.Error())
 	} else {
 		log.Infof(ctx, "returning %d (%s) for error %v", serr.status, http.StatusText(serr.status), err)
 	}
@@ -182,7 +181,7 @@ func renderPage(ctx context.Context, w http.ResponseWriter, page interface{}, tm
 		return err
 	}
 	if _, err := io.Copy(w, &buf); err != nil {
-		log.Error(ctx, "copying buffer to ResponseWriter", event.Value("error", err))
+		log.Errorf(ctx, "copying buffer to ResponseWriter: %v", err)
 		return err
 	}
 	return nil
@@ -284,7 +283,7 @@ func (s *Server) handleIssues(w http.ResponseWriter, r *http.Request) error {
 			}
 		}
 	}
-	log.Info(r.Context(), "creating issues", event.Int64("limit", int64(limit)))
+	log.With("limit", limit).Infof(r.Context(), "creating issues")
 	return CreateIssues(r.Context(), s.cfg.Store, s.issueClient, limit)
 }
 

internal/worker/triage.go

@@ -14,7 +14,6 @@ import (
 	"strings"
 	"time"
 
-	"golang.org/x/exp/event"
 	"golang.org/x/time/rate"
 	"golang.org/x/vulndb/internal/cveschema"
 	"golang.org/x/vulndb/internal/derrors"
@@ -182,10 +181,11 @@ func knownToPkgsite(ctx context.Context, baseURL, modulePath string) (bool, erro
 	if err == nil {
 		status = strconv.Quote(res.Status)
 	}
-	log.Info(ctx, "HEAD "+url,
-		event.Value("latency", time.Since(start)),
-		event.String("status", status),
-		event.Value("error", err))
+	log.With(
+		"latency", time.Since(start),
+		"status", status,
+		"error", err,
+	).Infof(ctx, "HEAD "+url)
 	if err != nil {
 		return false, err
 	}

internal/worker/update.go

@@ -19,7 +19,6 @@ import (
 	"github.com/go-git/go-git/v5/plumbing"
 	"github.com/go-git/go-git/v5/plumbing/filemode"
 	"github.com/go-git/go-git/v5/plumbing/object"
-	"golang.org/x/exp/event"
 	"golang.org/x/vulndb/internal/cveschema"
 	"golang.org/x/vulndb/internal/derrors"
 	"golang.org/x/vulndb/internal/worker/log"
@@ -74,23 +73,19 @@ func (u *updater) update(ctx context.Context) (ur *store.CommitUpdateRecord, err
 
 	defer func() {
 		if err != nil {
-			log.Error(ctx, "update failed", event.Value("error", err))
+			log.Errorf(ctx, "update failed: %v", err)
 		} else {
-			var nProcessed, nAdded, nModified int64
+			var nAdded, nModified int64
 			if ur != nil {
-				nProcessed = int64(ur.NumProcessed)
 				nAdded = int64(ur.NumAdded)
 				nModified = int64(ur.NumModified)
 			}
-			log.Info(ctx, "update succeeded",
-				event.String("commit", u.commitHash.String()),
-				event.Int64("processed", nProcessed),
-				event.Int64("added", nAdded),
-				event.Int64("modified", nModified))
+			log.Infof(ctx, "update succeeded on %s: added %d, modified %d",
+				u.commitHash, nAdded, nModified)
 		}
 	}()
 
-	log.Info(ctx, "update starting", event.String("commit", u.commitHash.String()))
+	log.Infof(ctx, "update starting on %s", u.commitHash)
 
 	commit, err := u.repo.CommitObject(u.commitHash)
 	if err != nil {
@@ -238,11 +233,7 @@ func (u *updater) updateBatch(ctx context.Context, batch []repoFile) (numAdds, n
 	if err != nil {
 		return 0, 0, err
 	}
-	log.Debug(ctx, "update transaction",
-		event.String("startID", startID),
-		event.String("endID", endID),
-		event.Int64("adds", int64(numAdds)),
-		event.Int64("mods", int64(numMods)))
+	log.Debugf(ctx, "update transaction %s=%s: added %d, modified %d", startID, endID, numAdds, numMods)
 	return numAdds, numMods, nil
 }
 

internal/worker/worker.go

@@ -18,7 +18,6 @@ import (
 
 	"github.com/go-git/go-git/v5"
 	"github.com/go-git/go-git/v5/plumbing"
-	"golang.org/x/exp/event"
 	"golang.org/x/sync/errgroup"
 	"golang.org/x/time/rate"
 	vulnc "golang.org/x/vuln/client"
@@ -39,7 +38,7 @@ func UpdateCommit(ctx context.Context, repoPath, commitHash string, st store.Sto
 		return err
 	}
 	if !b {
-		log.Info(ctx, "inserting false positives")
+		log.Infof(ctx, "inserting false positives")
 		if err := InsertFalsePositives(ctx, st); err != nil {
 			return err
 		}
@@ -188,19 +187,19 @@ func CreateIssues(ctx context.Context, st store.Store, ic IssueClient, limit int
 	if err != nil {
 		return err
 	}
-	log.Info(ctx, "CreateIssues starting",
-		event.String("destination", ic.Destination()),
-		event.Int64("needsIssue", int64(len(needsIssue))))
+	log.Infof(ctx, "CreateIssues starting; destination: %s, total needing issue: %d",
+		ic.Destination(), len(needsIssue))
 	numCreated := int64(0)
 	for _, r := range needsIssue {
 		if limit > 0 && int(numCreated) >= limit {
 			break
 		}
 		if r.IssueReference != "" || !r.IssueCreatedAt.IsZero() {
-			log.Error(ctx, "triage state is NeedsIssue but issue field(s) non-zero; skipping",
-				event.String("ID", r.ID),
-				event.String("IssueReference", r.IssueReference),
-				event.Value("IssueCreatedAt", r.IssueCreatedAt))
+			log.With(
+				"CVE", r.ID,
+				"IssueReference", r.IssueReference,
+				"IssueCreatedAt", r.IssueCreatedAt,
+			).Errorf(ctx, "%s: triage state is NeedsIssue but issue field(s) non-zero; skipping", r.ID)
 			continue
 		}
 		body, err := newBody(r)
@@ -226,7 +225,7 @@ func CreateIssues(ctx context.Context, st store.Store, ic IssueClient, limit int
 		// worse (we won't miss a CVE).
 		// TODO(golang/go#49733): look for the issue title to avoid duplications.
 		ref := ic.Reference(num)
-		log.Info(ctx, "created issue", event.String("CVE", r.ID), event.String("reference", ref))
+		log.With("CVE", r.ID).Infof(ctx, "created issue %s for %s", ref, r.ID)
 
 		// Update the CVERecord in the DB with issue information.
 		err = st.RunTransaction(ctx, func(ctx context.Context, tx store.Transaction) error {
@@ -245,7 +244,7 @@ func CreateIssues(ctx context.Context, st store.Store, ic IssueClient, limit int
 		}
 		numCreated++
 	}
-	log.Info(ctx, "CreateIssues done", event.Int64("limit", int64(limit)), event.Int64("numCreated", numCreated))
+	log.With("limit", limit).Infof(ctx, "CreateIssues done: %d created", numCreated)
 	return nil
 }