From 77d0438411633676a6fd48d34be5a81ac4dbb14b Mon Sep 17 00:00:00 2001 From: Trong Huu Nguyen Date: Tue, 5 Oct 2021 10:55:08 +0200 Subject: [PATCH] feat: use latest go-chi v5, add middlewares for panic recovery and logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-Authored-By: Sindre Rødseth Hansen --- cmd/wonderwall/main.go | 7 ++- go.mod | 4 +- go.sum | 11 +++- pkg/config/config.go | 5 +- pkg/errorhandler/errorhandler.go | 16 ++---- pkg/logging/httplog.go | 25 ++++++++ pkg/middleware/correlationid.go | 16 ++---- pkg/middleware/logentry.go | 97 ++++++++++++++++++++++++++++++++ pkg/middleware/prometheus.go | 2 +- pkg/mock/idporten.go | 2 +- pkg/router/handler.go | 12 +++- pkg/router/router.go | 8 ++- pkg/router/router_test.go | 5 +- 13 files changed, 171 insertions(+), 39 deletions(-) create mode 100644 pkg/logging/httplog.go create mode 100644 pkg/middleware/logentry.go diff --git a/cmd/wonderwall/main.go b/cmd/wonderwall/main.go index 4aaa0f2..74309e1 100644 --- a/cmd/wonderwall/main.go +++ b/cmd/wonderwall/main.go @@ -4,14 +4,13 @@ import ( "context" "encoding/base64" "fmt" - "github.com/go-chi/chi" - "github.com/nais/wonderwall/pkg/metrics" "net/http" "os" "os/signal" "syscall" "time" + "github.com/go-chi/chi/v5" "github.com/go-redis/redis/v8" "github.com/lestrrat-go/jwx/jwk" "github.com/nais/liberator/pkg/conftools" @@ -21,6 +20,7 @@ import ( "github.com/nais/wonderwall/pkg/config" "github.com/nais/wonderwall/pkg/cryptutil" "github.com/nais/wonderwall/pkg/logging" + "github.com/nais/wonderwall/pkg/metrics" "github.com/nais/wonderwall/pkg/router" "github.com/nais/wonderwall/pkg/session" ) @@ -94,7 +94,8 @@ func run() error { return fmt.Errorf("fetching jwks: %w", err) } - handler, err := router.NewHandler(cfg.IDPorten, crypt, jwkSet, sessionStore, cfg.UpstreamHost) + httplogger := logging.NewHttpLogger(cfg) + handler, err := router.NewHandler(cfg.IDPorten, crypt, httplogger, jwkSet, sessionStore, cfg.UpstreamHost) if err != nil { return fmt.Errorf("initializing routing handler: %w", err) } diff --git a/go.mod b/go.mod index 38fa7b3..1fd3637 100644 --- a/go.mod +++ b/go.mod @@ -3,7 +3,8 @@ module github.com/nais/wonderwall go 1.17 require ( - github.com/go-chi/chi v1.5.4 + github.com/go-chi/chi/v5 v5.0.4 + github.com/go-chi/httplog v0.2.0 github.com/go-redis/redis/v8 v8.11.3 github.com/google/uuid v1.1.2 github.com/lestrrat-go/jwx v1.2.7 @@ -42,6 +43,7 @@ require ( github.com/prometheus/client_model v0.0.0-20190812154241-14fe0d1b01d4 // indirect github.com/prometheus/common v0.4.1 // indirect github.com/prometheus/procfs v0.0.2 // indirect + github.com/rs/zerolog v1.18.1-0.20200514152719-663cbb4c8469 // indirect github.com/spf13/afero v1.6.0 // indirect github.com/spf13/cast v1.3.1 // indirect github.com/spf13/jwalterweatherman v1.1.0 // indirect diff --git a/go.sum b/go.sum index f8c16d1..69c5cf7 100644 --- a/go.sum +++ b/go.sum @@ -130,8 +130,11 @@ github.com/ghodss/yaml v0.0.0-20150909031657-73d445a93680/go.mod h1:4dBDuWmgqj2H github.com/ghodss/yaml v1.0.0/go.mod h1:4dBDuWmgqj2HViK6kFavaiC9ZROes6MMH2rRYeMEF04= github.com/globalsign/mgo v0.0.0-20180905125535-1ca0a4f7cbcb/go.mod h1:xkRDCp4j0OGD1HRkm4kmhM+pmpv3AKq5SU7GMg4oO/Q= github.com/globalsign/mgo v0.0.0-20181015135952-eeefdecb41b8/go.mod h1:xkRDCp4j0OGD1HRkm4kmhM+pmpv3AKq5SU7GMg4oO/Q= -github.com/go-chi/chi v1.5.4 h1:QHdzF2szwjqVV4wmByUnTcsbIg7UGaQ0tPF2t5GcAIs= -github.com/go-chi/chi v1.5.4/go.mod h1:uaf8YgoFazUOkPBG7fxPftUylNumIev9awIWOENIuEg= +github.com/go-chi/chi/v5 v5.0.0/go.mod h1:BBug9lr0cqtdAhsu6R4AAdvufI0/XBzAQSsUqJpoZOs= +github.com/go-chi/chi/v5 v5.0.4 h1:5e494iHzsYBiyXQAHHuI4tyJS9M3V84OuX3ufIIGHFo= +github.com/go-chi/chi/v5 v5.0.4/go.mod h1:DslCQbL2OYiznFReuXYUmQ2hGd1aDpCnlMNITLSKoi8= +github.com/go-chi/httplog v0.2.0 h1:sRqfURbFG5Wjmp5DzwrhZ7/TrT7XR2foq/fd9OLdfo4= +github.com/go-chi/httplog v0.2.0/go.mod h1:JyHOFO9twSfGoTin/RoP25Lx2a9Btq10ug+sgxe0+bo= github.com/go-gl/glfw v0.0.0-20190409004039-e6da0acd62b1/go.mod h1:vR7hzQXu2zJy9AVAgeJqvqgH9Q5CA+iKCZ2gyEVpxRU= github.com/go-gl/glfw/v3.3/glfw v0.0.0-20191125211704-12ad95a8df72/go.mod h1:tQ2UAYgL5IevRw8kRxooKSPJfGvJ9fJQFa0TUsXzTg8= github.com/go-gl/glfw/v3.3/glfw v0.0.0-20200222043503-6f7a984d4dc4/go.mod h1:tQ2UAYgL5IevRw8kRxooKSPJfGvJ9fJQFa0TUsXzTg8= @@ -433,6 +436,9 @@ github.com/remyoudompheng/bigfft v0.0.0-20170806203942-52369c62f446/go.mod h1:uY github.com/rogpeppe/fastuuid v0.0.0-20150106093220-6724a57986af/go.mod h1:XWv6SoW27p1b0cqNHllgS5HIMJraePCO15w5zCzIWYg= github.com/rogpeppe/fastuuid v1.2.0/go.mod h1:jVj6XXZzXRy/MSR5jhDC/2q6DgLz+nrA6LYCDYWNEvQ= github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4= +github.com/rs/xid v1.2.1/go.mod h1:+uKXf+4Djp6Md1KODXJxgGQPKngRmWyn10oCKFzNHOQ= +github.com/rs/zerolog v1.18.1-0.20200514152719-663cbb4c8469 h1:DuXsEWHUTO5lsxxzKM4KUKGDIOi7nawNDs6d+AiulEA= +github.com/rs/zerolog v1.18.1-0.20200514152719-663cbb4c8469/go.mod h1:IzD0RJ65iWH0w97OQQebJEvTZYvsCUm9WVLWBQrJRjo= github.com/russross/blackfriday v1.5.2/go.mod h1:JO/DiYxRf+HjHt06OyowR9PTA263kcR/rfWxYHBV53g= github.com/ryanuber/columnize v0.0.0-20160712163229-9b3edd62028f/go.mod h1:sm1tb6uqfes/u+d4ooFouqFdy9/2g9QGwK3SQygK0Ts= github.com/sean-/seed v0.0.0-20170313163322-e2103e2c3529/go.mod h1:DxrIzT+xaE7yg65j358z/aeFdxmN0P9QXhEzd20vsDc= @@ -733,6 +739,7 @@ golang.org/x/tools v0.0.0-20190617190820-da514acc4774/go.mod h1:/rFqwRUd4F7ZHNgw golang.org/x/tools v0.0.0-20190621195816-6e04913cbbac/go.mod h1:/rFqwRUd4F7ZHNgwSSTFct+R/Kf4OFW1sUzUTQQTgfc= golang.org/x/tools v0.0.0-20190628153133-6cdbf07be9d0/go.mod h1:/rFqwRUd4F7ZHNgwSSTFct+R/Kf4OFW1sUzUTQQTgfc= golang.org/x/tools v0.0.0-20190816200558-6889da9d5479/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= +golang.org/x/tools v0.0.0-20190828213141-aed303cbaa74/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/tools v0.0.0-20190911174233-4f2ddba30aff/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/tools v0.0.0-20190920225731-5eefd052ad72/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/tools v0.0.0-20191012152004-8de300cfc20a/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= diff --git a/pkg/config/config.go b/pkg/config/config.go index 335b9f0..436388a 100644 --- a/pkg/config/config.go +++ b/pkg/config/config.go @@ -3,9 +3,8 @@ package config import ( "time" - flag "github.com/spf13/pflag" - "github.com/nais/liberator/pkg/conftools" + flag "github.com/spf13/pflag" "github.com/spf13/viper" "github.com/nais/wonderwall/pkg/token" @@ -79,7 +78,7 @@ func Initialize() *Config { conftools.Initialize("wonderwall") bindNAIS() - flag.String(LogFormat, "text", "Log format, either 'json' or 'text'.") + flag.String(LogFormat, "json", "Log format, either 'json' or 'text'.") flag.String(LogLevel, "debug", "Logging verbosity level.") flag.String(BindAddress, "127.0.0.1:8090", "Listen address for public connections.") flag.String(MetricsBindAddress, "127.0.0.1:8091", "Listen address for metrics only.") diff --git a/pkg/errorhandler/errorhandler.go b/pkg/errorhandler/errorhandler.go index a6eef8f..dbb567c 100644 --- a/pkg/errorhandler/errorhandler.go +++ b/pkg/errorhandler/errorhandler.go @@ -1,22 +1,14 @@ package errorhandler import ( - "github.com/nais/wonderwall/pkg/middleware" - log "github.com/sirupsen/logrus" "net/http" + + "github.com/go-chi/httplog" ) func respondError(w http.ResponseWriter, r *http.Request, statusCode int, cause error) { - id, ok := middleware.GetCorrelationID(r.Context()) - if !ok { - log.Warnf("no correlation id in context") - } - - logFields := log.Fields{ - "correlation_id": id, - } - - log.WithFields(logFields).Error(cause) + logger := httplog.LogEntry(r.Context()) + logger.Error().Stack().Err(cause).Msgf("error in route: %+v", cause) w.WriteHeader(statusCode) } diff --git a/pkg/logging/httplog.go b/pkg/logging/httplog.go new file mode 100644 index 0000000..50e1cb6 --- /dev/null +++ b/pkg/logging/httplog.go @@ -0,0 +1,25 @@ +package logging + +import ( + "github.com/go-chi/httplog" + "github.com/rs/zerolog" + + "github.com/nais/wonderwall/pkg/config" +) + +func NewHttpLogger(cfg *config.Config) zerolog.Logger { + opts := httplog.Options{ + Concise: true, + LogLevel: "warn", + } + + format := cfg.LogFormat + switch format { + case "json": + opts.JSON = true + default: + opts.JSON = false + } + + return httplog.NewLogger("wonderwall", opts) +} diff --git a/pkg/middleware/correlationid.go b/pkg/middleware/correlationid.go index 721eab5..d50f305 100644 --- a/pkg/middleware/correlationid.go +++ b/pkg/middleware/correlationid.go @@ -2,22 +2,18 @@ package middleware import ( "context" - "github.com/google/uuid" "net/http" + + chi_middleware "github.com/go-chi/chi/v5/middleware" + "github.com/google/uuid" ) -// contextKey is the type of contextKeys used for correlation IDs. -type contextKey struct{} - -func GetCorrelationID(ctx context.Context) (string, bool) { - id, ok := ctx.Value(contextKey{}).(string) - return id, ok -} - func CorrelationIDHandler(next http.Handler) http.Handler { fn := func(w http.ResponseWriter, r *http.Request) { + id := uuid.New().String() + ctx := r.Context() - ctx = context.WithValue(ctx, contextKey{}, uuid.New().String()) + ctx = context.WithValue(ctx, chi_middleware.RequestIDKey, id) next.ServeHTTP(w, r.WithContext(ctx)) } return http.HandlerFunc(fn) diff --git a/pkg/middleware/logentry.go b/pkg/middleware/logentry.go new file mode 100644 index 0000000..1d13e76 --- /dev/null +++ b/pkg/middleware/logentry.go @@ -0,0 +1,97 @@ +package middleware + +import ( + "bytes" + "io" + "io/ioutil" + "net/http" + "time" + + "github.com/go-chi/chi/v5/middleware" + "github.com/go-chi/httplog" + "github.com/rs/zerolog" +) + +// LogEntryHandler is copied verbatim from httplog package to replace with our own requestLogger implementation. +func LogEntryHandler(logger zerolog.Logger) func(next http.Handler) http.Handler { + var f middleware.LogFormatter = &requestLogger{logger} + return func(next http.Handler) http.Handler { + fn := func(w http.ResponseWriter, r *http.Request) { + entry := f.NewLogEntry(r) + ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor) + + buf := newLimitBuffer(512) + ww.Tee(buf) + + t1 := time.Now() + defer func() { + var respBody []byte + if ww.Status() >= 400 { + respBody, _ = ioutil.ReadAll(buf) + } + entry.Write(ww.Status(), ww.BytesWritten(), ww.Header(), time.Since(t1), respBody) + }() + + next.ServeHTTP(ww, middleware.WithLogEntry(r, entry)) + } + return http.HandlerFunc(fn) + } +} + +type requestLogger struct { + Logger zerolog.Logger +} + +func (l *requestLogger) NewLogEntry(r *http.Request) middleware.LogEntry { + entry := &httplog.RequestLoggerEntry{} + entry.Logger = l.Logger.With().Fields(requestLogFields(r)).Logger() + return entry +} + +func requestLogFields(r *http.Request) map[string]interface{} { + requestFields := map[string]interface{}{ + "requestMethod": r.Method, + "requestPath": r.URL.Path, + "proto": r.Proto, + } + if reqID := middleware.GetReqID(r.Context()); reqID != "" { + requestFields["requestID"] = reqID + } + + return map[string]interface{}{ + "httpRequest": requestFields, + } +} + +// limitBuffer is used to pipe response body information from the +// response writer to a certain limit amount. The idea is to read +// a portion of the response body such as an error response so we +// may log it. +// +// Copied verbatim from httplog package as it is unexported. +type limitBuffer struct { + *bytes.Buffer + limit int +} + +func newLimitBuffer(size int) io.ReadWriter { + return limitBuffer{ + Buffer: bytes.NewBuffer(make([]byte, 0, size)), + limit: size, + } +} + +func (b limitBuffer) Write(p []byte) (n int, err error) { + if b.Buffer.Len() >= b.limit { + return len(p), nil + } + limit := b.limit + if len(p) < limit { + limit = len(p) + } + return b.Buffer.Write(p[:limit]) +} + +func (b limitBuffer) Read(p []byte) (n int, err error) { + return b.Buffer.Read(p) +} diff --git a/pkg/middleware/prometheus.go b/pkg/middleware/prometheus.go index b8ae8c5..9999f96 100644 --- a/pkg/middleware/prometheus.go +++ b/pkg/middleware/prometheus.go @@ -8,7 +8,7 @@ import ( "strconv" "time" - chi_middleware "github.com/go-chi/chi/middleware" + chi_middleware "github.com/go-chi/chi/v5/middleware" "github.com/prometheus/client_golang/prometheus" ) diff --git a/pkg/mock/idporten.go b/pkg/mock/idporten.go index 32b5630..1b704dc 100644 --- a/pkg/mock/idporten.go +++ b/pkg/mock/idporten.go @@ -9,7 +9,7 @@ import ( "net/url" "time" - "github.com/go-chi/chi" + "github.com/go-chi/chi/v5" "github.com/google/uuid" "github.com/lestrrat-go/jwx/jwa" "github.com/lestrrat-go/jwx/jwk" diff --git a/pkg/router/handler.go b/pkg/router/handler.go index 6987cca..85e4f71 100644 --- a/pkg/router/handler.go +++ b/pkg/router/handler.go @@ -1,6 +1,7 @@ package router import ( + "github.com/rs/zerolog" "sync" "github.com/lestrrat-go/jwx/jwk" @@ -27,9 +28,17 @@ type Handler struct { UpstreamHost string jwkSet jwk.Set lock sync.Mutex + httplogger zerolog.Logger } -func NewHandler(cfg config.IDPorten, crypter cryptutil.Crypter, jwkSet jwk.Set, sessionStore session.Store, upstreamHost string) (*Handler, error) { +func NewHandler( + cfg config.IDPorten, + crypter cryptutil.Crypter, + httplogger zerolog.Logger, + jwkSet jwk.Set, + sessionStore session.Store, + upstreamHost string, +) (*Handler, error) { oauthConfig := oauth2.Config{ ClientID: cfg.ClientID, Endpoint: oauth2.Endpoint{ @@ -43,6 +52,7 @@ func NewHandler(cfg config.IDPorten, crypter cryptutil.Crypter, jwkSet jwk.Set, return &Handler{ Config: cfg, Crypter: crypter, + httplogger: httplogger, jwkSet: jwkSet, lock: sync.Mutex{}, OauthConfig: oauthConfig, diff --git a/pkg/router/router.go b/pkg/router/router.go index 3594dcf..2de960b 100644 --- a/pkg/router/router.go +++ b/pkg/router/router.go @@ -1,20 +1,22 @@ package router import ( - "github.com/go-chi/chi" - chi_middleware "github.com/go-chi/chi/middleware" + "github.com/go-chi/chi/v5" + chi_middleware "github.com/go-chi/chi/v5/middleware" "github.com/nais/wonderwall/pkg/middleware" ) func New(handler *Handler, prefixes []string) chi.Router { r := chi.NewRouter() + r.Use(middleware.CorrelationIDHandler) + r.Use(middleware.LogEntryHandler(handler.httplogger)) + r.Use(chi_middleware.Recoverer) prometheusMiddleware := middleware.NewPrometheusMiddleware("wonderwall") for _, prefix := range prefixes { r.Route(prefix+"/oauth2", func(r chi.Router) { r.Use(prometheusMiddleware.Handler) - r.Use(middleware.CorrelationIDHandler) r.Use(chi_middleware.NoCache) r.Get("/login", handler.Login) r.Get("/callback", handler.Callback) diff --git a/pkg/router/router_test.go b/pkg/router/router_test.go index 4a629c8..e0bdc5d 100644 --- a/pkg/router/router_test.go +++ b/pkg/router/router_test.go @@ -7,7 +7,6 @@ import ( "encoding/base64" "encoding/json" "fmt" - "github.com/nais/wonderwall/pkg/mock" "net/http" "net/http/cookiejar" "net/http/httptest" @@ -16,10 +15,12 @@ import ( "time" "github.com/lestrrat-go/jwx/jwk" + "github.com/rs/zerolog" "github.com/stretchr/testify/assert" "github.com/nais/wonderwall/pkg/config" "github.com/nais/wonderwall/pkg/cryptutil" + "github.com/nais/wonderwall/pkg/mock" "github.com/nais/wonderwall/pkg/router" "github.com/nais/wonderwall/pkg/session" ) @@ -88,7 +89,7 @@ func handler(cfg config.IDPorten) *router.Handler { crypter := cryptutil.New(encryptionKey) sessionStore := session.NewMemory() - handler, err := router.NewHandler(cfg, crypter, jwkSet, sessionStore, "") + handler, err := router.NewHandler(cfg, crypter, zerolog.Logger{}, jwkSet, sessionStore, "") if err != nil { panic(err) }