From eab65e6301667e48972e61aa4034a25f13e04e2f Mon Sep 17 00:00:00 2001 From: Bob Callaway Date: Sat, 10 Dec 2022 12:10:46 +0000 Subject: [PATCH 1/3] logging tweaks to improve usability Signed-off-by: Bob Callaway --- pkg/api/entries.go | 8 +- pkg/api/error.go | 7 +- pkg/api/public_key.go | 2 - .../restapi/configure_rekor_server.go | 104 ++++++++++++++++-- pkg/log/log.go | 38 ++++++- 5 files changed, 144 insertions(+), 15 deletions(-) diff --git a/pkg/api/entries.go b/pkg/api/entries.go index 81a00af56..70c96f8d2 100644 --- a/pkg/api/entries.go +++ b/pkg/api/entries.go @@ -133,14 +133,14 @@ func logEntryFromLeaf(ctx context.Context, signer signature.Signer, tc TrillianC if attKey != "" { att, fetchErr = storageClient.FetchAttestation(ctx, attKey) if fetchErr != nil { - log.ContextLogger(ctx).Errorf("error fetching attestation by key, trying by UUID: %s %w", attKey, fetchErr) + log.ContextLogger(ctx).Debugf("error fetching attestation by key, trying by UUID: %s %v", attKey, fetchErr) } } // if looking up by key failed or we weren't able to generate a key, try looking up by uuid if attKey == "" || fetchErr != nil { att, fetchErr = storageClient.FetchAttestation(ctx, entryIDstruct.UUID) if fetchErr != nil { - log.ContextLogger(ctx).Errorf("error fetching attestation by uuid: %s %v", entryIDstruct.UUID, fetchErr) + log.ContextLogger(ctx).Debugf("error fetching attestation by uuid: %s %v", entryIDstruct.UUID, fetchErr) } } if fetchErr == nil { @@ -237,12 +237,12 @@ func createLogEntry(params entries.CreateLogEntryParams) (models.LogEntry, middl go func() { keys, err := entry.IndexKeys() if err != nil { - log.ContextLogger(ctx).Error(err) + log.ContextLogger(ctx).Errorf("getting entry index keys: %v", err) return } for _, key := range keys { if err := addToIndex(context.Background(), key, entryID); err != nil { - log.ContextLogger(ctx).Error(err) + log.ContextLogger(ctx).Errorf("adding keys to index: %v", err) } } }() diff --git a/pkg/api/error.go b/pkg/api/error.go index c84cdddba..63693927b 100644 --- a/pkg/api/error.go +++ b/pkg/api/error.go @@ -69,7 +69,12 @@ func handleRekorAPIError(params interface{}, code int, err error, message string logMsg := func(r *http.Request) { ctx := r.Context() - log.ContextLogger(ctx).Errorw("error processing request", append([]interface{}{"handler", handler, "statusCode", code, "clientMessage", message, "error", err}, fields...)...) + fields := append([]interface{}{"handler", handler, "statusCode", code, "clientMessage", message}, fields...) + if code >= 500 { + log.ContextLogger(ctx).Errorw(err.Error(), fields) + } else { + log.ContextLogger(ctx).Warnw(err.Error(), fields) + } paramsFields := map[string]interface{}{} if err := mapstructure.Decode(params, ¶msFields); err == nil { log.ContextLogger(ctx).Debug(paramsFields) diff --git a/pkg/api/public_key.go b/pkg/api/public_key.go index 78fcd7148..22e0c0436 100644 --- a/pkg/api/public_key.go +++ b/pkg/api/public_key.go @@ -23,7 +23,6 @@ import ( "github.com/go-openapi/swag" "github.com/sigstore/rekor/pkg/generated/models" "github.com/sigstore/rekor/pkg/generated/restapi/operations/pubkey" - "github.com/sigstore/rekor/pkg/log" ) func GetPublicKeyHandler(params pubkey.GetPublicKeyParams) middleware.Responder { @@ -34,7 +33,6 @@ func GetPublicKeyHandler(params pubkey.GetPublicKeyParams) middleware.Responder if err != nil { return handleRekorAPIError(params, http.StatusBadRequest, err, "") } - log.ContextLogger(ctx).Info("returning public key") return pubkey.NewGetPublicKeyOK().WithPayload(pk) } diff --git a/pkg/generated/restapi/configure_rekor_server.go b/pkg/generated/restapi/configure_rekor_server.go index 30342fe30..054ceb9c0 100644 --- a/pkg/generated/restapi/configure_rekor_server.go +++ b/pkg/generated/restapi/configure_rekor_server.go @@ -20,7 +20,9 @@ package restapi import ( "context" "crypto/tls" + "fmt" "net/http" + "net/http/httputil" "strconv" "time" @@ -33,6 +35,8 @@ import ( "github.com/mitchellh/mapstructure" "github.com/rs/cors" "github.com/spf13/viper" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" pkgapi "github.com/sigstore/rekor/pkg/api" "github.com/sigstore/rekor/pkg/generated/restapi/operations" @@ -174,21 +178,81 @@ func setupMiddlewares(handler http.Handler) http.Handler { return handler } +type httpRequestFields struct { + requestMethod string + requestUrl string + requestSize string + status int + responseSize string + userAgent string + remoteIP string + latency string + protocol string +} + +func (h httpRequestFields) MarshalLogObject(enc zapcore.ObjectEncoder) error { + enc.AddString("requestMethod", h.requestMethod) + enc.AddString("requestUrl", h.requestUrl) + enc.AddString("requestSize", h.requestSize) + enc.AddInt("status", h.status) + enc.AddString("responseSize", h.responseSize) + enc.AddString("userAgent", h.userAgent) + enc.AddString("remoteIP", h.remoteIP) + enc.AddString("latency", h.latency) + enc.AddString("protocol", h.protocol) + return nil +} + // We need this type to act as an adapter between zap and the middleware request logger. -type logAdapter struct { +type zapLogEntry struct { + r *http.Request } -func (l *logAdapter) Print(v ...interface{}) { - log.Logger.Info(v...) +func (z *zapLogEntry) Write(status, bytes int, header http.Header, elapsed time.Duration, extra interface{}) { + var fields []interface{} + + // follows https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry as a convention + // append HTTP Request / Response Information + scheme := "http" + if z.r.TLS != nil { + scheme = "https" + } + httpRequestObj := httpRequestFields{ + requestMethod: z.r.Method, + requestUrl: fmt.Sprintf("%s://%s%s", scheme, z.r.Host, z.r.RequestURI), + requestSize: fmt.Sprintf("%d", z.r.ContentLength), + status: status, + responseSize: fmt.Sprintf("%d", bytes), + userAgent: z.r.Header.Get("User-Agent"), + remoteIP: z.r.RemoteAddr, + latency: fmt.Sprintf("%.9fs", elapsed.Seconds()), + protocol: z.r.Proto, + } + fields = append(fields, zap.Object("httpRequest", httpRequestObj)) + if extra != nil { + fields = append(fields, zap.Any("extra", extra)) + } + + log.ContextLogger(z.r.Context()).With(fields...).Info("completed request") +} + +func (z *zapLogEntry) Panic(v interface{}, stack []byte) { + fields := []interface{}{zap.String("message", fmt.Sprintf("%v\n%v", v, string(stack)))} + log.ContextLogger(z.r.Context()).With(fields...).Errorf("panic detected: %v", v) +} + +type logFormatter struct{} + +func (l *logFormatter) NewLogEntry(r *http.Request) middleware.LogEntry { + return &zapLogEntry{r} } // The middleware configuration happens before anything, this middleware also applies to serving the swagger.json document. // So this is a good place to plug in a panic handling middleware, logging and metrics func setupGlobalMiddleware(handler http.Handler) http.Handler { - middleware.DefaultLogger = middleware.RequestLogger( - &middleware.DefaultLogFormatter{Logger: &logAdapter{}}) - returnHandler := middleware.Logger(handler) - returnHandler = middleware.Recoverer(returnHandler) + returnHandler := recoverer(handler) + middleware.DefaultLogger = middleware.RequestLogger(&logFormatter{}) + returnHandler = middleware.Logger(returnHandler) returnHandler = middleware.Heartbeat("/ping")(returnHandler) returnHandler = serveStaticContent(returnHandler) @@ -296,3 +360,29 @@ func serveStaticContent(handler http.Handler) http.Handler { handler.ServeHTTP(w, r) }) } + +// recoverer +func recoverer(next http.Handler) http.Handler { + fn := func(w http.ResponseWriter, r *http.Request) { + defer func() { + if rvr := recover(); rvr != nil && rvr != http.ErrAbortHandler { + var fields []interface{} + + // get context before dump request in case there is an error + ctx := r.Context() + request, err := httputil.DumpRequest(r, false) + if err == nil { + fields = append(fields, zap.ByteString("request_headers", request)) + } + + log.ContextLogger(ctx).With(fields...).Errorf("panic detected: %v", rvr) + + errors.ServeError(w, r, nil) + } + }() + + next.ServeHTTP(w, r) + } + + return http.HandlerFunc(fn) +} diff --git a/pkg/log/log.go b/pkg/log/log.go index 7473347a9..413b604f7 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -37,6 +37,11 @@ func ConfigureLogger(logType string) { cfg = zap.NewProductionConfig() cfg.EncoderConfig.LevelKey = "severity" cfg.EncoderConfig.MessageKey = "message" + cfg.EncoderConfig.TimeKey = "time" + cfg.EncoderConfig.EncodeLevel = encodeLevel() + cfg.EncoderConfig.EncodeTime = zapcore.RFC3339TimeEncoder + cfg.EncoderConfig.EncodeDuration = zapcore.SecondsDurationEncoder + cfg.EncoderConfig.EncodeCaller = zapcore.FullCallerEncoder } else { cfg = zap.NewDevelopmentConfig() cfg.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder @@ -48,6 +53,27 @@ func ConfigureLogger(logType string) { Logger = logger.Sugar() } +func encodeLevel() zapcore.LevelEncoder { + return func(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { + switch l { + case zapcore.DebugLevel: + enc.AppendString("DEBUG") + case zapcore.InfoLevel: + enc.AppendString("INFO") + case zapcore.WarnLevel: + enc.AppendString("WARNING") + case zapcore.ErrorLevel: + enc.AppendString("ERROR") + case zapcore.DPanicLevel: + enc.AppendString("CRITICAL") + case zapcore.PanicLevel: + enc.AppendString("ALERT") + case zapcore.FatalLevel: + enc.AppendString("EMERGENCY") + } + } +} + var CliLogger = createCliLogger() func createCliLogger() *zap.SugaredLogger { @@ -68,11 +94,21 @@ func WithRequestID(ctx context.Context, id string) context.Context { return context.WithValue(ctx, middleware.RequestIDKey, id) } +type operation struct { + id string +} + +func (o operation) MarshalLogObject(enc zapcore.ObjectEncoder) error { + enc.AddString("id", o.id) + return nil +} + func ContextLogger(ctx context.Context) *zap.SugaredLogger { proposedLogger := Logger if ctx != nil { if ctxRequestID, ok := ctx.Value(middleware.RequestIDKey).(string); ok { - proposedLogger = proposedLogger.With(zap.String("requestID", ctxRequestID)) + requestID := operation{ctxRequestID} + proposedLogger = proposedLogger.With(zap.Object("operation", requestID)) } } return proposedLogger From fde7dd193cd2ad73a56c7aebc9969448fff25cdf Mon Sep 17 00:00:00 2001 From: Bob Callaway Date: Sat, 10 Dec 2022 16:03:08 +0000 Subject: [PATCH 2/3] variable name for linter Signed-off-by: Bob Callaway --- pkg/generated/restapi/configure_rekor_server.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/pkg/generated/restapi/configure_rekor_server.go b/pkg/generated/restapi/configure_rekor_server.go index 054ceb9c0..f7e0b84f4 100644 --- a/pkg/generated/restapi/configure_rekor_server.go +++ b/pkg/generated/restapi/configure_rekor_server.go @@ -180,7 +180,7 @@ func setupMiddlewares(handler http.Handler) http.Handler { type httpRequestFields struct { requestMethod string - requestUrl string + requestURL string requestSize string status int responseSize string @@ -192,7 +192,7 @@ type httpRequestFields struct { func (h httpRequestFields) MarshalLogObject(enc zapcore.ObjectEncoder) error { enc.AddString("requestMethod", h.requestMethod) - enc.AddString("requestUrl", h.requestUrl) + enc.AddString("requestUrl", h.requestURL) enc.AddString("requestSize", h.requestSize) enc.AddInt("status", h.status) enc.AddString("responseSize", h.responseSize) @@ -219,7 +219,7 @@ func (z *zapLogEntry) Write(status, bytes int, header http.Header, elapsed time. } httpRequestObj := httpRequestFields{ requestMethod: z.r.Method, - requestUrl: fmt.Sprintf("%s://%s%s", scheme, z.r.Host, z.r.RequestURI), + requestURL: fmt.Sprintf("%s://%s%s", scheme, z.r.Host, z.r.RequestURI), requestSize: fmt.Sprintf("%d", z.r.ContentLength), status: status, responseSize: fmt.Sprintf("%d", bytes), From d1306a3cd5602c24c374899fd0b33a3e3dfd4c55 Mon Sep 17 00:00:00 2001 From: Bob Callaway Date: Sun, 11 Dec 2022 19:16:13 -0500 Subject: [PATCH 3/3] update types to put string formatting at lower level Signed-off-by: Bob Callaway --- .../restapi/configure_rekor_server.go | 22 +++++++++---------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/pkg/generated/restapi/configure_rekor_server.go b/pkg/generated/restapi/configure_rekor_server.go index f7e0b84f4..90cf05100 100644 --- a/pkg/generated/restapi/configure_rekor_server.go +++ b/pkg/generated/restapi/configure_rekor_server.go @@ -181,24 +181,24 @@ func setupMiddlewares(handler http.Handler) http.Handler { type httpRequestFields struct { requestMethod string requestURL string - requestSize string + requestSize int64 status int - responseSize string + responseSize int userAgent string remoteIP string - latency string + latency time.Duration protocol string } -func (h httpRequestFields) MarshalLogObject(enc zapcore.ObjectEncoder) error { +func (h *httpRequestFields) MarshalLogObject(enc zapcore.ObjectEncoder) error { enc.AddString("requestMethod", h.requestMethod) enc.AddString("requestUrl", h.requestURL) - enc.AddString("requestSize", h.requestSize) + enc.AddString("requestSize", fmt.Sprintf("%d", h.requestSize)) enc.AddInt("status", h.status) - enc.AddString("responseSize", h.responseSize) + enc.AddString("responseSize", fmt.Sprintf("%d", h.responseSize)) enc.AddString("userAgent", h.userAgent) enc.AddString("remoteIP", h.remoteIP) - enc.AddString("latency", h.latency) + enc.AddString("latency", fmt.Sprintf("%.9fs", h.latency.Seconds())) // formatted per GCP expectations enc.AddString("protocol", h.protocol) return nil } @@ -217,15 +217,15 @@ func (z *zapLogEntry) Write(status, bytes int, header http.Header, elapsed time. if z.r.TLS != nil { scheme = "https" } - httpRequestObj := httpRequestFields{ + httpRequestObj := &httpRequestFields{ requestMethod: z.r.Method, requestURL: fmt.Sprintf("%s://%s%s", scheme, z.r.Host, z.r.RequestURI), - requestSize: fmt.Sprintf("%d", z.r.ContentLength), + requestSize: z.r.ContentLength, status: status, - responseSize: fmt.Sprintf("%d", bytes), + responseSize: bytes, userAgent: z.r.Header.Get("User-Agent"), remoteIP: z.r.RemoteAddr, - latency: fmt.Sprintf("%.9fs", elapsed.Seconds()), + latency: elapsed, protocol: z.r.Proto, } fields = append(fields, zap.Object("httpRequest", httpRequestObj))