diff --git a/config.go b/config.go new file mode 100644 index 0000000..c97c05c --- /dev/null +++ b/config.go @@ -0,0 +1,58 @@ +package chizap + +import ( + "net/http" + "time" + + "go.uber.org/zap" +) + +type Filter func(r *http.Request) bool + +type AdditionalFieldExtractor func(r *http.Request) []zap.Field + +type config struct { + filters []Filter + timeFormat string + additionalFieldExtractors []AdditionalFieldExtractor +} + +type Option func(*config) + +func newConfig(opts ...Option) *config { + cfg := &config{ + timeFormat: time.RFC3339, + } + + for _, opt := range opts { + opt(cfg) + } + + return cfg +} + +// WithFilter adds a filter to the list of filters used by the middleware. +// If any filter indicates to exclude a request then the request will not be logged. +// All filters must allow a request to be logged. +// If no filters are provided, then all requests are logged. +func WithFilter(f Filter) Option { + return func(c *config) { + c.filters = append(c.filters, f) + } +} + +// WithTimeFormat specifies a time format to use for logging a request time. +// time.RFC3339 is used by default. +func WithTimeFormat(f string) Option { + return func(c *config) { + c.timeFormat = f + } +} + +// WithAdditionalFieldExtractor takes a function that will be called on every +// request and the returned fields will be added to a log entry. +func WithAdditionalFieldExtractor(extractor AdditionalFieldExtractor) Option { + return func(c *config) { + c.additionalFieldExtractors = append(c.additionalFieldExtractors, extractor) + } +} diff --git a/go.mod b/go.mod index e8d6f07..a38ec1e 100644 --- a/go.mod +++ b/go.mod @@ -1,13 +1,17 @@ -module github.com/Kichiyaki/chizap +module gitea.dwysokinski.me/Kichiyaki/chizap go 1.17 require ( github.com/go-chi/chi/v5 v5.0.7 + github.com/stretchr/testify v1.8.0 go.uber.org/zap v1.21.0 ) require ( + github.com/davecgh/go-spew v1.1.1 // indirect + github.com/pmezard/go-difflib v1.0.0 // indirect go.uber.org/atomic v1.9.0 // indirect go.uber.org/multierr v1.7.0 // indirect + gopkg.in/yaml.v3 v3.0.1 // indirect ) diff --git a/go.sum b/go.sum index 7d7bea5..dd6cc2d 100644 --- a/go.sum +++ b/go.sum @@ -3,44 +3,37 @@ github.com/benbjohnson/clock v1.1.0/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZx github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= 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/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/chi/v5 v5.0.7 h1:rDTPXLDHGATaeHvVlLcR4Qe0zftYethFucbjVQ1PxU8= github.com/go-chi/chi/v5 v5.0.7/go.mod h1:DslCQbL2OYiznFReuXYUmQ2hGd1aDpCnlMNITLSKoi8= +github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI= github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo= github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= +github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE= github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= github.com/pkg/errors v0.8.1 h1:iURUrRGxPUNPdy5/HRSm+Yj6okJ6UtLINN0Q9M4+h3I= github.com/pkg/errors v0.8.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/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= +github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw= github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= -github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= -github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY= github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= +github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= +github.com/stretchr/testify v1.8.0 h1:pSgiaMZlXftHpm5L7V1+rVB+AZJydKsMxsQBIJw4PKk= +github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU= github.com/yuin/goldmark v1.3.5/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k= go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc= go.uber.org/atomic v1.9.0 h1:ECmE8Bn/WFTYwEW/bpKD3M8VtR/zQVbavAoalC1PYyE= go.uber.org/atomic v1.9.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc= -go.uber.org/goleak v1.1.10 h1:z+mqJhf6ss6BSfSM671tgKyZBFPTTJM+HLxnhPC3wu0= -go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A= -go.uber.org/goleak v1.1.11-0.20210813005559-691160354723/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ= +go.uber.org/goleak v1.1.11 h1:wy28qYRKZgnJTxGxvye5/wgWr1EKjmUDGYox5mGlRlI= go.uber.org/goleak v1.1.11/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ= go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU= go.uber.org/multierr v1.7.0 h1:zaiO/rmgFjbmCXdSYJWQcdvOCsthmdaHfr3Gm2Kx4Ec= go.uber.org/multierr v1.7.0/go.mod h1:7EAYxJLBy9rStEaz58O2t4Uvip6FSURkq8/ppBp95ak= -go.uber.org/zap v1.19.0 h1:mZQZefskPPCMIBCSEH0v2/iUqqLrYtaeqwD6FUGUnFE= -go.uber.org/zap v1.19.0/go.mod h1:xg/QME4nWcxGxrpdeYfq7UvYrLh66cuVKdrbD1XF/NI= -go.uber.org/zap v1.19.1 h1:ue41HOKd1vGURxrmeKIgELGb3jPW9DMUDGtsinblHwI= -go.uber.org/zap v1.19.1/go.mod h1:j3DNczoxDZroyBnOT1L/Q79cfUMGZxlv/9dzN7SM1rI= -go.uber.org/zap v1.20.0 h1:N4oPlghZwYG55MlU6LXk/Zp00FVNE9X9wrYO8CEs4lc= -go.uber.org/zap v1.20.0/go.mod h1:wjWOCqI0f2ZZrJF/UufIOkiC8ii6tm1iqIsLo76RfJw= go.uber.org/zap v1.21.0 h1:WefMeulhovoZ2sYXz7st6K0sLj7bBhpiFaud4r4zST8= go.uber.org/zap v1.21.0/go.mod h1:wjWOCqI0f2ZZrJF/UufIOkiC8ii6tm1iqIsLo76RfJw= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI= -golang.org/x/lint v0.0.0-20190930215403-16217165b5de h1:5hukYrvBGR8/eNkX5mdUezrA6JiaEZDtJb9Ei+1LlBs= golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc= golang.org/x/mod v0.4.2/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= @@ -59,18 +52,17 @@ golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ= golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs= -golang.org/x/tools v0.0.0-20191108193012-7d206e10da11 h1:Yq9t9jnGoR+dBuitxdo9l6Q7xh/zOyNnYUtDKaQ3x0E= -golang.org/x/tools v0.0.0-20191108193012-7d206e10da11/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/tools v0.1.5/go.mod h1:o0xws9oXOQQZyjljx8fwUC0k7L1pTE6eaCbjGeHmOkk= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= +gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY= gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= -gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v2 v2.2.8 h1:obN1ZagJSUGI0Ek/LBmuj4SNLPfIny3KsKFopxRdj10= gopkg.in/yaml.v2 v2.2.8/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= -gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b h1:h8qDotaEPuJATrMmW04NCwg7v22aHH28wwpauUhK9Oo= gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= +gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= +gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= diff --git a/logger.go b/logger.go index c61df1c..7bb8acc 100644 --- a/logger.go +++ b/logger.go @@ -1,74 +1,63 @@ package chizap import ( - "fmt" - "github.com/go-chi/chi/v5/middleware" - "go.uber.org/zap" "net/http" "time" + + "github.com/go-chi/chi/v5/middleware" + "go.uber.org/zap" ) -const timeFormat = "02/Jan/2006:15:04:05 -0700" - -func Logger(logger *zap.Logger) func(next http.Handler) http.Handler { +// Logger returns a go-chi middleware that logs requests using go.uber.org/zap. +// +// Requests with status code >= 500 are logged using logger.Error. +// Requests with status code >= 400 are logged using logger.Warn. +// Other requests are logged using logger.Info. +func Logger(logger *zap.Logger, opts ...Option) func(next http.Handler) http.Handler { + cfg := newConfig(opts...) return func(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - path := r.URL.Path - if r.URL.RawQuery != "" { - path += "?" + r.URL.RawQuery + for _, f := range cfg.filters { + if !f(r) { + next.ServeHTTP(w, r) + return + } } - start := time.Now() + + path := r.URL.Path + query := r.URL.RawQuery ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor) + start := time.Now() next.ServeHTTP(ww, r) - stop := time.Since(start) + end := time.Now() statusCode := ww.Status() - clientUserAgent := r.UserAgent() - if clientUserAgent == "" { - clientUserAgent = "-" - } - referer := r.Referer() - if referer == "" { - referer = "-" - } - dataLength := ww.BytesWritten() - if dataLength < 0 { - dataLength = 0 - } fields := []zap.Field{ zap.Int("statusCode", statusCode), - zap.Int64("duration", stop.Nanoseconds()), - zap.String("durationPretty", stop.String()), - zap.String("clientIP", r.RemoteAddr), + zap.Duration("duration", end.Sub(start)), + zap.String("ip", r.RemoteAddr), zap.String("method", r.Method), + zap.String("query", query), zap.String("path", path), zap.String("proto", r.Proto), - zap.String("referer", referer), - zap.Int("dataLength", dataLength), - zap.String("usetAgent", clientUserAgent), + zap.String("referer", r.Referer()), + zap.Int("contentSize", ww.BytesWritten()), + zap.String("userAgent", r.UserAgent()), + zap.String("time", end.Format(cfg.timeFormat)), + } + + for _, fn := range cfg.additionalFieldExtractors { + fields = append(fields, fn(r)...) } - msg := fmt.Sprintf( - `%s - - [%s] "%s %s %s" %d %d "%s" "%s" %s`, - r.RemoteAddr, - time.Now().Format(timeFormat), - r.Method, - path, - r.Proto, - statusCode, - dataLength, - referer, - clientUserAgent, - stop.String(), - ) if statusCode >= http.StatusInternalServerError { - logger.Error(msg, fields...) + logger.Error(path, fields...) } else if statusCode >= http.StatusBadRequest { - logger.Warn(msg, fields...) + logger.Warn(path, fields...) } else { - logger.Info(msg, fields...) + logger.Info(path, fields...) } }) } diff --git a/logger_test.go b/logger_test.go new file mode 100644 index 0000000..6e77447 --- /dev/null +++ b/logger_test.go @@ -0,0 +1,169 @@ +package chizap_test + +import ( + "net/http" + "net/http/httptest" + "strings" + "testing" + "time" + + "gitea.dwysokinski.me/Kichiyaki/chizap" + "github.com/go-chi/chi/v5" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" +) + +func TestLogger(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + req *http.Request + excluded bool + expectedLevel zapcore.Level + expectedTimeFormat string + expectedAdditionalFields []zap.Field + }{ + { + name: "/info?test=true", + req: httptest.NewRequest(http.MethodGet, "/info?test=true", nil), + expectedLevel: zap.InfoLevel, + expectedTimeFormat: time.RFC3339, + }, + { + name: "/warn?test=true", + req: httptest.NewRequest(http.MethodGet, "/warn?test=true", nil), + expectedLevel: zap.WarnLevel, + expectedTimeFormat: time.RFC3339, + }, + { + name: "/error?test=true", + req: httptest.NewRequest(http.MethodGet, "/error?test=true", nil), + expectedLevel: zap.ErrorLevel, + expectedTimeFormat: time.RFC3339, + }, + { + name: "/excluded?test=true", + req: httptest.NewRequest(http.MethodGet, "/excluded?test=true", nil), + excluded: true, + }, + { + name: "/delete/123", + req: httptest.NewRequest(http.MethodDelete, "/delete/123", nil), + expectedLevel: zap.InfoLevel, + expectedTimeFormat: time.RFC3339, + expectedAdditionalFields: []zap.Field{ + zap.String("id", "123"), + }, + }, + { + name: "/custom-time-format", + req: httptest.NewRequest(http.MethodGet, "/custom-time-format", nil), + expectedLevel: zap.InfoLevel, + expectedTimeFormat: time.RFC1123Z, + }, + } + + for _, tt := range tests { + tt := tt + + t.Run(tt.name, func(t *testing.T) { + logger, obs := newLogger() + + rr := httptest.NewRecorder() + newRouter(logger).ServeHTTP(rr, tt.req) + + entries := obs.TakeAll() + + if tt.excluded { + require.Len(t, entries, 0) + return + } + + require.Len(t, entries, 1) + entry := entries[0] + assert.Equal(t, tt.req.URL.Path, entry.Message) + assert.Equal(t, tt.expectedLevel, entry.Level) + require.Len(t, entry.Context, 11+len(tt.expectedAdditionalFields)) + assert.Contains(t, entry.Context, zap.Int("statusCode", rr.Code)) + assert.Contains(t, entry.Context, zap.String("method", tt.req.Method)) + assert.Contains(t, entry.Context, zap.String("path", tt.req.URL.Path)) + assert.Contains(t, entry.Context, zap.String("query", tt.req.URL.RawQuery)) + for _, f := range tt.expectedAdditionalFields { + assert.Contains(t, entry.Context, f) + } + for _, f := range entry.Context { + if f.Key != "time" { + continue + } + + assertTime(t, tt.expectedTimeFormat, f.String) + break + } + }) + } +} + +func newLogger() (*zap.Logger, *observer.ObservedLogs) { + core, obs := observer.New(zap.NewAtomicLevelAt(zap.InfoLevel)) + logger := zap.New(core) + return logger, obs +} + +func newRouter(logger *zap.Logger) *chi.Mux { + router := chi.NewRouter() + + router.Route("/", func(r chi.Router) { + r.Use(chizap.Logger( + logger, + chizap.WithFilter(func(r *http.Request) bool { + return r.URL.Path != "/excluded" + }), + chizap.WithFilter(func(r *http.Request) bool { + return r.URL.Path != "/excluded2" + }), + chizap.WithAdditionalFieldExtractor(func(r *http.Request) []zap.Field { + if !strings.HasPrefix(r.URL.Path, "/delete") { + return nil + } + + return []zap.Field{ + zap.String("id", chi.URLParam(r, "id")), + } + }), + )) + r.Get("/info", func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + }) + r.Get("/warn", func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusBadRequest) + }) + r.Get("/error", func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusInternalServerError) + }) + r.Get("/excluded", func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + }) + r.Delete("/delete/{id}", func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + }) + }) + + router.With(chizap.Logger(logger, chizap.WithTimeFormat(time.RFC1123Z))). + Get("/custom-time-format", func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + }) + + return router +} + +func assertTime(tb testing.TB, format, timeStr string) { + tb.Helper() + + end, err := time.Parse(format, timeStr) + assert.NoError(tb, err) + assert.WithinDuration(tb, end, time.Now(), 1*time.Second) +} diff --git a/renovate.json b/renovate.json index f45d8f1..745a803 100644 --- a/renovate.json +++ b/renovate.json @@ -1,5 +1,10 @@ { "extends": [ - "config:base" + "config:base", + ":semanticCommits", + ":semanticCommitTypeAll(chore)" + ], + "postUpdateOptions": [ + "gomodTidy" ] }