From 10360958c042646e696b13eeddffcb5085ceadba Mon Sep 17 00:00:00 2001 From: Trong Huu Nguyen Date: Tue, 28 Jan 2025 13:27:39 +0100 Subject: [PATCH] feat(middleware): clean up logging middleware, add span attributes Co-authored-by: sindrerh2 --- Makefile | 2 +- internal/observability/logging.go | 1 + pkg/middleware/logentry.go | 142 ++++++++++++++++-------------- pkg/mock/request.go | 2 +- pkg/router/router.go | 4 +- 5 files changed, 80 insertions(+), 71 deletions(-) diff --git a/Makefile b/Makefile index 2170aff..25b7895 100644 --- a/Makefile +++ b/Makefile @@ -10,7 +10,7 @@ local: fmt --bind-address=127.0.0.1:3000 \ --upstream-host=localhost:4000 \ --redis.uri=redis://localhost:6379 \ - --log-level=debug \ + --log-level=info \ --log-format=text test: fmt diff --git a/internal/observability/logging.go b/internal/observability/logging.go index 1271f8e..eb2190c 100644 --- a/internal/observability/logging.go +++ b/internal/observability/logging.go @@ -47,6 +47,7 @@ func SetupLogger(level, format string) error { log.FatalLevel, log.ErrorLevel, log.WarnLevel, + log.InfoLevel, ))) return nil diff --git a/pkg/middleware/logentry.go b/pkg/middleware/logentry.go index 4a6eb90..1d8f4ac 100644 --- a/pkg/middleware/logentry.go +++ b/pkg/middleware/logentry.go @@ -10,28 +10,45 @@ import ( "github.com/go-chi/chi/v5/middleware" httpinternal "github.com/nais/wonderwall/internal/http" log "github.com/sirupsen/logrus" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" "github.com/nais/wonderwall/pkg/cookie" "github.com/nais/wonderwall/pkg/router/paths" ) -var logger *requestLogger - -type LogEntryMiddleware struct{} - -// LogEntry is copied verbatim from httplog package to replace with our own requestLogger implementation. -func LogEntry(provider string) LogEntryMiddleware { - logger = &requestLogger{Logger: log.StandardLogger(), Provider: provider} - return LogEntryMiddleware{} +type logger struct { + Logger *log.Logger + Provider string } -func (l *LogEntryMiddleware) Handler(next http.Handler) http.Handler { +// Logger provides a middleware that logs requests and responses. +func Logger(provider string) logger { + return logger{ + Logger: log.StandardLogger(), + Provider: provider, + } +} + +// LogEntryFrom returns a log entry from the request context. +func LogEntryFrom(r *http.Request) *log.Entry { + ctx := r.Context() + entry, ok := ctx.Value(middleware.LogEntryCtxKey).(*logEntryAdapter) + if ok { + return entry.Logger + } + + return log.NewEntry(log.StandardLogger()). + WithFields(requestFields(r)). + WithFields(traceFields(r)) +} + +func (l *logger) Handler(next http.Handler) http.Handler { fn := func(w http.ResponseWriter, r *http.Request) { - entry := logger.NewLogEntry(r) + entry := l.newLogEntry(r) ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor) if !strings.HasSuffix(r.URL.Path, paths.Ping) { - entry.Logger.Debugf("request start: %s - %s", r.Method, r.URL.Path) t1 := time.Now() defer func() { entry.Write(ww.Status(), ww.BytesWritten(), ww.Header(), time.Since(t1), nil) @@ -43,28 +60,46 @@ func (l *LogEntryMiddleware) Handler(next http.Handler) http.Handler { return http.HandlerFunc(fn) } -func LogEntryFrom(r *http.Request) *log.Entry { - ctx := r.Context() - val := ctx.Value(middleware.LogEntryCtxKey) - entry, ok := val.(*requestLoggerEntry) - if ok { - return entry.Logger +func (l *logger) newLogEntry(r *http.Request) *logEntryAdapter { + return &logEntryAdapter{ + requestFields: requestFields(r), + Logger: l.Logger.WithContext(r.Context()). + WithField("provider", l.Provider). + WithFields(traceFields(r)), + } +} + +// logEntryAdapter implements [middleware.LogEntry] +type logEntryAdapter struct { + Logger *log.Entry + requestFields log.Fields +} + +func (l *logEntryAdapter) Write(status, bytes int, _ http.Header, elapsed time.Duration, _ any) { + responseFields := log.Fields{ + "response_status": status, + "response_bytes": bytes, + "response_elapsed_ms": float64(elapsed.Nanoseconds()) / 1000000.0, // in milliseconds, with fractional } - entry = logger.NewLogEntry(r) - return entry.Logger + l.Logger.WithFields(l.requestFields). + WithFields(responseFields). + Debugf("response: %d %s", status, http.StatusText(status)) } -type requestLogger struct { - Logger *log.Logger - Provider string -} +func (l *logEntryAdapter) Panic(v interface{}, _ []byte) { + stacktrace := "#" -func (l *requestLogger) NewLogEntry(r *http.Request) *requestLoggerEntry { - entry := &requestLoggerEntry{} fields := log.Fields{ - "correlation_id": middleware.GetReqID(r.Context()), - "provider": l.Provider, + "stacktrace": stacktrace, + "error": fmt.Sprintf("%+v", v), + } + + l.Logger = l.Logger.WithFields(fields) +} + +func requestFields(r *http.Request) log.Fields { + fields := log.Fields{ "request_cookies": nonEmptyRequestCookies(r), "request_host": r.Host, "request_is_navigational": httpinternal.IsNavigationRequest(r), @@ -78,52 +113,25 @@ func (l *requestLogger) NewLogEntry(r *http.Request) *requestLoggerEntry { "request_user_agent": r.UserAgent(), } - entry.Logger = l.Logger. - WithContext(r.Context()). - WithFields(fields) - return entry -} - -type requestLoggerEntry struct { - Logger *log.Entry -} - -func (l *requestLoggerEntry) Write(status, bytes int, _ http.Header, elapsed time.Duration, _ any) { - msg := fmt.Sprintf("request end: HTTP %d (%s)", status, statusLabel(status)) - fields := log.Fields{ - "response_status": status, - "response_bytes": bytes, - "response_elapsed_ms": float64(elapsed.Nanoseconds()) / 1000000.0, // in milliseconds, with fractional + span := trace.SpanFromContext(r.Context()) + for k, v := range fields { + attrKey := "wonderwall." + k + span.SetAttributes(attribute.String(attrKey, fmt.Sprint(v))) } - entry := l.Logger.WithFields(fields) - entry.Debugf(msg) + return fields } -func (l *requestLoggerEntry) Panic(v interface{}, _ []byte) { - stacktrace := "#" - - fields := log.Fields{ - "stacktrace": stacktrace, - "error": fmt.Sprintf("%+v", v), +func traceFields(r *http.Request) log.Fields { + fields := log.Fields{} + span := trace.SpanFromContext(r.Context()) + if span.SpanContext().HasTraceID() { + fields["trace_id"] = span.SpanContext().TraceID().String() + } else { + fields["correlation_id"] = middleware.GetReqID(r.Context()) } - l.Logger = l.Logger.WithFields(fields) -} - -func statusLabel(status int) string { - switch { - case status >= 100 && status < 300: - return "OK" - case status >= 300 && status < 400: - return "Redirect" - case status >= 400 && status < 500: - return "Client Error" - case status >= 500: - return "Server Error" - default: - return "Unknown" - } + return fields } func nonEmptyRequestCookies(r *http.Request) string { diff --git a/pkg/mock/request.go b/pkg/mock/request.go index cee44b2..8ceb217 100644 --- a/pkg/mock/request.go +++ b/pkg/mock/request.go @@ -19,7 +19,7 @@ func NewGetRequest(target string, ingresses *ingress.Ingresses) *http.Request { req = mw.RequestWithIngress(req, ing) } - mw.LogEntry("test") + mw.Logger("test") return req } diff --git a/pkg/router/router.go b/pkg/router/router.go index 3c5158f..58b1b69 100644 --- a/pkg/router/router.go +++ b/pkg/router/router.go @@ -52,7 +52,7 @@ func New(src Source, cfg *config.Config) chi.Router { providerName := string(cfg.OpenID.Provider) ingressMw := middleware.Ingress(src) prometheus := middleware.Prometheus(providerName) - logentry := middleware.LogEntry(providerName) + logger := middleware.Logger(providerName) r := chi.NewRouter() if cfg.OpenTelemetry.Enabled { @@ -64,6 +64,7 @@ func New(src Source, cfg *config.Config) chi.Router { r.Use(middleware.CorrelationIDHandler) r.Use(chi_middleware.Recoverer) r.Use(ingressMw.Handler) + r.Use(logger.Handler) prefixes := src.GetIngresses().Paths() @@ -72,7 +73,6 @@ func New(src Source, cfg *config.Config) chi.Router { } r.Group(func(r chi.Router) { - r.Use(logentry.Handler) r.Use(prometheus.Handler) r.Use(chi_middleware.NoCache)