ensure log messages have requestID where possible (sigstore#907)

bobcallaway · web-flow · commit 4d45710833b1 · 2022-07-06T09:05:24.000-04:00
Signed-off-by: Bob Callaway &lt;bcallaway@google.com&gt;
diff --git a/pkg/api/entries.go b/pkg/api/entries.go
@@ -113,7 +113,7 @@ func logEntryFromLeaf(ctx context.Context, signer signature.Signer, tc TrillianC
 		if attKey != "" {
 			att, fetchErr = storageClient.FetchAttestation(ctx, attKey)
 			if fetchErr != nil {
-				log.Logger.Errorf("error fetching attestation by key, trying by UUID: %s %w", attKey, fetchErr)
+				log.ContextLogger(ctx).Errorf("error fetching attestation by key, trying by UUID: %s %w", attKey, fetchErr)
 			}
 		}
 		// if looking up by key failed or we weren't able to generate a key, try looking up by uuid
@@ -125,7 +125,7 @@ func logEntryFromLeaf(ctx context.Context, signer signature.Signer, tc TrillianC
 			}
 			att, fetchErr = storageClient.FetchAttestation(ctx, entryIDstruct.UUID)
 			if fetchErr != nil {
-				log.Logger.Errorf("error fetching attestation by uuid: %s %v", entryIDstruct.UUID, fetchErr)
+				log.ContextLogger(ctx).Errorf("error fetching attestation by uuid: %s %v", entryIDstruct.UUID, fetchErr)
 			}
 		}
 		if fetchErr == nil {
@@ -149,7 +149,7 @@ func GetLogEntryByIndexHandler(params entries.GetLogEntryByIndexParams) middlewa
 	ctx := params.HTTPRequest.Context()
 	tid, resolvedIndex := api.logRanges.ResolveVirtualIndex(int(params.LogIndex))
 	tc := NewTrillianClientFromTreeID(ctx, tid)
-	log.RequestIDLogger(params.HTTPRequest).Debugf("Retrieving resolved index %v from TreeID %v", resolvedIndex, tid)
+	log.ContextLogger(ctx).Debugf("Retrieving resolved index %v from TreeID %v", resolvedIndex, tid)
 
 	resp := tc.getLeafAndProofByIndex(resolvedIndex)
 	switch resp.status {
@@ -238,12 +238,12 @@ func createLogEntry(params entries.CreateLogEntryParams) (models.LogEntry, middl
 		go func() {
 			keys, err := entry.IndexKeys()
 			if err != nil {
-				log.RequestIDLogger(params.HTTPRequest).Error(err)
+				log.ContextLogger(ctx).Error(err)
 				return
 			}
 			for _, key := range keys {
 				if err := addToIndex(context.Background(), key, entryID); err != nil {
-					log.RequestIDLogger(params.HTTPRequest).Error(err)
+					log.ContextLogger(ctx).Error(err)
 				}
 			}
 		}()
@@ -254,14 +254,14 @@ func createLogEntry(params entries.CreateLogEntryParams) (models.LogEntry, middl
 		go func() {
 			attKey, attVal := entry.AttestationKeyValue()
 			if attVal == nil {
-				log.RequestIDLogger(params.HTTPRequest).Infof("no attestation for %s", uuid)
+				log.ContextLogger(ctx).Infof("no attestation for %s", uuid)
 				return
 			}
 			if err := storeAttestation(context.Background(), attKey, attVal); err != nil {
 				// entryIDstruct.UUID
-				log.RequestIDLogger(params.HTTPRequest).Errorf("error storing attestation: %s", err)
+				log.ContextLogger(ctx).Errorf("error storing attestation: %s", err)
 			} else {
-				log.RequestIDLogger(params.HTTPRequest).Infof("stored attestation for uuid %s with filename %s", entryIDstruct.UUID, attKey)
+				log.ContextLogger(ctx).Infof("stored attestation for uuid %s with filename %s", entryIDstruct.UUID, attKey)
 			}
 		}()
 	}
@@ -490,7 +490,7 @@ func retrieveUUIDFromTree(ctx context.Context, uuid string, tid int64) (models.L
 	}
 
 	tc := NewTrillianClientFromTreeID(ctx, tid)
-	log.Logger.Debugf("Attempting to retrieve UUID %v from TreeID %v", uuid, tid)
+	log.ContextLogger(ctx).Debugf("Attempting to retrieve UUID %v from TreeID %v", uuid, tid)
 
 	resp := tc.getLeafAndProofByHash(hashValue)
 	switch resp.status {
@@ -510,6 +510,7 @@ func retrieveUUIDFromTree(ctx context.Context, uuid string, tid int64) (models.L
 	case codes.NotFound:
 		return models.LogEntry{}, ErrNotFound
 	default:
+		log.ContextLogger(ctx).Errorf("Unexpected response code while attempting to retrieve UUID %v from TreeID %v: %v", uuid, tid, resp.status)
 		return models.LogEntry{}, errors.New("unexpected error")
 	}
 }
diff --git a/pkg/api/error.go b/pkg/api/error.go
@@ -67,10 +67,11 @@ func handleRekorAPIError(params interface{}, code int, err error, message string
 	handler := re.FindStringSubmatch(typeStr)[1]
 
 	logMsg := func(r *http.Request) {
-		log.RequestIDLogger(r).Errorw("exiting with error", append([]interface{}{"handler", handler, "statusCode", code, "clientMessage", message, "error", err}, fields...)...)
+		ctx := r.Context()
+		log.ContextLogger(ctx).Errorw("error processing request", append([]interface{}{"handler", handler, "statusCode", code, "clientMessage", message, "error", err}, fields...)...)
 		paramsFields := map[string]interface{}{}
 		if err := mapstructure.Decode(params, &paramsFields); err == nil {
-			log.RequestIDLogger(r).Debug(paramsFields)
+			log.ContextLogger(ctx).Debug(paramsFields)
 		}
 	}
 
diff --git a/pkg/generated/restapi/configure_rekor_server.go b/pkg/generated/restapi/configure_rekor_server.go
@@ -159,7 +159,7 @@ func setupGlobalMiddleware(handler http.Handler) http.Handler {
 		ctx := r.Context()
 		r = r.WithContext(log.WithRequestID(ctx, middleware.GetReqID(ctx)))
 		defer func() {
-			_ = log.RequestIDLogger(r).Sync()
+			_ = log.ContextLogger(ctx).Sync()
 		}()
 
 		returnHandler.ServeHTTP(w, r)
@@ -196,14 +196,15 @@ func cacheForever(handler http.Handler) http.Handler {
 }
 
 func logAndServeError(w http.ResponseWriter, r *http.Request, err error) {
+	ctx := r.Context()
 	if apiErr, ok := err.(errors.Error); ok && apiErr.Code() == http.StatusNotFound {
-		log.RequestIDLogger(r).Warn(err)
+		log.ContextLogger(ctx).Warn(err)
 	} else {
-		log.RequestIDLogger(r).Error(err)
+		log.ContextLogger(ctx).Error(err)
 	}
 	requestFields := map[string]interface{}{}
 	if err := mapstructure.Decode(r, &requestFields); err == nil {
-		log.RequestIDLogger(r).Debug(requestFields)
+		log.ContextLogger(ctx).Debug(requestFields)
 	}
 	errors.ServeError(w, r, err)
 }
diff --git a/pkg/log/log.go b/pkg/log/log.go
@@ -18,7 +18,6 @@ package log
 import (
 	"context"
 	"log"
-	"net/http"
 
 	"github.com/go-chi/chi/middleware"
 	"go.uber.org/zap"
@@ -69,10 +68,10 @@ func WithRequestID(ctx context.Context, id string) context.Context {
 	return context.WithValue(ctx, middleware.RequestIDKey, id)
 }
 
-func RequestIDLogger(r *http.Request) *zap.SugaredLogger {
+func ContextLogger(ctx context.Context) *zap.SugaredLogger {
 	proposedLogger := Logger
-	if r != nil {
-		if ctxRequestID, ok := r.Context().Value(middleware.RequestIDKey).(string); ok {
+	if ctx != nil {
+		if ctxRequestID, ok := ctx.Value(middleware.RequestIDKey).(string); ok {
 			proposedLogger = proposedLogger.With(zap.String("requestID", ctxRequestID))
 		}
 	}
diff --git a/pkg/storage/storage.go b/pkg/storage/storage.go
@@ -55,7 +55,7 @@ type Blob struct {
 }
 
 func (b *Blob) StoreAttestation(ctx context.Context, key string, attestation []byte) error {
-	log.Logger.Infof("storing attestation at %s", key)
+	log.ContextLogger(ctx).Infof("storing attestation at %s", key)
 	w, err := b.bucket.NewWriter(ctx, key, nil)
 	if err != nil {
 		return err
@@ -67,7 +67,7 @@ func (b *Blob) StoreAttestation(ctx context.Context, key string, attestation []b
 }
 
 func (b *Blob) FetchAttestation(ctx context.Context, key string) ([]byte, error) {
-	log.Logger.Infof("fetching attestation %s", key)
+	log.ContextLogger(ctx).Infof("fetching attestation %s", key)
 	exists, err := b.bucket.Exists(ctx, key)
 	if err != nil {
 		return nil, err

Original file line number	Diff line number	Diff line change
`@@ -113,7 +113,7 @@ func logEntryFromLeaf(ctx context.Context, signer signature.Signer, tc TrillianC`
`113`	`113`	`if attKey != "" {`
`114`	`114`	`att, fetchErr = storageClient.FetchAttestation(ctx, attKey)`
`115`	`115`	`if fetchErr != nil {`
`116`		`- log.Logger.Errorf("error fetching attestation by key, trying by UUID: %s %w", attKey, fetchErr)`
	`116`	`+ log.ContextLogger(ctx).Errorf("error fetching attestation by key, trying by UUID: %s %w", attKey, fetchErr)`
`117`	`117`	`}`
`118`	`118`	`}`
`119`	`119`	`// if looking up by key failed or we weren't able to generate a key, try looking up by uuid`
`@@ -125,7 +125,7 @@ func logEntryFromLeaf(ctx context.Context, signer signature.Signer, tc TrillianC`
`125`	`125`	`}`
`126`	`126`	`att, fetchErr = storageClient.FetchAttestation(ctx, entryIDstruct.UUID)`
`127`	`127`	`if fetchErr != nil {`
`128`		`- log.Logger.Errorf("error fetching attestation by uuid: %s %v", entryIDstruct.UUID, fetchErr)`
	`128`	`+ log.ContextLogger(ctx).Errorf("error fetching attestation by uuid: %s %v", entryIDstruct.UUID, fetchErr)`
`129`	`129`	`}`
`130`	`130`	`}`
`131`	`131`	`if fetchErr == nil {`
`@@ -149,7 +149,7 @@ func GetLogEntryByIndexHandler(params entries.GetLogEntryByIndexParams) middlewa`
`149`	`149`	`ctx := params.HTTPRequest.Context()`
`150`	`150`	`tid, resolvedIndex := api.logRanges.ResolveVirtualIndex(int(params.LogIndex))`
`151`	`151`	`tc := NewTrillianClientFromTreeID(ctx, tid)`
`152`		`- log.RequestIDLogger(params.HTTPRequest).Debugf("Retrieving resolved index %v from TreeID %v", resolvedIndex, tid)`
	`152`	`+ log.ContextLogger(ctx).Debugf("Retrieving resolved index %v from TreeID %v", resolvedIndex, tid)`
`153`	`153`
`154`	`154`	`resp := tc.getLeafAndProofByIndex(resolvedIndex)`
`155`	`155`	`switch resp.status {`
`@@ -238,12 +238,12 @@ func createLogEntry(params entries.CreateLogEntryParams) (models.LogEntry, middl`
`238`	`238`	`go func() {`
`239`	`239`	`keys, err := entry.IndexKeys()`
`240`	`240`	`if err != nil {`
`241`		`- log.RequestIDLogger(params.HTTPRequest).Error(err)`
	`241`	`+ log.ContextLogger(ctx).Error(err)`
`242`	`242`	`return`
`243`	`243`	`}`
`244`	`244`	`for _, key := range keys {`
`245`	`245`	`if err := addToIndex(context.Background(), key, entryID); err != nil {`
`246`		`- log.RequestIDLogger(params.HTTPRequest).Error(err)`
	`246`	`+ log.ContextLogger(ctx).Error(err)`
`247`	`247`	`}`
`248`	`248`	`}`
`249`	`249`	`}()`
`@@ -254,14 +254,14 @@ func createLogEntry(params entries.CreateLogEntryParams) (models.LogEntry, middl`
`254`	`254`	`go func() {`
`255`	`255`	`attKey, attVal := entry.AttestationKeyValue()`
`256`	`256`	`if attVal == nil {`
`257`		`- log.RequestIDLogger(params.HTTPRequest).Infof("no attestation for %s", uuid)`
	`257`	`+ log.ContextLogger(ctx).Infof("no attestation for %s", uuid)`
`258`	`258`	`return`
`259`	`259`	`}`
`260`	`260`	`if err := storeAttestation(context.Background(), attKey, attVal); err != nil {`
`261`	`261`	`// entryIDstruct.UUID`
`262`		`- log.RequestIDLogger(params.HTTPRequest).Errorf("error storing attestation: %s", err)`
	`262`	`+ log.ContextLogger(ctx).Errorf("error storing attestation: %s", err)`
`263`	`263`	`} else {`
`264`		`- log.RequestIDLogger(params.HTTPRequest).Infof("stored attestation for uuid %s with filename %s", entryIDstruct.UUID, attKey)`
	`264`	`+ log.ContextLogger(ctx).Infof("stored attestation for uuid %s with filename %s", entryIDstruct.UUID, attKey)`
`265`	`265`	`}`
`266`	`266`	`}()`
`267`	`267`	`}`
`@@ -490,7 +490,7 @@ func retrieveUUIDFromTree(ctx context.Context, uuid string, tid int64) (models.L`
`490`	`490`	`}`
`491`	`491`
`492`	`492`	`tc := NewTrillianClientFromTreeID(ctx, tid)`
`493`		`- log.Logger.Debugf("Attempting to retrieve UUID %v from TreeID %v", uuid, tid)`
	`493`	`+ log.ContextLogger(ctx).Debugf("Attempting to retrieve UUID %v from TreeID %v", uuid, tid)`
`494`	`494`
`495`	`495`	`resp := tc.getLeafAndProofByHash(hashValue)`
`496`	`496`	`switch resp.status {`
`@@ -510,6 +510,7 @@ func retrieveUUIDFromTree(ctx context.Context, uuid string, tid int64) (models.L`
`510`	`510`	`case codes.NotFound:`
`511`	`511`	`return models.LogEntry{}, ErrNotFound`
`512`	`512`	`default:`
	`513`	`+ log.ContextLogger(ctx).Errorf("Unexpected response code while attempting to retrieve UUID %v from TreeID %v: %v", uuid, tid, resp.status)`
`513`	`514`	`return models.LogEntry{}, errors.New("unexpected error")`
`514`	`515`	`}`
`515`	`516`	`}`
Original file line number	Diff line number	Diff line change
`@@ -67,10 +67,11 @@ func handleRekorAPIError(params interface{}, code int, err error, message string`
`67`	`67`	`handler := re.FindStringSubmatch(typeStr)[1]`
`68`	`68`
`69`	`69`	`logMsg := func(r *http.Request) {`
`70`		`- log.RequestIDLogger(r).Errorw("exiting with error", append([]interface{}{"handler", handler, "statusCode", code, "clientMessage", message, "error", err}, fields...)...)`
	`70`	`+ ctx := r.Context()`
	`71`	`+ log.ContextLogger(ctx).Errorw("error processing request", append([]interface{}{"handler", handler, "statusCode", code, "clientMessage", message, "error", err}, fields...)...)`
`71`	`72`	`paramsFields := map[string]interface{}{}`
`72`	`73`	`if err := mapstructure.Decode(params, &paramsFields); err == nil {`
`73`		`- log.RequestIDLogger(r).Debug(paramsFields)`
	`74`	`+ log.ContextLogger(ctx).Debug(paramsFields)`
`74`	`75`	`}`
`75`	`76`	`}`
`76`	`77`
Original file line number	Diff line number	Diff line change
`@@ -18,7 +18,6 @@ package log`
`18`	`18`	`import (`
`19`	`19`	`"context"`
`20`	`20`	`"log"`
`21`		`- "net/http"`
`22`	`21`
`23`	`22`	`"github.com/go-chi/chi/middleware"`
`24`	`23`	`"go.uber.org/zap"`
`@@ -69,10 +68,10 @@ func WithRequestID(ctx context.Context, id string) context.Context {`
`69`	`68`	`return context.WithValue(ctx, middleware.RequestIDKey, id)`
`70`	`69`	`}`
`71`	`70`
`72`		`-func RequestIDLogger(r http.Request) zap.SugaredLogger {`
	`71`	`+func ContextLogger(ctx context.Context) *zap.SugaredLogger {`
`73`	`72`	`proposedLogger := Logger`
`74`		`- if r != nil {`
`75`		`- if ctxRequestID, ok := r.Context().Value(middleware.RequestIDKey).(string); ok {`
	`73`	`+ if ctx != nil {`
	`74`	`+ if ctxRequestID, ok := ctx.Value(middleware.RequestIDKey).(string); ok {`
`76`	`75`	`proposedLogger = proposedLogger.With(zap.String("requestID", ctxRequestID))`
`77`	`76`	`}`
`78`	`77`	`}`