diff --git a/external/v3/user/login.go b/external/v3/user/login.go index 662a5ba..9b2cf9c 100644 --- a/external/v3/user/login.go +++ b/external/v3/user/login.go @@ -5,6 +5,7 @@ import ( "fmt" "github.com/VATUSA/primary-api/pkg/config" "github.com/VATUSA/primary-api/pkg/cookie" + logger "github.com/VATUSA/primary-api/pkg/logging" "github.com/VATUSA/primary-api/pkg/oauth" "github.com/VATUSA/primary-api/pkg/utils" gonanoid "github.com/matoous/go-nanoid" @@ -80,17 +81,20 @@ func GetLogin(w http.ResponseWriter, r *http.Request) { func GetLoginCallback(w http.ResponseWriter, r *http.Request) { sessionCookie, err := r.Cookie("session") if err != nil { + logger.ErrorWithErr(err, "Error getting session cookie") utils.Render(w, r, utils.ErrForbidden) return } session := make(map[string]string) if err := cookie.CookieStore.Decode("session", sessionCookie.Value, &session); err != nil { + logger.ErrorWithErr(err, "Error decoding session cookie") utils.Render(w, r, utils.ErrForbidden) return } if r.URL.Query().Get("state") != session["state"] { + logger.Error("State mismatch on login/callback") utils.Render(w, r, utils.ErrForbidden) return } diff --git a/go.mod b/go.mod index 1f2906b..20c5299 100644 --- a/go.mod +++ b/go.mod @@ -46,10 +46,13 @@ require ( github.com/josharian/intern v1.0.0 // indirect github.com/leodido/go-urn v1.4.0 // indirect github.com/mailru/easyjson v0.7.7 // indirect + github.com/mattn/go-colorable v0.1.13 // indirect + github.com/mattn/go-isatty v0.0.20 // indirect + github.com/rs/zerolog v1.33.0 // indirect github.com/swaggo/files v1.0.1 // indirect golang.org/x/crypto v0.22.0 // indirect golang.org/x/net v0.24.0 // indirect - golang.org/x/sys v0.19.0 // indirect + golang.org/x/sys v0.20.0 // indirect golang.org/x/text v0.14.0 // indirect golang.org/x/tools v0.20.0 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect diff --git a/go.sum b/go.sum index c52ac94..04e13cb 100644 --- a/go.sum +++ b/go.sum @@ -28,6 +28,7 @@ github.com/aws/aws-sdk-go-v2/service/s3 v1.53.1 h1:6cnno47Me9bRykw9AEv9zkXE+5or7 github.com/aws/aws-sdk-go-v2/service/s3 v1.53.1/go.mod h1:qmdkIIAC+GCLASF7R2whgNrJADz0QZPX+Seiw/i4S3o= github.com/aws/smithy-go v1.20.2 h1:tbp628ireGtzcHDDmLT/6ADHidqnwgF57XOXZe6tp4Q= github.com/aws/smithy-go v1.20.2/go.mod h1:krry+ya/rV9RDcV/Q16kpu6ypI4K2czasz0NC3qS14E= +github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/gabriel-vasile/mimetype v1.4.3 h1:in2uUcidCuFcDKtdcBxlR0rJ1+fsokWf+uqxgUFjbI0= @@ -57,6 +58,7 @@ github.com/go-playground/validator/v10 v10.19.0/go.mod h1:dbuPbCMFw/DrkbEynArYaC github.com/go-sql-driver/mysql v1.7.0/go.mod h1:OXbVy3sEdcQ2Doequ6Z5BW6fXNQTmx+9S1MCJN5yJMI= github.com/go-sql-driver/mysql v1.8.1 h1:LedoTUt/eveggdHS9qUFC1EFSa8bU2+1pZjSRpvNJ1Y= github.com/go-sql-driver/mysql v1.8.1/go.mod h1:wEBSXgmK//2ZFJyE+qWnIsVGmvmEKlqwuVSjsCm7DZg= +github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= github.com/google/go-cmp v0.5.9 h1:O2Tfq5qg4qc4AmwVlvv0oLiVAGB7enBSJ2x2DqQFi38= github.com/google/go-cmp v0.5.9/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= github.com/google/gofuzz v1.2.0 h1:xRy4A+RhZaiKjJ1bPfwQ8sedCA+YS2YcCHW6ec7JMi0= @@ -81,10 +83,20 @@ github.com/mailru/easyjson v0.7.7 h1:UGYAvKxe3sBsEDzO8ZeWOSlIQfWFlxbzLZe7hwFURr0 github.com/mailru/easyjson v0.7.7/go.mod h1:xzfreul335JAWq5oZzymOObrkdz5UnU4kGfJJLY9Nlc= github.com/matoous/go-nanoid v1.5.0 h1:VRorl6uCngneC4oUQqOYtO3S0H5QKFtKuKycFG3euek= github.com/matoous/go-nanoid v1.5.0/go.mod h1:zyD2a71IubI24efhpvkJz+ZwfwagzgSO6UNiFsZKN7U= +github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA= +github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg= +github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= +github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= +github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY= +github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= +github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/rogpeppe/go-internal v1.11.0 h1:cWPaGQEPrBb5/AsnsZesgZZ9yb1OQ+GOISoDNXVBh4M= github.com/rogpeppe/go-internal v1.11.0/go.mod h1:ddIwULY96R17DhadqLgMfk9H9tvdUzkipdSkR5nkCZA= +github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= +github.com/rs/zerolog v1.33.0 h1:1cU2KZkvPxNyfgEmhHAz/1A9Bz+llsdYzklWFzgp0r8= +github.com/rs/zerolog v1.33.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss= github.com/stretchr/testify v1.9.0 h1:HtqpIVDClZ4nwg75+f6Lvsy/wHu+3BoSGCbBAcpTsTg= github.com/stretchr/testify v1.9.0/go.mod h1:r2ic/lqez/lEtzL7wO/rwa5dbSLXVDPFyf8C91i36aY= github.com/swaggo/files v1.0.1 h1:J1bVJ4XHZNq0I46UU90611i9/YzdrF7x92oX1ig5IdE= @@ -118,9 +130,14 @@ golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7w golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.5.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.19.0 h1:q5f1RH2jigJ1MoAWp2KTp3gm5zAGFUTarQZ5U386+4o= golang.org/x/sys v0.19.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= +golang.org/x/sys v0.20.0 h1:Od9JTbYCk261bKm4M/mw7AklTlFYIa0bIp9BgSm1S8Y= +golang.org/x/sys v0.20.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= golang.org/x/term v0.0.0-20210927222741-03fcf44c2211/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8= golang.org/x/term v0.5.0/go.mod h1:jMB1sMXY+tzblOD4FWmEbocvup2/aLOaQEp7JmGp78k= diff --git a/pkg/go-chi/middleware/logger/logger.go b/pkg/go-chi/middleware/logger/logger.go new file mode 100644 index 0000000..9007fbb --- /dev/null +++ b/pkg/go-chi/middleware/logger/logger.go @@ -0,0 +1,237 @@ +package logger + +import ( + "bytes" + "context" + "fmt" + "io" + "net/http" + "strings" + "time" + + "github.com/go-chi/chi/v5" + "github.com/go-chi/chi/v5/middleware" + "github.com/rs/zerolog" + + logger "github.com/VATUSA/primary-api/pkg/logging" +) + +func Logger(logger zerolog.Logger, skipPaths ...[]string) func(next http.Handler) http.Handler { + return chi.Chain( + middleware.RequestID, + Handler(logger, skipPaths...), + middleware.Recoverer, + ).Handler +} + +func NewLogger() zerolog.Logger { + return logger.ZL.With().Str("component", "access").Logger() +} + +func Handler(logger zerolog.Logger, optSkipPaths ...[]string) func(next http.Handler) http.Handler { + var f middleware.LogFormatter = &requestLogger{logger} + + skipPaths := map[string]struct{}{} + if len(optSkipPaths) > 0 { + for _, path := range optSkipPaths[0] { + skipPaths[path] = struct{}{} + } + } + + return func(next http.Handler) http.Handler { + fn := func(w http.ResponseWriter, r *http.Request) { + // Skip the logger if the path is in the skip list + if len(skipPaths) > 0 { + _, skip := skipPaths[r.URL.Path] + if skip { + next.ServeHTTP(w, r) + return + } + } + + // Log the 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, _ = io.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 := &RequestLoggerEntry{} + entry.Logger = l.Logger.With().Fields(requestLogFields(r)).Logger() + return entry +} + +type RequestLoggerEntry struct { + Logger zerolog.Logger + msg string +} + +func (l *RequestLoggerEntry) Write(status, bytes int, header http.Header, elapsed time.Duration, extra interface{}) { + responseLog := map[string]interface{}{ + "status": status, + "bytes": bytes, + "elapsed": elapsed.String(), // in milliseconds + "content-type": header.Get("Content-Type"), + "body": string(extra.([]byte)), + } + + l.Logger.WithLevel(statusLevel(status)).Fields(map[string]interface{}{ + "httpResponse": responseLog, + }).Msgf("") +} + +func (l *RequestLoggerEntry) Panic(v interface{}, stack []byte) { + stacktrace := "#" + + l.Logger = l.Logger.With(). + Str("stacktrace", stacktrace). + Str("panic", fmt.Sprintf("%+v", v)). + Logger() + + l.msg = fmt.Sprintf("%+v", v) + + middleware.PrintPrettyStack(v) +} + +func requestLogFields(r *http.Request) map[string]interface{} { + scheme := "http" + if r.TLS != nil { + scheme = "https" + } + requestURL := fmt.Sprintf("%s://%s%s", scheme, r.Host, r.RequestURI) + + requestFields := map[string]interface{}{ + "requestURL": requestURL, + "requestMethod": r.Method, + "requestPath": r.URL.Path, + "remoteIP": r.RemoteAddr, + "proto": r.Proto, + } + if reqID := middleware.GetReqID(r.Context()); reqID != "" { + requestFields["requestID"] = reqID + } + + requestFields["scheme"] = scheme + + if len(r.Header) > 0 { + requestFields["header"] = headerLogField(r.Header) + } + + return map[string]interface{}{ + "httpRequest": requestFields, + } +} + +func headerLogField(header http.Header) map[string]string { + headerField := map[string]string{} + for k, v := range header { + k = strings.ToLower(k) + switch { + case len(v) == 0: + continue + case len(v) == 1: + headerField[k] = v[0] + default: + headerField[k] = fmt.Sprintf("[%s]", strings.Join(v, "], [")) + } + if k == "authorization" || k == "cookie" || k == "set-cookie" { + headerField[k] = "***" + } + } + return headerField +} + +func statusLevel(status int) zerolog.Level { + switch { + case status <= 0: + return zerolog.WarnLevel + case status < 500: // for codes in 100-499 + return zerolog.InfoLevel + case status >= 500: + return zerolog.ErrorLevel + default: + return zerolog.InfoLevel + } +} + +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" + } +} + +func LogEntry(ctx context.Context) zerolog.Logger { + entry, ok := ctx.Value(middleware.LogEntryCtxKey).(*RequestLoggerEntry) + if !ok || entry == nil { + return zerolog.Nop() + } + return entry.Logger +} + +func LogEntrySetField(ctx context.Context, key, value string) { + if entry, ok := ctx.Value(middleware.LogEntryCtxKey).(*RequestLoggerEntry); ok { + entry.Logger = entry.Logger.With().Str(key, value).Logger() + } +} + +func LogEntrySetFields(ctx context.Context, fields map[string]interface{}) { + if entry, ok := ctx.Value(middleware.LogEntryCtxKey).(*RequestLoggerEntry); ok { + entry.Logger = entry.Logger.With().Fields(fields).Logger() + } +} + +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/go-chi/setup.go b/pkg/go-chi/setup.go index 03835a7..0699fc7 100644 --- a/pkg/go-chi/setup.go +++ b/pkg/go-chi/setup.go @@ -2,6 +2,8 @@ package go_chi import ( "github.com/VATUSA/primary-api/pkg/config" + "github.com/VATUSA/primary-api/pkg/go-chi/middleware/logger" + "github.com/VATUSA/primary-api/pkg/logging" "github.com/go-chi/chi/v5" "github.com/go-chi/chi/v5/middleware" "github.com/go-chi/cors" @@ -12,7 +14,7 @@ import ( func New(cfg *config.Config) *chi.Mux { r := chi.NewRouter() - r.Use(middleware.Logger) + r.Use(logger.Logger(logging.ZL.With().Str("component", "access").Logger())) r.Use(middleware.Recoverer) r.Use(middleware.RealIP) diff --git a/pkg/logging/log.go b/pkg/logging/log.go new file mode 100644 index 0000000..9c27729 --- /dev/null +++ b/pkg/logging/log.go @@ -0,0 +1,86 @@ +package logging + +import ( + "os" + "strings" + "time" + + "github.com/rs/zerolog" +) + +var ZL zerolog.Logger + +func New(logLevel string) { + var lvl zerolog.Level + switch strings.ToLower(logLevel) { + case "debug": + lvl = zerolog.DebugLevel + case "info": + lvl = zerolog.InfoLevel + case "warn": + lvl = zerolog.WarnLevel + case "error": + lvl = zerolog.ErrorLevel + case "fatal": + lvl = zerolog.FatalLevel + default: + lvl = zerolog.InfoLevel + } + + ZL = zerolog.New( + zerolog.ConsoleWriter{ + Out: os.Stdout, + TimeFormat: time.RFC3339, + }, + ). + Level(lvl). + With().Timestamp().Logger() +} + +func Debug(msg string) { + ZL.Debug().Msg(msg) +} + +func Debugf(format string, args ...interface{}) { + ZL.Debug().Msgf(format, args...) +} + +func Info(msg string) { + ZL.Info().Msg(msg) +} + +func Infof(format string, args ...interface{}) { + ZL.Info().Msgf(format, args...) +} + +func Warn(msg string) { + ZL.Warn().Msg(msg) +} + +func Warnf(format string, args ...interface{}) { + ZL.Warn().Msgf(format, args...) +} + +func Error(msg string) { + ZL.Error().Msg(msg) +} + +func Errorf(format string, args ...interface{}) { + ZL.Error().Msgf(format, args...) +} + +func ErrorWithErr(err error, msg string) { + ZL.Error().Err(err).Msg(msg) +} + +func ErrorWithErrf(err error, format string, args ...interface{}) { + ZL.Error().Err(err).Msgf(format, args...) +} + +func Fatal(msg string) { + ZL.Fatal().Msg(msg) +} + +func Fatalf(format string, args ...interface{}) { + ZL.Fatal().Msgf(format, args...) +}