internal/{log,middleware}: add trace ID to context, use in logging

- The requestlog middleware gets the trace ID from the request and
  adds it to the request's context.

- The internal/log package retrieves the traceID and adds it to log
  messages. It also creates two logs instead of one, a "parent" log
  used in requestlog, and a "child" log used for all other logging.
  Together, these two changes will cause the Stackdriver log viewer to
  group all log messages for a request with the request start and end
  log messages.

- These changes require that all log functions take a context, so I
  plumbed one through everywhere. In a handful of cases it didn't seem
  worth doing the plumbing. I used context.TODO() for those so we can
  easily find and re-evalaute them.

Change-Id: I663588463520187d0549a8f802ba9cb44a893592
Reviewed-on: https://team-review.git.corp.google.com/c/golang/discovery/+/622940
Reviewed-by: Robert Findley <rfindley@google.com>

1 files changed, 9 insertions, 9 deletions

diff --git a/internal/database/database.go b/internal/database/database.go
index f6a80a1c..d1780e1c 100644
--- a/internal/database/database.go
+++ b/internal/database/database.go
@@ -62,27 +62,27 @@ func (db *DB) Close() error {
 
 // Exec executes a SQL statement.
 func (db *DB) Exec(ctx context.Context, query string, args ...interface{}) (res sql.Result, err error) {
-	defer logQuery(query, args)(&err)
+	defer logQuery(ctx, query, args)(&err)
 
 	return db.db.ExecContext(ctx, query, args...)
 }
 
 // ExecTx runs a query in a transaction.
 func ExecTx(ctx context.Context, tx *sql.Tx, query string, args ...interface{}) (res sql.Result, err error) {
-	defer logQuery(query, args)(&err)
+	defer logQuery(ctx, query, args)(&err)
 
 	return tx.ExecContext(ctx, query, args...)
 }
 
 // Query runs the DB query.
 func (db *DB) Query(ctx context.Context, query string, args ...interface{}) (_ *sql.Rows, err error) {
-	defer logQuery(query, args)(&err)
+	defer logQuery(ctx, query, args)(&err)
 	return db.db.QueryContext(ctx, query, args...)
 }
 
 // QueryRow runs the query and returns a single row.
 func (db *DB) QueryRow(ctx context.Context, query string, args ...interface{}) *sql.Row {
-	defer logQuery(query, args)(nil)
+	defer logQuery(ctx, query, args)(nil)
 	return db.db.QueryRowContext(ctx, query, args...)
 }
 
@@ -224,7 +224,7 @@ type queryEndLogEntry struct {
 	Error           string `json:",omitempty"`
 }
 
-func logQuery(query string, args []interface{}) func(*error) {
+func logQuery(ctx context.Context, query string, args []interface{}) func(*error) {
 	if QueryLoggingDisabled {
 		return func(*error) {}
 	}
@@ -275,12 +275,12 @@ func logQuery(query string, args []interface{}) func(*error) {
 	}
 	argString := strings.Join(argStrings, ", ")
 
-	log.Debugf("%s %s args=%s", uid, query, argString)
+	log.Debugf(ctx, "%s %s args=%s", uid, query, argString)
 	start := time.Now()
 	return func(errp *error) {
 		dur := time.Since(start)
 		if errp == nil { // happens with queryRow
-			log.Debugf("%s done", uid)
+			log.Debugf(ctx, "%s done", uid)
 		} else {
 			derrors.Wrap(errp, "DB running query %s", uid)
 			entry := queryEndLogEntry{
@@ -290,10 +290,10 @@ func logQuery(query string, args []interface{}) func(*error) {
 				DurationSeconds: dur.Seconds(),
 			}
 			if *errp == nil {
-				log.Debug(entry)
+				log.Debug(ctx, entry)
 			} else {
 				entry.Error = (*errp).Error()
-				log.Error(entry)
+				log.Error(ctx, entry)
 			}
 		}
 	}