Open vknabel opened 7 months ago
During the migration away from zap to slog, we decided to skip migrating the middleware tests for now. The goal is to reintroduce them. Here is the old zap-variant:
During the migration away from zap to slog, we decided to skip migrating the middleware tests for now. The goal is to reintroduce them. Here is the old zap-variant:
Removed code in `bus/eventbus_test.go`.
```golang // bus/eventbus_test.go // ... func TestBridgeNsqLogToCoreLog(t *testing.T) { type Test struct { NsqMsg string Level zapcore.Level } tests := []Test{ { NsqMsg: "INF 123 [switch/fra-equ01-leaf01] querying nsqlookupd http://metal.test.metal-stack.io:4161/lookup?topic=switch {\"app\": \"metal-core\"} ", Level: zap.InfoLevel, }, { NsqMsg: "ERR 2 [switch/fra-equ01-leaf01] error querying nsqlookupd (http://metal.test.metal-stack.io:4161/lookup?topic=switch) - Get http://metal.test.metal-stack.io:4161/lookup?topic=switch: dial tcp: i/o timeout {\"app\": \"metal-core\"}", Level: zap.ErrorLevel, }, { NsqMsg: "WRN 1 [switch/fra-equ01-leaf01] error querying nsqlookupd (http://metal.test.metal-stack.io:4161/lookup?topic=switch) - Get http://metal.test.metal-stack.io:4161/lookup?topic=switch: dial tcp: i/o timeout {\"app\": \"metal-core\"}", Level: zap.WarnLevel, }, { NsqMsg: "DBG 1 [switch/fra-equ01-leaf01] error querying nsqlookupd (http://metal.test.metal-stack.io:4161/lookup?topic=switch) - Get http://metal.test.metal-stack.io:4161/lookup?topic=switch: dial tcp: i/o timeout {\"app\": \"metal-core\"}", Level: zap.DebugLevel, }, } for _, tst := range tests { tst := tst t.Run(tst.Level.String(), func(t *testing.T) { // record all messages of all levels core, recorded := observer.New(zapcore.DebugLevel) logger := zap.New(core) bridgeNsqLogToCoreLog(tst.NsqMsg, logger) if len(recorded.AllUntimed()) != 1 || recorded.AllUntimed()[0].Level != tst.Level { t.Errorf("expected one info level msg") } }) } } ```Removed code in `rest/middleware_test.go`.
```golang // rest/middleware_test.go package rest import ( "bufio" "bytes" "context" "encoding/json" "fmt" "io" "net/http" "net/http/httptest" "net/url" "strings" "testing" "time" "github.com/emicklei/go-restful/v3" "github.com/google/go-cmp/cmp" "github.com/google/go-cmp/cmp/cmpopts" "github.com/google/uuid" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.uber.org/zap" "go.uber.org/zap/zapcore" ) func TestRequestLoggerFilter(t *testing.T) { type logMessage struct { Level string `json:"level"` RequestID string `json:"rqid"` Message string `json:"msg"` RemoteAddr string `json:"remoteaddr"` Method string `json:"method"` URI string `json:"uri"` Route string `json:"route"` Status int `json:"status"` ContentLength int `json:"content-length"` Duration string `json:"duration"` Body string `json:"body"` Response string `json:"response"` } tests := []struct { name string level zapcore.Level handler func(req *restful.Request, resp *restful.Response) wantRequestLog *logMessage wantClosingLog *logMessage wantBody bool }{ { name: "info level", level: zapcore.InfoLevel, handler: func(req *restful.Request, resp *restful.Response) { requestLogger := GetLoggerFromContext(req.Request, nil) requestLogger.Infow("this is a test message") _ = resp.WriteHeaderAndEntity(http.StatusOK, nil) }, wantRequestLog: &logMessage{ Level: "info", Message: "this is a test message", RemoteAddr: "1.2.3.4", Method: "GET", URI: "/test", Route: "/test", }, wantClosingLog: &logMessage{ Level: "info", Message: "finished handling rest call", RemoteAddr: "1.2.3.4", Method: "GET", URI: "/test", Route: "/test", Status: http.StatusOK, }, }, { name: "debug level", level: zapcore.DebugLevel, handler: func(req *restful.Request, resp *restful.Response) { requestLogger := GetLoggerFromContext(req.Request, nil) requestLogger.Debugw("this is a test message") _ = resp.WriteHeaderAndEntity(http.StatusOK, "Test Response") }, wantRequestLog: &logMessage{ Level: "debug", Message: "this is a test message", RemoteAddr: "1.2.3.4", Method: "GET", URI: "/test", Route: "/test", }, wantClosingLog: &logMessage{ Level: "info", Message: "finished handling rest call", RemoteAddr: "1.2.3.4", Method: "GET", URI: "/test", Route: "/test", Status: http.StatusOK, ContentLength: 15, Response: `"Test Response"`, }, wantBody: true, }, } for i := range tests { tt := tests[i] t.Run(tt.name, func(t *testing.T) { testLogger := newZapTestLogger(t, tt.level) log := testLogger.GetLogger().Named("test-logger") sendRequestThroughFilterChain(t, tt.handler, RequestLoggerFilter(log)) lines := strings.Split(testLogger.GetLogs(), "\n") t.Log(lines) require.Len(t, lines, 2) var requestLog logMessage err := json.Unmarshal([]byte(lines[0]), &requestLog) require.NoError(t, err) assert.NotEmpty(t, requestLog.RequestID) _, err = uuid.Parse(requestLog.RequestID) require.NoError(t, err) if tt.wantBody { assert.NotEmpty(t, requestLog.Body) } if diff := cmp.Diff(&requestLog, tt.wantRequestLog, cmpopts.IgnoreFields(logMessage{}, "RequestID", "Body")); diff != "" { t.Errorf("diff in entry log: %s", diff) } var closingLog logMessage err = json.Unmarshal([]byte(lines[1]), &closingLog) require.NoError(t, err) assert.NotEmpty(t, closingLog.RequestID) _, err = uuid.Parse(closingLog.RequestID) require.NoError(t, err) d, err := time.ParseDuration(closingLog.Duration) require.NoError(t, err) assert.Greater(t, int64(d), int64(0)) if tt.wantBody { assert.NotEmpty(t, closingLog.Body) } if diff := cmp.Diff(&closingLog, tt.wantClosingLog, cmpopts.IgnoreFields(logMessage{}, "RequestID", "Duration", "Body")); diff != "" { t.Errorf("diff in closing log: %s", diff) } }) } } type ZapTestLogger struct { io.Writer b *bytes.Buffer bwriter *bufio.Writer logger *zap.SugaredLogger } func (z ZapTestLogger) Close() error { return nil } func (z ZapTestLogger) Sync() error { return nil } func (z *ZapTestLogger) GetLogs() string { z.bwriter.Flush() return strings.TrimSpace(z.b.String()) } func (z *ZapTestLogger) GetLogger() *zap.SugaredLogger { return z.logger } func newZapTestLogger(t *testing.T, level zapcore.Level) *ZapTestLogger { var b bytes.Buffer bWriter := bufio.NewWriter(&b) config := zap.NewProductionConfig() config.EncoderConfig.FunctionKey = "function" testLogger := ZapTestLogger{ Writer: bWriter, bwriter: bWriter, b: &b, } schemeName := strings.ReplaceAll(t.Name(), "/", "-") schemeName = strings.ReplaceAll(schemeName, "_", "-") err := zap.RegisterSink(schemeName, func(u *url.URL) (zap.Sink, error) { return testLogger, nil }) require.NoError(t, err) customPath := fmt.Sprintf("%s:whatever", schemeName) config.OutputPaths = []string{customPath} config.Level = zap.NewAtomicLevelAt(level) config.EncoderConfig.TimeKey = "timestamp" config.EncoderConfig.EncodeTime = zapcore.RFC3339TimeEncoder zapLogger, err := config.Build() require.NoError(t, err) testLogger.logger = zapLogger.Sugar() return &testLogger } func sendRequestThroughFilterChain(t *testing.T, handler func(req *restful.Request, resp *restful.Response), filters ...restful.FilterFunction) { ws := new(restful.WebService).Path("/").Consumes(restful.MIME_JSON).Produces(restful.MIME_JSON) c := restful.NewContainer() c.Add(ws.Route(ws.GET("test").To(handler))) for _, f := range filters { c.Filter(f) } httpRequest, err := http.NewRequestWithContext(context.TODO(), "GET", "http://localhost/test", nil) require.NoError(t, err) httpRequest.RemoteAddr = "1.2.3.4" httpRequest.Header.Set("Accept", "application/json") httpWriter := httptest.NewRecorder() c.Dispatch(httpWriter, httpRequest) require.Equal(t, http.StatusOK, httpWriter.Code) } ```