refactor(middleware/logentry): replace zerologger with logrus

This commit is contained in:
Trong Huu Nguyen
2022-07-18 15:47:35 +02:00
parent 445a20f1c1
commit bece03c94e
15 changed files with 111 additions and 203 deletions

View File

@@ -61,8 +61,7 @@ func run() error {
crypt := crypto.NewCrypter(key)
sessionStore := session.NewStore(cfg)
httplogger := logging.NewHttpLogger(cfg)
h, err := handler.NewHandler(jwksRefreshCtx, openidConfig, crypt, httplogger, sessionStore)
h, err := handler.NewHandler(jwksRefreshCtx, openidConfig, crypt, sessionStore)
if err != nil {
return fmt.Errorf("initializing routing handler: %w", err)
}

2
go.mod
View File

@@ -11,7 +11,6 @@ require (
github.com/lestrrat-go/jwx/v2 v2.0.3
github.com/nais/liberator v0.0.0-20220708061353-10750ef0b304
github.com/prometheus/client_golang v1.12.2
github.com/rs/zerolog v1.27.0
github.com/sethvargo/go-retry v0.2.3
github.com/sirupsen/logrus v1.8.1
github.com/spf13/pflag v1.0.5
@@ -48,6 +47,7 @@ require (
github.com/prometheus/client_model v0.2.0 // indirect
github.com/prometheus/common v0.36.0 // indirect
github.com/prometheus/procfs v0.7.3 // indirect
github.com/rs/zerolog v1.27.0 // indirect
github.com/spf13/afero v1.8.2 // indirect
github.com/spf13/cast v1.5.0 // indirect
github.com/spf13/jwalterweatherman v1.1.0 // indirect

View File

@@ -4,8 +4,6 @@ import (
"context"
"net/http"
"github.com/rs/zerolog"
"github.com/nais/wonderwall/pkg/autologin"
"github.com/nais/wonderwall/pkg/config"
"github.com/nais/wonderwall/pkg/cookie"
@@ -26,14 +24,12 @@ type Handler struct {
Loginstatus loginstatus.Client
Provider provider.Provider
Sessions session.Store
Httplogger zerolog.Logger
}
func NewHandler(
jwksRefreshCtx context.Context,
cfg openidconfig.Config,
crypter crypto.Crypter,
httplogger zerolog.Logger,
sessionStore session.Store,
) (*Handler, error) {
loginstatusClient := loginstatus.NewClient(cfg.Wonderwall().Loginstatus, http.DefaultClient)
@@ -58,7 +54,6 @@ func NewHandler(
Client: openidClient,
CookieOptions: cookieOpts,
Crypter: crypter,
Httplogger: httplogger,
Loginstatus: loginstatusClient,
Cfg: cfg,
Provider: openidProvider,

View File

@@ -51,7 +51,7 @@ func (h *Handler) Callback(w http.ResponseWriter, r *http.Request) {
return
}
tokens, err := h.redeemValidTokens(r.Context(), loginCallback)
tokens, err := h.redeemValidTokens(r, loginCallback)
if err != nil {
h.InternalError(w, r, fmt.Errorf("callback: %w", err))
return
@@ -64,35 +64,35 @@ func (h *Handler) Callback(w http.ResponseWriter, r *http.Request) {
}
if h.Cfg.Wonderwall().Loginstatus.Enabled {
tokenResponse, err := h.getLoginstatusToken(r.Context(), tokens)
tokenResponse, err := h.getLoginstatusToken(r, tokens)
if err != nil {
h.InternalError(w, r, fmt.Errorf("callback: exchanging loginstatus token: %w", err))
return
}
h.Loginstatus.SetCookie(w, tokenResponse, h.CookieOptions)
log.Debug("callback: successfully fetched loginstatus token")
logentry.LogEntry(r).Debug("callback: successfully fetched loginstatus token")
}
logSuccessfulLogin(r, tokens, loginCookie.Referer)
http.Redirect(w, r, loginCookie.Referer, http.StatusTemporaryRedirect)
}
func (h *Handler) redeemValidTokens(ctx context.Context, loginCallback client.LoginCallback) (*openid.Tokens, error) {
func (h *Handler) redeemValidTokens(r *http.Request, loginCallback client.LoginCallback) (*openid.Tokens, error) {
var tokens *openid.Tokens
var err error
retryable := func(ctx context.Context) error {
tokens, err = loginCallback.RedeemTokens(ctx)
if err != nil {
log.Warnf("callback: retrying: %+v", err)
logentry.LogEntry(r).Warnf("callback: retrying: %+v", err)
return retry.RetryableError(err)
}
return nil
}
err = retry.Do(ctx, backoff(), retryable)
err = retry.Do(r.Context(), backoff(), retryable)
if err != nil {
return nil, err
}
@@ -100,15 +100,15 @@ func (h *Handler) redeemValidTokens(ctx context.Context, loginCallback client.Lo
return tokens, nil
}
func (h *Handler) getLoginstatusToken(ctx context.Context, tokens *openid.Tokens) (*loginstatus.TokenResponse, error) {
func (h *Handler) getLoginstatusToken(r *http.Request, tokens *openid.Tokens) (*loginstatus.TokenResponse, error) {
var tokenResponse *loginstatus.TokenResponse
err := retry.Do(ctx, backoff(), func(ctx context.Context) error {
err := retry.Do(r.Context(), backoff(), func(ctx context.Context) error {
var err error
tokenResponse, err = h.Loginstatus.ExchangeToken(ctx, tokens.AccessToken)
if err != nil {
log.Warnf("callback: exchanging loginstatus token; retrying: %+v", err)
logentry.LogEntry(r).Warnf("callback: exchanging loginstatus token; retrying: %+v", err)
return retry.RetryableError(err)
}
@@ -122,13 +122,12 @@ func (h *Handler) getLoginstatusToken(ctx context.Context, tokens *openid.Tokens
}
func logSuccessfulLogin(r *http.Request, tokens *openid.Tokens, referer string) {
fields := map[string]interface{}{
fields := log.Fields{
"redirect_to": referer,
"jti": tokens.IDToken.GetJwtID(),
}
logger := logentry.LogEntryWithFields(r.Context(), fields)
logger.Info().Msg("callback: successful login")
logentry.LogEntry(r).WithFields(fields).Info("callback: successful login")
}
func backoff() retry.Backoff {

View File

@@ -4,8 +4,7 @@ import (
"net/http"
"net/http/httputil"
log "github.com/sirupsen/logrus"
logentry "github.com/nais/wonderwall/pkg/middleware"
"github.com/nais/wonderwall/pkg/session"
)
@@ -24,7 +23,7 @@ func (h *Handler) Default(w http.ResponseWriter, r *http.Request) {
// force new authentication if loginstatus is enabled and cookie isn't set
if h.Cfg.Wonderwall().Loginstatus.Enabled && !h.Loginstatus.HasCookie(r) {
isAuthenticated = false
log.Info("default: loginstatus was enabled, but no matching cookie was found; state is now unauthenticated")
logentry.LogEntry(r).Info("default: loginstatus was enabled, but no matching cookie was found; state is now unauthenticated")
}
}

View File

@@ -8,7 +8,6 @@ import (
"strconv"
"github.com/go-chi/chi/v5/middleware"
"github.com/rs/zerolog"
log "github.com/sirupsen/logrus"
logentry "github.com/nais/wonderwall/pkg/middleware"
@@ -34,9 +33,16 @@ func init() {
}
}
func (h *Handler) respondError(w http.ResponseWriter, r *http.Request, statusCode int, cause error, level zerolog.Level) {
logger := logentry.LogEntry(r.Context())
logger.WithLevel(level).Stack().Err(cause).Msgf("error in route: %+v", cause)
func (h *Handler) respondError(w http.ResponseWriter, r *http.Request, statusCode int, cause error, level log.Level) {
logger := logentry.LogEntry(r)
msg := "error in route: %+v"
switch level {
case log.WarnLevel:
logger.Warnf(msg, cause)
default:
logger.Errorf(msg, cause)
}
if len(h.Cfg.Wonderwall().ErrorRedirectURI) > 0 {
err := h.customErrorRedirect(w, r, statusCode)
@@ -62,7 +68,7 @@ func (h *Handler) defaultErrorResponse(w http.ResponseWriter, r *http.Request, s
}
err = errorTemplate.Execute(w, errorPage)
if err != nil {
log.Errorf("executing error template: %+v", err)
logentry.LogEntry(r).Errorf("executing error template: %+v", err)
}
}
@@ -87,13 +93,13 @@ func (h *Handler) customErrorRedirect(w http.ResponseWriter, r *http.Request, st
}
func (h *Handler) InternalError(w http.ResponseWriter, r *http.Request, cause error) {
h.respondError(w, r, http.StatusInternalServerError, cause, zerolog.ErrorLevel)
h.respondError(w, r, http.StatusInternalServerError, cause, log.ErrorLevel)
}
func (h *Handler) BadRequest(w http.ResponseWriter, r *http.Request, cause error) {
h.respondError(w, r, http.StatusBadRequest, cause, zerolog.ErrorLevel)
h.respondError(w, r, http.StatusBadRequest, cause, log.ErrorLevel)
}
func (h *Handler) Unauthorized(w http.ResponseWriter, r *http.Request, cause error) {
h.respondError(w, r, http.StatusUnauthorized, cause, zerolog.WarnLevel)
h.respondError(w, r, http.StatusUnauthorized, cause, log.WarnLevel)
}

View File

@@ -3,9 +3,8 @@ package handler
import (
"net/http"
log "github.com/sirupsen/logrus"
"github.com/nais/wonderwall/pkg/cookie"
logentry "github.com/nais/wonderwall/pkg/middleware"
)
// FrontChannelLogout triggers logout triggered by a third-party.
@@ -19,7 +18,7 @@ func (h *Handler) FrontChannelLogout(w http.ResponseWriter, r *http.Request) {
logoutFrontchannel := h.Client.LogoutFrontchannel(r)
if logoutFrontchannel.MissingSidParameter() {
log.Info("front-channel logout: sid parameter not set in request; ignoring")
logentry.LogEntry(r).Info("front-channel logout: sid parameter not set in request; ignoring")
h.DeleteSessionFallback(w, r)
w.WriteHeader(http.StatusAccepted)
return
@@ -29,14 +28,14 @@ func (h *Handler) FrontChannelLogout(w http.ResponseWriter, r *http.Request) {
sessionID := h.localSessionID(sid)
sessionData, err := h.getSession(r.Context(), sessionID)
if err != nil {
log.Infof("front-channel logout: getting session (user might already be logged out): %+v", err)
logentry.LogEntry(r).Infof("front-channel logout: getting session (user might already be logged out): %+v", err)
}
err = h.destroySession(w, r, sessionID)
if err != nil {
log.Errorf("front-channel logout: destroying session: %+v", err)
logentry.LogEntry(r).Warnf("front-channel logout: destroying session: %+v", err)
} else if sessionData != nil {
log.WithField("jti", sessionData.IDTokenJwtID).Infof("front-channel logout: successful logout")
logentry.LogEntry(r).WithField("jti", sessionData.IDTokenJwtID).Infof("front-channel logout: successful logout")
}
w.WriteHeader(http.StatusOK)

View File

@@ -7,6 +7,8 @@ import (
"net/http"
"time"
log "github.com/sirupsen/logrus"
"github.com/nais/wonderwall/pkg/cookie"
logentry "github.com/nais/wonderwall/pkg/middleware"
"github.com/nais/wonderwall/pkg/openid"
@@ -35,20 +37,17 @@ func (h *Handler) Login(w http.ResponseWriter, r *http.Request) {
return
}
fields := map[string]interface{}{
fields := log.Fields{
"redirect_after_login": login.CanonicalRedirect(),
}
logger := logentry.LogEntryWithFields(r.Context(), fields)
logger.Info().Msg("login: redirecting to identity provider")
logentry.LogEntry(r).WithFields(fields).Info("login: redirecting to identity provider")
http.Redirect(w, r, login.AuthCodeURL(), http.StatusTemporaryRedirect)
}
func (h *Handler) getLoginCookie(r *http.Request) (*openid.LoginCookie, error) {
loginCookieJson, err := cookie.GetDecrypted(r, cookie.Login, h.Crypter)
if err != nil {
logger := logentry.LogEntry(r.Context())
logger.Info().Msgf("failed to fetch login cookie: %+v; falling back to legacy cookie", err)
logentry.LogEntry(r).Debugf("failed to fetch login cookie: %+v; falling back to legacy cookie", err)
loginCookieJson, err = cookie.GetDecrypted(r, cookie.LoginLegacy, h.Crypter)
if err != nil {

View File

@@ -6,6 +6,7 @@ import (
"net/http"
"github.com/go-redis/redis/v8"
log "github.com/sirupsen/logrus"
"github.com/nais/wonderwall/pkg/cookie"
logentry "github.com/nais/wonderwall/pkg/middleware"
@@ -24,11 +25,10 @@ func (h *Handler) Logout(w http.ResponseWriter, r *http.Request) {
return
}
fields := map[string]interface{}{
fields := log.Fields{
"jti": sessionData.IDTokenJwtID,
}
logger := logentry.LogEntryWithFields(r.Context(), fields)
logger.Info().Msg("logout: successful local logout")
logentry.LogEntry(r).WithFields(fields).Info("logout: successful local logout")
}
cookie.Clear(w, cookie.Session, h.CookieOptions)
@@ -43,8 +43,6 @@ func (h *Handler) Logout(w http.ResponseWriter, r *http.Request) {
return
}
logger := logentry.LogEntry(r.Context())
logger.Info().Msg("logout: redirecting to identity provider")
logentry.LogEntry(r).Info("logout: redirecting to identity provider")
http.Redirect(w, r, logout.SingleLogoutURL(idToken), http.StatusTemporaryRedirect)
}

View File

@@ -10,7 +10,6 @@ import (
func (h *Handler) LogoutCallback(w http.ResponseWriter, r *http.Request) {
redirect := h.Client.LogoutCallback(r).PostLogoutRedirectURI()
logger := logentry.LogEntry(r.Context())
logger.Info().Msgf("logout/callback: redirecting to %s", redirect)
logentry.LogEntry(r).Infof("logout/callback: redirecting to %s", redirect)
http.Redirect(w, r, redirect, http.StatusTemporaryRedirect)
}

View File

@@ -8,9 +8,9 @@ import (
"time"
"github.com/go-redis/redis/v8"
log "github.com/sirupsen/logrus"
"github.com/nais/wonderwall/pkg/cookie"
logentry "github.com/nais/wonderwall/pkg/middleware"
"github.com/nais/wonderwall/pkg/openid"
"github.com/nais/wonderwall/pkg/session"
)
@@ -40,7 +40,7 @@ func (h *Handler) getSessionFromCookie(w http.ResponseWriter, r *http.Request) (
return nil, fmt.Errorf("session not found in store: %w", err)
}
log.Warnf("get session: store is unavailable: %+v; using cookie fallback", err)
logentry.LogEntry(r).Warnf("get session: store is unavailable: %+v; using cookie fallback", err)
fallbackSessionData, err := h.GetSessionFallback(w, r)
if err != nil {
@@ -107,7 +107,7 @@ func (h *Handler) createSession(w http.ResponseWriter, r *http.Request, tokens *
return nil
}
log.Warnf("create session: store is unavailable: %+v; using cookie fallback", err)
logentry.LogEntry(r).Warnf("create session: store is unavailable: %+v; using cookie fallback", err)
err = h.SetSessionFallback(w, r, sessionData, sessionLifetime)
if err != nil {

View File

@@ -1,25 +0,0 @@
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: "info",
}
format := cfg.LogFormat
switch format {
case "json":
opts.JSON = true
default:
opts.JSON = false
}
return httplog.NewLogger("wonderwall", opts)
}

View File

@@ -1,39 +1,33 @@
package middleware
import (
"bytes"
"context"
"fmt"
"io"
"io/ioutil"
"net/http"
"strings"
"time"
"github.com/go-chi/chi/v5/middleware"
"github.com/go-chi/httplog"
"github.com/rs/zerolog"
log "github.com/sirupsen/logrus"
"github.com/nais/wonderwall/pkg/cookie"
)
var logger *requestLogger
// 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}
func LogEntryHandler(provider string) func(next http.Handler) http.Handler {
logger = &requestLogger{Logger: log.StandardLogger(), Provider: provider}
return func(next http.Handler) http.Handler {
fn := func(w http.ResponseWriter, r *http.Request) {
entry := f.NewLogEntry(r)
entry := logger.NewLogEntry(r)
entry.WithRequestLogFields(r).Debugf("request")
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)
entry.Write(ww.Status(), ww.BytesWritten(), ww.Header(), time.Since(t1), nil)
}()
next.ServeHTTP(ww, middleware.WithLogEntry(r, entry))
@@ -42,50 +36,70 @@ func LogEntryHandler(logger zerolog.Logger) func(next http.Handler) http.Handler
}
}
func LogEntry(ctx context.Context) zerolog.Logger {
func LogEntry(r *http.Request) *log.Entry {
ctx := r.Context()
val := ctx.Value(middleware.LogEntryCtxKey)
entry, ok := val.(*requestLoggerEntry)
if ok {
return entry.Logger
}
return httplog.NewLogger("wonderwall")
}
func LogEntryWithFields(ctx context.Context, fields any) zerolog.Logger {
return LogEntry(ctx).With().Fields(fields).Logger()
entry = logger.NewLogEntry(r)
return entry.Logger
}
type requestLogger struct {
Logger zerolog.Logger
Logger *log.Logger
Provider string
}
func (l *requestLogger) NewLogEntry(r *http.Request) middleware.LogEntry {
func (l *requestLogger) NewLogEntry(r *http.Request) *requestLoggerEntry {
entry := &requestLoggerEntry{}
entry.Logger = l.Logger.With().Fields(requestLogFields(r)).Logger()
correlationID := middleware.GetReqID(r.Context())
fields := log.Fields{
"correlation_id": correlationID,
"provider": l.Provider,
}
entry.Logger = l.Logger.WithFields(fields)
return entry
}
type requestLoggerEntry struct {
Logger zerolog.Logger
msg string
Logger *log.Entry
}
func (l *requestLoggerEntry) Write(status, bytes int, header http.Header, elapsed time.Duration, extra interface{}) {
func (l *requestLoggerEntry) WithRequestLogFields(r *http.Request) *log.Entry {
fields := log.Fields{
"request_cookies": nonEmptyRequestCookies(r),
"request_host": r.Host,
"request_method": r.Method,
"request_path": r.URL.Path,
"request_protocol": r.Proto,
"request_referer": r.Referer(),
"request_user_agent": r.UserAgent(),
}
return l.Logger.WithFields(fields)
}
func (l *requestLoggerEntry) Write(status, bytes int, _ http.Header, elapsed time.Duration, _ any) {
msg := fmt.Sprintf("response: HTTP %d (%s)", status, statusLabel(status))
if l.msg != "" {
msg = fmt.Sprintf("%s - %s", msg, l.msg)
fields := log.Fields{
"response_status": status,
"response_bytes": bytes,
"response_elapsed_ms": float64(elapsed.Nanoseconds()) / 1000000.0, // in milliseconds, with fractional
}
responseLog := map[string]interface{}{
"status": status,
"bytes": bytes,
"elapsed": float64(elapsed.Nanoseconds()) / 1000000.0, // in milliseconds
}
entry := l.Logger.WithFields(fields)
l.Logger.WithLevel(statusLevel(status)).Fields(map[string]interface{}{
"httpResponse": responseLog,
}).Msgf(msg)
switch {
case status >= 400:
entry.Infof(msg)
default:
entry.Debugf(msg)
}
}
func (l *requestLoggerEntry) Panic(v interface{}, stack []byte) {
@@ -94,25 +108,12 @@ func (l *requestLoggerEntry) Panic(v interface{}, stack []byte) {
stacktrace = string(stack)
}
l.Logger = l.Logger.With().
Str("stacktrace", stacktrace).
Str("panic", fmt.Sprintf("%+v", v)).
Logger()
l.msg = fmt.Sprintf("%+v", v)
if !httplog.DefaultOptions.JSON {
middleware.PrintPrettyStack(v)
fields := log.Fields{
"stacktrace": stacktrace,
"error": fmt.Sprintf("%+v", v),
}
}
func statusLevel(status int) zerolog.Level {
switch {
case status >= 400:
return zerolog.InfoLevel
default:
return zerolog.DebugLevel
}
l.Logger = l.Logger.WithFields(fields)
}
func statusLabel(status int) string {
@@ -130,45 +131,18 @@ func statusLabel(status int) string {
}
}
func requestLogFields(r *http.Request) map[string]interface{} {
requestFields := map[string]interface{}{
"cookies": requestCookies(r),
"protocol": r.Proto,
"referer": r.Referer(),
"requestMethod": r.Method,
"requestPath": r.URL.Path,
"userAgent": r.UserAgent(),
}
if reqID := middleware.GetReqID(r.Context()); reqID != "" {
requestFields["requestID"] = reqID
}
return map[string]interface{}{
"httpRequest": requestFields,
}
}
type requestCookie struct {
Name string `json:"name"`
IsEmpty bool `json:"isEmpty"`
}
func requestCookies(r *http.Request) []requestCookie {
result := make([]requestCookie, 0)
func nonEmptyRequestCookies(r *http.Request) string {
result := make([]string, 0)
for _, c := range r.Cookies() {
if !isRelevantCookie(c.Name) {
if !isRelevantCookie(c.Name) || len(c.Value) <= 0 {
continue
}
result = append(result, requestCookie{
Name: c.Name,
IsEmpty: len(c.Value) <= 0,
})
result = append(result, c.Name)
}
return result
return strings.Join(result, ", ")
}
func isRelevantCookie(name string) bool {
@@ -181,36 +155,3 @@ func isRelevantCookie(name string) bool {
return false
}
// 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)
}

View File

@@ -16,7 +16,6 @@ import (
"github.com/lestrrat-go/jwx/v2/jwa"
"github.com/lestrrat-go/jwx/v2/jwk"
"github.com/lestrrat-go/jwx/v2/jwt"
"github.com/rs/zerolog"
"github.com/nais/wonderwall/pkg/config"
"github.com/nais/wonderwall/pkg/crypto"
@@ -77,7 +76,7 @@ func NewIdentityProvider(cfg *config.Config) IdentityProvider {
sessionStore := session.NewMemory()
ctx, cancel := context.WithCancel(context.Background())
rpHandler, err := handlerpkg.NewHandler(ctx, openidConfig, crypter, zerolog.Nop(), sessionStore)
rpHandler, err := handlerpkg.NewHandler(ctx, openidConfig, crypter, sessionStore)
if err != nil {
panic(err)
}

View File

@@ -19,7 +19,7 @@ func New(handler *handler.Handler) chi.Router {
prefix := config.ParseIngress(handler.Cfg.Wonderwall().Ingress)
r.Group(func(r chi.Router) {
r.Use(middleware.LogEntryHandler(handler.Httplogger))
r.Use(middleware.LogEntryHandler(handler.Cfg.ProviderName()))
r.Use(prometheusMiddleware.Handler)
r.Use(chi_middleware.NoCache)