From 9e8ff46ed14b127c6fa69010b69dfb9290700f4f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dawid=20Wysoki=C5=84ski?= Date: Fri, 16 Sep 2022 16:06:04 +0200 Subject: [PATCH] refactor --- logger_test.go | 236 +++++++++++++++++++++++++++++-------------------- 1 file changed, 141 insertions(+), 95 deletions(-) diff --git a/logger_test.go b/logger_test.go index ba96100..6e77447 100644 --- a/logger_test.go +++ b/logger_test.go @@ -3,117 +3,108 @@ 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() - t.Run("OK: status code=200", func(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, + }, + } - logger, obs := newLogger() + for _, tt := range tests { + tt := tt - router := chi.NewRouter() - router.Use(chizap.Logger(logger)) - router.Get("/info", func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) + 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 + } }) - - req, err := http.NewRequest("GET", "/info?test=true", nil) - assert.NoError(t, err) - router.ServeHTTP(httptest.NewRecorder(), req) - - entries := obs.TakeAll() - require.Len(t, entries, 1) - assert.Equal(t, "/info", entries[0].Message) - assert.Equal(t, zap.InfoLevel, entries[0].Level) - }) - - t.Run("OK: status code=400", func(t *testing.T) { - t.Parallel() - - logger, obs := newLogger() - - router := chi.NewRouter() - router.Use(chizap.Logger(logger)) - router.Get("/warn", func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusBadRequest) - }) - - req, err := http.NewRequest("GET", "/warn", nil) - assert.NoError(t, err) - router.ServeHTTP(httptest.NewRecorder(), req) - - entries := obs.TakeAll() - require.Len(t, entries, 1) - assert.Equal(t, "/warn", entries[0].Message) - assert.Equal(t, zap.WarnLevel, entries[0].Level) - }) - - t.Run("OK: status code=500", func(t *testing.T) { - t.Parallel() - - logger, obs := newLogger() - - router := chi.NewRouter() - router.Use(chizap.Logger(logger)) - router.Get("/error", func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusInternalServerError) - }) - - req, err := http.NewRequest("GET", "/error", nil) - assert.NoError(t, err) - router.ServeHTTP(httptest.NewRecorder(), req) - - entries := obs.TakeAll() - require.Len(t, entries, 1) - assert.Equal(t, "/error", entries[0].Message) - assert.Equal(t, zap.ErrorLevel, entries[0].Level) - }) - - t.Run("OK: path should be skipped", func(t *testing.T) { - t.Parallel() - - logger, obs := newLogger() - - router := chi.NewRouter() - router.Use(chizap.Logger( - logger, - chizap.WithFilter(func(r *http.Request) bool { - return r.URL.Path != "/anythingelse" - }), - chizap.WithFilter(func(r *http.Request) bool { - return r.URL.Path != "/error" - }), - )) - router.Get("/error", func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusInternalServerError) - }) - router.Get("/success", func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) - }) - - req1, err := http.NewRequest("GET", "/error", nil) - assert.NoError(t, err) - router.ServeHTTP(httptest.NewRecorder(), req1) - - req2, err := http.NewRequest("GET", "/success", nil) - assert.NoError(t, err) - router.ServeHTTP(httptest.NewRecorder(), req2) - - entries := obs.TakeAll() - require.Len(t, entries, 1) - assert.Equal(t, "/success", entries[0].Message) - assert.Equal(t, zap.InfoLevel, entries[0].Level) - }) + } } func newLogger() (*zap.Logger, *observer.ObservedLogs) { @@ -121,3 +112,58 @@ func newLogger() (*zap.Logger, *observer.ObservedLogs) { 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) +}