From 37036059daa100e8f791db97fb93a7344840ca97 Mon Sep 17 00:00:00 2001 From: instabledesign Date: Sat, 22 Feb 2020 15:38:48 +0100 Subject: [PATCH] Update middleware/tripperware accordling to logger signature (#3) --- go.mod | 3 +- go.sum | 24 +++- middleware/correlation_id_test.go | 64 +++++---- middleware/logger.go | 8 +- middleware/logger_test.go | 171 ++++++++++++----------- tripperware/correlation_id_test.go | 68 +++++---- tripperware/logger.go | 10 +- tripperware/logger_test.go | 214 ++++++++++++++--------------- 8 files changed, 303 insertions(+), 259 deletions(-) diff --git a/go.mod b/go.mod index 6163d9b..7157f47 100644 --- a/go.mod +++ b/go.mod @@ -4,6 +4,7 @@ go 1.13 require ( github.com/gol4ng/httpware/v2 v2.1.1 - github.com/gol4ng/logger v0.3.0 + github.com/gol4ng/logger v0.5.3 + github.com/golang/mock v1.4.0 github.com/stretchr/testify v1.4.0 ) diff --git a/go.sum b/go.sum index 66b84c8..24ac772 100644 --- a/go.sum +++ b/go.sum @@ -13,12 +13,12 @@ github.com/go-kit/kit v0.8.0/go.mod h1:xBxKIO96dXMWWy0MnWVtmwkA9/13aqxPnvrjFYMA2 github.com/go-logfmt/logfmt v0.3.0/go.mod h1:Qt1PoO58o5twSAckw1HlFXLmHsOX5/0LbT9GBnD5lWE= github.com/go-stack/stack v1.8.0/go.mod h1:v0f6uXyyMGvRgIKkXu+yp6POWl0qKG85gN/melR3HDY= github.com/gogo/protobuf v1.1.1/go.mod h1:r8qH/GZQm5c6nD/R0oafs1akxWv10x8SbQlK7atdtwQ= -github.com/gol4ng/httpware/v2 v2.1.0 h1:eKtzvaoW/dw8YIAYTfhAvPDVmj0zDw8BkQSlLhjunUI= -github.com/gol4ng/httpware/v2 v2.1.0/go.mod h1:SIOrsksHg+ydQWikEj5KUVANB4lmwB8c5/NIBtdVzFM= github.com/gol4ng/httpware/v2 v2.1.1 h1:8xd4iN+6e/xjBSy8jjF2Vm8/PvxswJznu8GdaNu+vs8= github.com/gol4ng/httpware/v2 v2.1.1/go.mod h1:SIOrsksHg+ydQWikEj5KUVANB4lmwB8c5/NIBtdVzFM= -github.com/gol4ng/logger v0.3.0 h1:06RSztlRiQziN2uAcjAPfGhSisbcVcoDUpwg55QFq7I= -github.com/gol4ng/logger v0.3.0/go.mod h1:br5HY3VkhGzF83IhjDNE+PHkg2rV2Zy2uGPIfVfWZWg= +github.com/gol4ng/logger v0.5.3 h1:gX9fX5Ke1c9ldyIkbHBVux3EJ73FsPsmzWnXT8LEsTo= +github.com/gol4ng/logger v0.5.3/go.mod h1:RU2axpKm//DmUGqQNIhXmUBHKeLdtWarxu8bSV+5b4Y= +github.com/golang/mock v1.4.0 h1:Rd1kQnQu0Hq3qvJppYSG0HtP+f5LPPUiDswTLiEegLg= +github.com/golang/mock v1.4.0/go.mod h1:UOMv5ysSaYNkG+OFQykRIcU/QvvxJf3p21QfJ2Bt3cw= github.com/golang/protobuf v1.2.0/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U= github.com/golang/protobuf v1.3.1 h1:YF8+flBXS5eO826T4nzqPrxfhQThhXl0YzfuUPu4SBg= github.com/golang/protobuf v1.3.1/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U= @@ -28,6 +28,11 @@ github.com/json-iterator/go v1.1.6/go.mod h1:+SdeFBvtyEkXs7REEP0seUULqWtbJapLOCV github.com/julienschmidt/httprouter v1.2.0/go.mod h1:SYymIcj16QtmaHHD7aYtjjsJG7VTCxuUUipMqKk8s4w= github.com/konsorten/go-windows-terminal-sequences v1.0.1/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ= github.com/kr/logfmt v0.0.0-20140226030751-b84e30acd515/go.mod h1:+0opPa2QZZtGFBFZlji/RkVcI2GknAs/DXo4wKdlNEc= +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/matttproud/golang_protobuf_extensions v1.0.1 h1:4hp9jkHxhMHkqkrB3Ix0jegS5sx/RkqARlsWZ6pIwiU= github.com/matttproud/golang_protobuf_extensions v1.0.1/go.mod h1:D8He9yQNgCq6Z5Ld7szi9bcBfOoFv/3dc6xSMkL2PC0= github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd/go.mod h1:6dJC0mAP4ikYIbvyc7fijjWJddQyLn8Ig3JB5CqoB9Q= @@ -59,17 +64,28 @@ github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UV github.com/stretchr/testify v1.4.0 h1:2E4SXV/wtOkTonXsotYi4li6zVWxYlZuYNCXe9XRJyk= github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4= +golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/net v0.0.0-20181114220301-adae6a3d119a/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= +golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= golang.org/x/sync v0.0.0-20181108010431-42b317875d0f/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sync v0.0.0-20181221193216-37e7f081c4d4/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= +golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sys v0.0.0-20180905080454-ebe1bf3edb33/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/sys v0.0.0-20181116152217-5ac8a444bdc5 h1:mzjBh+S5frKOsOBobWIMAbXavqjmgO17k/2puhcFR94= golang.org/x/sys v0.0.0-20181116152217-5ac8a444bdc5/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= +golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= +golang.org/x/text v0.0.0-20170915032832-14c0d48ead0c/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= +golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= +golang.org/x/tools v0.0.0-20190425150028-36563e24a262/go.mod h1:RgjU9mgBXZiqYHBnxXauZ1Gv1EHHAz9KjViQ78xBX0Q= gopkg.in/alecthomas/kingpin.v2 v2.2.6/go.mod h1:FMv+mEhP44yOT+4EoQTLFTRgOQ1FBLkstjWtayDeSgw= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM= 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.1/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v2 v2.2.2 h1:ZCJp+EgiOT7lHqUV2J862kp8Qj64Jo6az82+3Td9dZw= gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gotest.tools v2.2.0+incompatible h1:VsBPFP1AI068pPrMxtb/S8Zkgf9xEmTLJjfM+P5UIEo= gotest.tools v2.2.0+incompatible/go.mod h1:DsYFclhRJ6vuDpmuTbkuFWG+y2sxOXAzmJt81HFBacw= +rsc.io/quote/v3 v3.1.0/go.mod h1:yEA65RcK8LyAZtP9Kv3t0HmxON59tX3rD+tICJqUlj0= +rsc.io/sampler v1.3.0/go.mod h1:T1hPZKmBbMNahiBKFy5HrXp6adAjACjK9JXDnKaTXpA= diff --git a/middleware/correlation_id_test.go b/middleware/correlation_id_test.go index abb9138..50f22bb 100644 --- a/middleware/correlation_id_test.go +++ b/middleware/correlation_id_test.go @@ -16,6 +16,7 @@ import ( "github.com/gol4ng/logger" "github.com/gol4ng/logger/formatter" "github.com/gol4ng/logger/handler" + testing_logger "github.com/gol4ng/logger/testing" "github.com/stretchr/testify/assert" http_middleware "github.com/gol4ng/logger-http/middleware" @@ -26,10 +27,7 @@ func TestCorrelationId(t *testing.T) { rand.New(correlation_id.NewLockedSource(rand.NewSource(1))), ) - loggerOutput := &Output{} - myLogger := logger.NewLogger( - handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), - ) + myLogger, store := testing_logger.NewLogger() request := httptest.NewRequest(http.MethodGet, "http://fake-addr", nil) request = request.WithContext(logger.InjectInContext(request.Context(), myLogger)) @@ -41,12 +39,12 @@ func TestCorrelationId(t *testing.T) { assert.NotEqual(t, request, innerRequest) assert.Equal(t, "p1LGIehp1s", innerRequest.Header.Get(correlation_id.HeaderName)) handlerRequest = innerRequest - logger.FromContext(innerRequest.Context(), nil).Info("handler info log", nil) + logger.FromContext(innerRequest.Context(), nil).Info("handler info log") }) - myLogger.Info("info log before request", logger.NewContext().Add("ctxvalue", "before")) + myLogger.Info("info log before request", logger.String("ctxvalue", "before")) http_middleware.CorrelationId()(h).ServeHTTP(responseWriter, request) - myLogger.Info("info log after request", logger.NewContext().Add("ctxvalue", "after")) + myLogger.Info("info log after request", logger.String("ctxvalue", "after")) respHeaderValue := responseWriter.Header().Get(correlation_id.HeaderName) reqContextValue := handlerRequest.Context().Value(correlation_id.HeaderName).(string) @@ -54,11 +52,24 @@ func TestCorrelationId(t *testing.T) { assert.True(t, len(respHeaderValue) == 10) assert.True(t, len(reqContextValue) == 10) assert.True(t, respHeaderValue == reqContextValue) - loggerOutput.Constains(t, []string{ - ` info log before request {"ctxvalue":"before"}`, - ` handler info log {"Correlation-Id":"p1LGIehp1s"}`, - ` info log after request {"ctxvalue":"after"}`, - }) + + entries := store.GetEntries() + assert.Len(t, entries, 3) + + entry1 := entries[0] + assert.Equal(t, logger.InfoLevel, entry1.Level) + assert.Equal(t, "info log before request", entry1.Message) + assert.Equal(t, "before", (*entry1.Context)["ctxvalue"].Value) + + entry2 := entries[1] + assert.Equal(t, logger.InfoLevel, entry2.Level) + assert.Equal(t, "handler info log", entry2.Message) + assert.Equal(t, "p1LGIehp1s", (*entry2.Context)["Correlation-Id"].Value) + + entry3 := entries[2] + assert.Equal(t, logger.InfoLevel, entry3.Level) + assert.Equal(t, "info log after request", entry3.Message) + assert.Equal(t, "after", (*entry3.Context)["ctxvalue"].Value) } func TestCorrelationId_WithoutWrappableLogger(t *testing.T) { @@ -66,10 +77,7 @@ func TestCorrelationId_WithoutWrappableLogger(t *testing.T) { rand.New(correlation_id.NewLockedSource(rand.NewSource(1))), ) - loggerOutput := &Output{} - myLogger := logger.NewLogger( - handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), - ) + myLogger, store := testing_logger.NewLogger() request := httptest.NewRequest(http.MethodGet, "http://fake-addr", nil) // WE DO NOT INJECT LOGGER IN REQUEST CONTEXT @@ -85,11 +93,11 @@ func TestCorrelationId_WithoutWrappableLogger(t *testing.T) { assert.Nil(t, logger.FromContext(innerRequest.Context(), nil)) }) - myLogger.Info("info log before request", logger.NewContext().Add("ctxvalue", "before")) + myLogger.Info("info log before request", logger.String("ctxvalue", "before")) output := getStdout(func() { http_middleware.CorrelationId()(h).ServeHTTP(responseRecorder, request) }) - myLogger.Info("info log after request", logger.NewContext().Add("ctxvalue", "after")) + myLogger.Info("info log after request", logger.String("ctxvalue", "after")) respHeaderValue := responseRecorder.Header().Get(correlation_id.HeaderName) reqContextValue := handlerRequest.Context().Value(correlation_id.HeaderName).(string) @@ -100,10 +108,18 @@ func TestCorrelationId_WithoutWrappableLogger(t *testing.T) { assert.Contains(t, output, "correlationId need a wrappable logger /") assert.Contains(t, output, "/src/github.com/gol4ng/logger-http/middleware/correlation_id_test.go:") - loggerOutput.Constains(t, []string{ - ` info log before request {"ctxvalue":"before"}`, - ` info log after request {"ctxvalue":"after"}`, - }) + entries := store.GetEntries() + assert.Len(t, entries, 2) + + entry1 := entries[0] + assert.Equal(t, logger.InfoLevel, entry1.Level) + assert.Equal(t, "info log before request", entry1.Message) + assert.Equal(t, "before", (*entry1.Context)["ctxvalue"].Value) + + entry2 := entries[1] + assert.Equal(t, logger.InfoLevel, entry2.Level) + assert.Equal(t, "info log after request", entry2.Message) + assert.Equal(t, "after", (*entry2.Context)["ctxvalue"].Value) } // Use to get os.Stdout @@ -147,7 +163,7 @@ func ExampleCorrelationId() { port := ":5001" myLogger := logger.NewLogger( - handler.Stream(os.Stdout, formatter.NewDefaultFormatter()), + handler.Stream(os.Stdout, formatter.NewDefaultFormatter(formatter.WithContext(true))), ) // we recommend to use MiddlewareStack to simplify managing all wanted middlewares @@ -164,7 +180,7 @@ func ExampleCorrelationId() { h := http.HandlerFunc(func(writer http.ResponseWriter, innerRequest *http.Request) { l := logger.FromContext(innerRequest.Context(), myLogger) - l.Info("handler log info", nil) + l.Info("handler log info") }) go func() { diff --git a/middleware/logger.go b/middleware/logger.go index 61b3d13..14d41ea 100644 --- a/middleware/logger.go +++ b/middleware/logger.go @@ -30,7 +30,7 @@ func Logger(log logger.LoggerInterface, opts ...logger_http.Option) httpware.Mid if err := recover(); err != nil { currentLoggerContext.Add("http_panic", err) - _ = currentLogger.Critical(fmt.Sprintf("http server panic %s %s [duration:%s]", req.Method, req.URL, duration), currentLoggerContext) + currentLogger.Critical(fmt.Sprintf("http server panic %s %s [duration:%s]", req.Method, req.URL, duration), *currentLoggerContext.Slice()...) panic(err) } @@ -38,17 +38,17 @@ func Logger(log logger.LoggerInterface, opts ...logger_http.Option) httpware.Mid Add("http_status_code", writerInterceptor.StatusCode). Add("http_response_length", len(writerInterceptor.Body)) - _ = currentLogger.Log( + currentLogger.Log( fmt.Sprintf( "http server %s %s [status_code:%d, duration:%s, content_length:%d]", req.Method, req.URL, writerInterceptor.StatusCode, duration, len(writerInterceptor.Body), ), o.LevelFunc(writerInterceptor.StatusCode), - currentLoggerContext, + *currentLoggerContext.Slice()..., ) }() - _ = currentLogger.Debug(fmt.Sprintf("http server received %s %s", req.Method, req.URL), currentLoggerContext) + currentLogger.Debug(fmt.Sprintf("http server received %s %s", req.Method, req.URL), *currentLoggerContext.Slice()...) next.ServeHTTP(writerInterceptor, req) }) } diff --git a/middleware/logger_test.go b/middleware/logger_test.go index e4f27d2..3ad5343 100644 --- a/middleware/logger_test.go +++ b/middleware/logger_test.go @@ -1,18 +1,14 @@ package middleware_test import ( - "bytes" "context" - "fmt" "net/http" "net/http/httptest" - "strings" "testing" "time" "github.com/gol4ng/logger" - "github.com/gol4ng/logger/formatter" - "github.com/gol4ng/logger/handler" + testing_logger "github.com/gol4ng/logger/testing" "github.com/stretchr/testify/assert" "github.com/gol4ng/logger-http" @@ -31,26 +27,29 @@ func TestLogger(t *testing.T) { writer.Write([]byte(`OK`)) }) - loggerOutput := &Output{} - myLogger := logger.NewLogger( - handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), - ) + myLogger, store := testing_logger.NewLogger() middleware.Logger(myLogger)(h).ServeHTTP(responseWriter, request) - loggerOutput.Constains(t, []string{ - ` http server GET http://127.0.0.1/my-fake-url [status_code:200, duration:`, - `content_length:2] {`, - `"http_kind":"server"`, - `"http_method":"GET"`, - `"http_response_length":2`, - `"http_status":"OK"`, - `"http_status_code":200`, - - `"http_url":"http://127.0.0.1`, - `"http_duration":`, - `"http_start_time":"`, - `"http_request_deadline":"`, - }) + + entries := store.GetEntries() + assert.Len(t, entries, 2) + + entry1 := entries[0] + AssertDefaultContextFields(t, entry1) + assert.Equal(t, logger.DebugLevel, entry1.Level) + assert.Equal(t, `http server received GET http://127.0.0.1/my-fake-url`, entry1.Message) + assert.Equal(t, "GET", (*entry1.Context)["http_method"].Value) + + entry2 := entries[1] + AssertDefaultContextFields(t, entry2) + assert.Equal(t, logger.InfoLevel, entry2.Level) + assert.Contains(t, entry2.Message, `http server GET http://127.0.0.1/my-fake-url [status_code:200, duration:`) + assert.Contains(t, entry2.Message, `content_length:2]`) + assert.Equal(t, "http://127.0.0.1/my-fake-url", (*entry2.Context)["http_url"].Value) + assert.Equal(t, int64(2), (*entry2.Context)["http_response_length"].Value) + assert.Equal(t, "OK", (*entry2.Context)["http_status"].Value) + assert.Equal(t, int64(200), (*entry2.Context)["http_status_code"].Value) + assert.Contains(t, *entry2.Context, "http_duration") } func TestLogger_WithPanic(t *testing.T) { @@ -63,25 +62,29 @@ func TestLogger_WithPanic(t *testing.T) { panic("my handler panic") }) - output := &Output{} - myLogger := logger.NewLogger( - handler.Stream(output, formatter.NewDefaultFormatter()), - ) + myLogger, store := testing_logger.NewLogger() assert.PanicsWithValue(t, "my handler panic", func() { middleware.Logger(myLogger)(h).ServeHTTP(responseWriter, req) }) - output.Constains(t, []string{ - ` http server panic GET http://127.0.0.1/my-fake-url [duration:`, - `"http_kind":"server"`, - `"http_method":"GET"`, + entries := store.GetEntries() + assert.Len(t, entries, 2) - `"http_url":"http://127.0.0.1`, - `"http_duration":`, - `"http_start_time":"`, - `"http_request_deadline":"`, - }) + entry1 := entries[0] + AssertDefaultContextFields(t, entry1) + assert.Equal(t, logger.DebugLevel, entry1.Level) + assert.Equal(t, `http server received GET http://127.0.0.1/my-fake-url`, entry1.Message) + assert.Equal(t, "GET", (*entry1.Context)["http_method"].Value) + + entry2 := entries[1] + AssertDefaultContextFields(t, entry2) + assert.Equal(t, logger.CriticalLevel, entry2.Level) + assert.Contains(t, entry2.Message, `http server panic GET http://127.0.0.1/my-fake-url [duration:`) + assert.Equal(t, "GET", (*entry2.Context)["http_method"].Value) + assert.Equal(t, "http://127.0.0.1/my-fake-url", (*entry2.Context)["http_url"].Value) + + assert.Contains(t, *entry2.Context, `http_panic`) } func TestLogger_WithContext(t *testing.T) { @@ -96,30 +99,33 @@ func TestLogger_WithContext(t *testing.T) { writer.Write([]byte(`OK`)) }) - loggerOutput := &Output{} - myLogger := logger.NewLogger( - handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), - ) + myLogger, store := testing_logger.NewLogger() middleware.Logger(myLogger, logger_http.WithLoggerContext(func(request *http.Request) *logger.Context { return logger.NewContext().Add("base_context_key", "base_context_value") }))(h).ServeHTTP(responseWriter, request) - loggerOutput.Constains(t, []string{ - ` http server GET http://127.0.0.1/my-fake-url [status_code:200, duration:`, - `content_length:2] {`, - `"http_kind":"server"`, - `"http_method":"GET"`, - `"http_response_length":2`, - `"http_status":"OK"`, - `"http_status_code":200`, - `"base_context_key":"base_context_value"`, - - `"http_url":"http://127.0.0.1`, - `"http_duration":`, - `"http_start_time":"`, - `"http_request_deadline":"`, - }) + entries := store.GetEntries() + assert.Len(t, entries, 2) + + entry1 := entries[0] + assert.Equal(t, "base_context_value", (*entry1.Context)["base_context_key"].Value) + AssertDefaultContextFields(t, entry1) + assert.Equal(t, logger.DebugLevel, entry1.Level) + assert.Equal(t, `http server received GET http://127.0.0.1/my-fake-url`, entry1.Message) + assert.Equal(t, "GET", (*entry1.Context)["http_method"].Value) + + entry2 := entries[1] + assert.Equal(t, "base_context_value", (*entry2.Context)["base_context_key"].Value) + AssertDefaultContextFields(t, entry2) + assert.Equal(t, logger.InfoLevel, entry2.Level) + assert.Contains(t, entry2.Message, `http server GET http://127.0.0.1/my-fake-url [status_code:200, duration:`) + assert.Contains(t, entry2.Message, `content_length:2]`) + assert.Equal(t, "http://127.0.0.1/my-fake-url", (*entry2.Context)["http_url"].Value) + assert.Equal(t, int64(2), (*entry2.Context)["http_response_length"].Value) + assert.Equal(t, "OK", (*entry2.Context)["http_status"].Value) + assert.Equal(t, int64(200), (*entry2.Context)["http_status_code"].Value) + assert.Contains(t, *entry2.Context, "http_duration") } func TestLogger_WithLevels(t *testing.T) { @@ -134,40 +140,37 @@ func TestLogger_WithLevels(t *testing.T) { writer.Write([]byte(`OK`)) }) - loggerOutput := &Output{} - myLogger := logger.NewLogger( - handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), - ) + myLogger, store := testing_logger.NewLogger() middleware.Logger(myLogger, logger_http.WithLevels(func(statusCode int) logger.Level { return logger.EmergencyLevel }))(h).ServeHTTP(responseWriter, request) - loggerOutput.Constains(t, []string{ - ` http server GET http://127.0.0.1/my-fake-url [status_code:200, duration:`, - `content_length:2] {`, - `"http_kind":"server"`, - `"http_method":"GET"`, - `"http_response_length":2`, - `"http_status":"OK"`, - `"http_status_code":200`, - - `"http_url":"http://127.0.0.1`, - `"http_duration":`, - `"http_start_time":"`, - `"http_request_deadline":"`, - }) -} - -type Output struct { - bytes.Buffer + entries := store.GetEntries() + assert.Len(t, entries, 2) + + entry1 := entries[0] + AssertDefaultContextFields(t, entry1) + assert.Equal(t, logger.DebugLevel, entry1.Level) + assert.Equal(t, `http server received GET http://127.0.0.1/my-fake-url`, entry1.Message) + assert.Equal(t, "GET", (*entry1.Context)["http_method"].Value) + + entry2 := entries[1] + AssertDefaultContextFields(t, entry2) + assert.Equal(t, logger.EmergencyLevel, entry2.Level) + assert.Contains(t, entry2.Message, `http server GET http://127.0.0.1/my-fake-url [status_code:200, duration:`) + assert.Contains(t, entry2.Message, `content_length:2]`) + assert.Equal(t, "http://127.0.0.1/my-fake-url", (*entry2.Context)["http_url"].Value) + assert.Equal(t, int64(2), (*entry2.Context)["http_response_length"].Value) + assert.Equal(t, "OK", (*entry2.Context)["http_status"].Value) + assert.Equal(t, int64(200), (*entry2.Context)["http_status_code"].Value) + assert.Contains(t, *entry2.Context, "http_duration") } -func (o *Output) Constains(t *testing.T, str []string) { - b := o.String() - for _, s := range str { - if strings.Contains(b, s) != true { - assert.Fail(t, fmt.Sprintf("buffer %s must contain %s\n", b, s)) - } - } +func AssertDefaultContextFields(t *testing.T, entry logger.Entry) { + assert.Equal(t, "server", (*entry.Context)["http_kind"].Value) + assert.Contains(t, *entry.Context, "http_method") + assert.Contains(t, *entry.Context, "http_url") + assert.Contains(t, *entry.Context, "http_start_time") + assert.Contains(t, *entry.Context, "http_request_deadline") } diff --git a/tripperware/correlation_id_test.go b/tripperware/correlation_id_test.go index ec425e5..3e6644a 100644 --- a/tripperware/correlation_id_test.go +++ b/tripperware/correlation_id_test.go @@ -13,8 +13,7 @@ import ( "github.com/gol4ng/httpware/v2" "github.com/gol4ng/httpware/v2/correlation_id" "github.com/gol4ng/logger" - "github.com/gol4ng/logger/formatter" - "github.com/gol4ng/logger/handler" + testing_logger "github.com/gol4ng/logger/testing" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" @@ -27,10 +26,7 @@ func TestCorrelationId(t *testing.T) { rand.New(correlation_id.NewLockedSource(rand.NewSource(1))), ) - loggerOutput := &Output{} - myLogger := logger.NewLogger( - handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), - ) + myLogger, store := testing_logger.NewLogger() roundTripperMock := &mocks.RoundTripper{} request := httptest.NewRequest(http.MethodPost, "http://fake-addr", nil) @@ -47,22 +43,35 @@ func TestCorrelationId(t *testing.T) { assert.NotEqual(t, request, innerRequest) assert.Equal(t, "p1LGIehp1s", innerRequest.Header.Get(correlation_id.HeaderName)) handlerReq = innerRequest - logger.FromContext(innerRequest.Context(), nil).Info("handler info log", nil) + logger.FromContext(innerRequest.Context(), nil).Info("handler info log") }) - myLogger.Info("info log before request", logger.NewContext().Add("ctxvalue", "before")) + myLogger.Info("info log before request", logger.String("ctxvalue", "before")) resultResponse, err := tripperware.CorrelationId()(roundTripperMock).RoundTrip(request) - myLogger.Info("info log after request", logger.NewContext().Add("ctxvalue", "after")) + myLogger.Info("info log after request", logger.String("ctxvalue", "after")) assert.Nil(t, err) assert.Equal(t, response, resultResponse) assert.Equal(t, "p1LGIehp1s", handlerReq.Header.Get(correlation_id.HeaderName)) assert.Equal(t, "", response.Header.Get(correlation_id.HeaderName)) - loggerOutput.Constains(t, []string{ - ` info log before request {"ctxvalue":"before"}`, - ` handler info log {"Correlation-Id":"p1LGIehp1s"}`, - ` info log after request {"ctxvalue":"after"}`, - }) + + entries := store.GetEntries() + assert.Len(t, entries, 3) + + entry1 := entries[0] + assert.Equal(t, logger.InfoLevel, entry1.Level) + assert.Equal(t, "info log before request", entry1.Message) + assert.Equal(t, "before", (*entry1.Context)["ctxvalue"].Value) + + entry2 := entries[1] + assert.Equal(t, logger.InfoLevel, entry2.Level) + assert.Equal(t, "handler info log", entry2.Message) + assert.Equal(t, "p1LGIehp1s", (*entry2.Context)["Correlation-Id"].Value) + + entry3 := entries[2] + assert.Equal(t, logger.InfoLevel, entry3.Level) + assert.Equal(t, "info log after request", entry3.Message) + assert.Equal(t, "after", (*entry3.Context)["ctxvalue"].Value) } func TestCorrelationId_WithoutWrappableLogger(t *testing.T) { @@ -70,10 +79,7 @@ func TestCorrelationId_WithoutWrappableLogger(t *testing.T) { rand.New(correlation_id.NewLockedSource(rand.NewSource(1))), ) - loggerOutput := &Output{} - myLogger := logger.NewLogger( - handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), - ) + myLogger, store := testing_logger.NewLogger() roundTripperMock := &mocks.RoundTripper{} request := httptest.NewRequest(http.MethodPost, "http://fake-addr", nil) @@ -96,11 +102,11 @@ func TestCorrelationId_WithoutWrappableLogger(t *testing.T) { var resultResponse *http.Response var err error - myLogger.Info("info log before request", logger.NewContext().Add("ctxvalue", "before")) + myLogger.Info("info log before request", logger.String("ctxvalue", "before")) output := getStdout(func() { resultResponse, err = tripperware.CorrelationId()(roundTripperMock).RoundTrip(request) }) - myLogger.Info("info log after request", logger.NewContext().Add("ctxvalue", "after")) + myLogger.Info("info log after request", logger.String("ctxvalue", "after")) assert.Nil(t, err) assert.Equal(t, response, resultResponse) @@ -109,10 +115,18 @@ func TestCorrelationId_WithoutWrappableLogger(t *testing.T) { assert.Contains(t, output, "correlationId need a wrappable logger /") assert.Contains(t, output, "/src/github.com/gol4ng/logger-http/tripperware/correlation_id_test.go") - loggerOutput.Constains(t, []string{ - ` info log before request {"ctxvalue":"before"}`, - ` info log after request {"ctxvalue":"after"}`, - }) + entries := store.GetEntries() + assert.Len(t, entries, 2) + + entry1 := entries[0] + assert.Equal(t, logger.InfoLevel, entry1.Level) + assert.Equal(t, "info log before request", entry1.Message) + assert.Equal(t, "before", (*entry1.Context)["ctxvalue"].Value) + + entry2 := entries[1] + assert.Equal(t, logger.InfoLevel, entry2.Level) + assert.Equal(t, "info log after request", entry2.Message) + assert.Equal(t, "after", (*entry2.Context)["ctxvalue"].Value) } // Use to get os.Stdout @@ -153,11 +167,7 @@ func getStdout(f func()) string { // ===================================================================================================================== func ExampleCorrelationId() { - // we use output buffer because some data was dynamic and go test cannot assert them - loggerOutput := &Output{} - myLogger := logger.NewLogger( - handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), - ) + myLogger := logger.NewNopLogger() clientStack := httpware.TripperwareStack( tripperware.InjectLogger(myLogger), diff --git a/tripperware/logger.go b/tripperware/logger.go index 046f3eb..aa8ae2e 100644 --- a/tripperware/logger.go +++ b/tripperware/logger.go @@ -28,7 +28,7 @@ func Logger(log logger.LoggerInterface, opts ...logger_http.Option) func(next ht if err := recover(); err != nil { currentLoggerContext.Add("http_panic", err) - _ = currentLogger.Critical(fmt.Sprintf("http client panic %s %s [duration:%s]", req.Method, req.URL, duration), currentLoggerContext) + currentLogger.Critical(fmt.Sprintf("http client panic %s %s [duration:%s]", req.Method, req.URL, duration), *currentLoggerContext.Slice()...) panic(err) } if err != nil { @@ -36,24 +36,24 @@ func Logger(log logger.LoggerInterface, opts ...logger_http.Option) func(next ht currentLoggerContext.Add("http_error_message", err.Error()) } if resp == nil { - _ = currentLogger.Error(fmt.Sprintf("http client error %s %s [duration:%s] %s", req.Method, req.URL, duration, err), currentLoggerContext) + currentLogger.Error(fmt.Sprintf("http client error %s %s [duration:%s] %s", req.Method, req.URL, duration, err), *currentLoggerContext.Slice()...) return } currentLoggerContext.Add("http_status", resp.Status). Add("http_status_code", resp.StatusCode). Add("http_response_length", resp.ContentLength) - _ = currentLogger.Log( + currentLogger.Log( fmt.Sprintf( "http client %s %s [status_code:%d, duration:%s, content_length:%d]", req.Method, req.URL, resp.StatusCode, duration, resp.ContentLength, ), o.LevelFunc(resp.StatusCode), - currentLoggerContext, + *currentLoggerContext.Slice()..., ) }() - _ = currentLogger.Debug(fmt.Sprintf("http client gonna %s %s", req.Method, req.URL), currentLoggerContext) + currentLogger.Debug(fmt.Sprintf("http client gonna %s %s", req.Method, req.URL), *currentLoggerContext.Slice()...) return next.RoundTrip(req) }) } diff --git a/tripperware/logger_test.go b/tripperware/logger_test.go index 20c6273..98e9a9d 100644 --- a/tripperware/logger_test.go +++ b/tripperware/logger_test.go @@ -1,20 +1,16 @@ package tripperware_test import ( - "bytes" "context" - "fmt" "net/http" "net/http/httptest" - "strings" "testing" "time" - "github.com/stretchr/testify/assert" "github.com/gol4ng/httpware/v2" "github.com/gol4ng/logger" - "github.com/gol4ng/logger/formatter" - "github.com/gol4ng/logger/handler" + testing_logger "github.com/gol4ng/logger/testing" + "github.com/stretchr/testify/assert" "github.com/gol4ng/logger-http" "github.com/gol4ng/logger-http/tripperware" @@ -27,10 +23,7 @@ func TestTripperware(t *testing.T) { })) defer server.Close() - loggerOutput := &Output{} - myLogger := logger.NewLogger( - handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), - ) + myLogger, store := testing_logger.NewLogger() c := http.Client{ Transport: tripperware.Logger(myLogger)(http.DefaultTransport), @@ -42,21 +35,26 @@ func TestTripperware(t *testing.T) { _, err := c.Do(request) assert.Nil(t, err) - loggerOutput.Constains(t, []string{ - ` http client GET http://127.0.0.1`, - `/my-fake-url [status_code:200, duration:`, - `content_length:2] {`, - `"http_kind":"client"`, - `"http_method":"GET"`, - `"http_response_length":2`, - `"http_status":"200 OK"`, - `"http_status_code":200`, - - `"http_url":"http://127.0.0.1`, - `"http_duration":`, - `"http_start_time":"`, - `"http_request_deadline":"`, - }) + + entries := store.GetEntries() + assert.Len(t, entries, 2) + + entry1 := entries[0] + AssertDefaultContextFields(t, entry1) + assert.Equal(t, logger.DebugLevel, entry1.Level) + assert.Equal(t, `http client gonna GET `+server.URL+`/my-fake-url`, entry1.Message) + assert.Equal(t, "GET", (*entry1.Context)["http_method"].Value) + + entry2 := entries[1] + AssertDefaultContextFields(t, entry2) + assert.Equal(t, logger.InfoLevel, entry2.Level) + assert.Contains(t, entry2.Message, `http client GET `+server.URL+`/my-fake-url [status_code:200, duration:`) + assert.Contains(t, entry2.Message, `content_length:2]`) + assert.Equal(t, server.URL+"/my-fake-url", (*entry2.Context)["http_url"].Value) + assert.Equal(t, int64(2), (*entry2.Context)["http_response_length"].Value) + assert.Equal(t, "200 OK", (*entry2.Context)["http_status"].Value) + assert.Equal(t, int64(200), (*entry2.Context)["http_status_code"].Value) + assert.Contains(t, *entry2.Context, "http_duration") } func TestTripperware_WithError(t *testing.T) { @@ -65,10 +63,7 @@ func TestTripperware_WithError(t *testing.T) { })) defer server.Close() - loggerOutput := &Output{} - myLogger := logger.NewLogger( - handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), - ) + myLogger, store := testing_logger.NewLogger() c := http.Client{ Transport: tripperware.Logger(myLogger)(http.DefaultTransport), @@ -80,21 +75,23 @@ func TestTripperware_WithError(t *testing.T) { _, err := c.Do(request) assert.Contains(t, err.Error(), "no such host") - loggerOutput.Constains(t, []string{ - ` http client error GET http://a.zz/my-fake-url [duration:`, - `dial tcp: lookup a.zz`, - `no such host`, - `"http_kind":"client"`, - `"http_method":"GET"`, - `"http_url":"http://a.zz/my-fake-url"`, - - `"http_error_message":"dial tcp: lookup a.zz`, - `"http_error":`, - - `"http_start_time":"`, - `"http_request_deadline":"`, - `"http_duration":`, - }) + + entries := store.GetEntries() + assert.Len(t, entries, 2) + + entry1 := entries[0] + AssertDefaultContextFields(t, entry1) + assert.Equal(t, logger.DebugLevel, entry1.Level) + assert.Equal(t, "http client gonna GET http://a.zz/my-fake-url", entry1.Message) + assert.Equal(t, "GET", (*entry1.Context)["http_method"].Value) + + entry2 := entries[1] + AssertDefaultContextFields(t, entry2) + assert.Equal(t, logger.ErrorLevel, entry2.Level) + assert.Contains(t, entry2.Message, `http client error GET http://a.zz/my-fake-url [duration:`) + assert.Contains(t, entry2.Message, `dial tcp: lookup a.zz`) + assert.Equal(t, "http://a.zz/my-fake-url", (*entry2.Context)["http_url"].Value) + assert.Contains(t, *entry2.Context, "http_duration") } func TestTripperware_WithPanic(t *testing.T) { @@ -103,10 +100,7 @@ func TestTripperware_WithPanic(t *testing.T) { })) defer server.Close() - loggerOutput := &Output{} - myLogger := logger.NewLogger( - handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), - ) + myLogger, store := testing_logger.NewLogger() transportPanic := httpware.RoundTripFunc(func(req *http.Request) (*http.Response, error) { panic("my transport panic") @@ -123,17 +117,21 @@ func TestTripperware_WithPanic(t *testing.T) { c.Do(request) }) - loggerOutput.Constains(t, []string{ - ` http client panic GET http://a.zz/my-fake-url [duration:`, - `"http_kind":"client"`, - `"http_method":"GET"`, - `"http_url":"http://a.zz/my-fake-url"`, - `"http_panic":"my transport panic"`, - - `"http_start_time":"`, - `"http_request_deadline":"`, - `"http_duration":`, - }) + entries := store.GetEntries() + assert.Len(t, entries, 2) + + entry1 := entries[0] + AssertDefaultContextFields(t, entry1) + assert.Equal(t, logger.DebugLevel, entry1.Level) + assert.Equal(t, "http client gonna GET http://a.zz/my-fake-url", entry1.Message) + assert.Equal(t, "GET", (*entry1.Context)["http_method"].Value) + + entry2 := entries[1] + AssertDefaultContextFields(t, entry2) + assert.Equal(t, logger.CriticalLevel, entry2.Level) + assert.Contains(t, entry2.Message, `http client panic GET http://a.zz/my-fake-url [duration:`) + assert.Equal(t, "http://a.zz/my-fake-url", (*entry2.Context)["http_url"].Value) + assert.Contains(t, *entry2.Context, "http_duration") } func TestTripperware_WithContext(t *testing.T) { @@ -143,10 +141,7 @@ func TestTripperware_WithContext(t *testing.T) { })) defer server.Close() - loggerOutput := &Output{} - myLogger := logger.NewLogger( - handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), - ) + myLogger, store := testing_logger.NewLogger() c := http.Client{ Transport: tripperware.Logger(myLogger, logger_http.WithLoggerContext(func(request *http.Request) *logger.Context { @@ -160,22 +155,28 @@ func TestTripperware_WithContext(t *testing.T) { _, err := c.Do(request) assert.Nil(t, err) - loggerOutput.Constains(t, []string{ - ` http client GET http://127.0.0.1`, - `/my-fake-url [status_code:200, duration:`, - `content_length:2] {`, - `"http_kind":"client"`, - `"http_method":"GET"`, - `"http_response_length":2`, - `"http_status":"200 OK"`, - `"http_status_code":200`, - - `"http_url":"http://127.0.0.1`, - `"http_duration":`, - `"http_start_time":"`, - `"http_request_deadline":"`, - `"base_context_key":"base_context_value"`, - }) + + entries := store.GetEntries() + assert.Len(t, entries, 2) + + entry1 := entries[0] + assert.Equal(t, "base_context_value", (*entry1.Context)["base_context_key"].Value) + AssertDefaultContextFields(t, entry1) + assert.Equal(t, logger.DebugLevel, entry1.Level) + assert.Equal(t, `http client gonna GET `+server.URL+`/my-fake-url`, entry1.Message) + assert.Equal(t, "GET", (*entry1.Context)["http_method"].Value) + + entry2 := entries[1] + assert.Equal(t, "base_context_value", (*entry2.Context)["base_context_key"].Value) + AssertDefaultContextFields(t, entry2) + assert.Equal(t, logger.InfoLevel, entry2.Level) + assert.Contains(t, entry2.Message, `http client GET `+server.URL+`/my-fake-url [status_code:200, duration:`) + assert.Contains(t, entry2.Message, `content_length:2]`) + assert.Equal(t, server.URL+"/my-fake-url", (*entry2.Context)["http_url"].Value) + assert.Equal(t, int64(2), (*entry2.Context)["http_response_length"].Value) + assert.Equal(t, "200 OK", (*entry2.Context)["http_status"].Value) + assert.Equal(t, int64(200), (*entry2.Context)["http_status_code"].Value) + assert.Contains(t, *entry2.Context, "http_duration") } func TestTripperware_WithLevels(t *testing.T) { @@ -185,10 +186,7 @@ func TestTripperware_WithLevels(t *testing.T) { })) defer server.Close() - loggerOutput := &Output{} - myLogger := logger.NewLogger( - handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), - ) + myLogger, store := testing_logger.NewLogger() c := http.Client{ Transport: tripperware.Logger(myLogger, logger_http.WithLevels(func(statusCode int) logger.Level { @@ -202,32 +200,32 @@ func TestTripperware_WithLevels(t *testing.T) { _, err := c.Do(request) assert.Nil(t, err) - loggerOutput.Constains(t, []string{ - ` http client GET http://127.0.0.1`, - `/my-fake-url [status_code:200, duration:`, - `content_length:2] {`, - `"http_kind":"client"`, - `"http_method":"GET"`, - `"http_response_length":2`, - `"http_status":"200 OK"`, - `"http_status_code":200`, - - `"http_url":"http://127.0.0.1`, - `"http_duration":`, - `"http_start_time":"`, - `"http_request_deadline":"`, - }) -} -type Output struct { - bytes.Buffer + entries := store.GetEntries() + assert.Len(t, entries, 2) + + entry1 := entries[0] + AssertDefaultContextFields(t, entry1) + assert.Equal(t, logger.DebugLevel, entry1.Level) + assert.Equal(t, `http client gonna GET `+server.URL+`/my-fake-url`, entry1.Message) + assert.Equal(t, "GET", (*entry1.Context)["http_method"].Value) + + entry2 := entries[1] + AssertDefaultContextFields(t, entry2) + assert.Equal(t, logger.EmergencyLevel, entry2.Level) + assert.Contains(t, entry2.Message, `http client GET `+server.URL+`/my-fake-url [status_code:200, duration:`) + assert.Contains(t, entry2.Message, `content_length:2]`) + assert.Equal(t, server.URL+"/my-fake-url", (*entry2.Context)["http_url"].Value) + assert.Equal(t, int64(2), (*entry2.Context)["http_response_length"].Value) + assert.Equal(t, "200 OK", (*entry2.Context)["http_status"].Value) + assert.Equal(t, int64(200), (*entry2.Context)["http_status_code"].Value) + assert.Contains(t, *entry2.Context, "http_duration") } -func (o *Output) Constains(t *testing.T, str []string) { - b := o.String() - for _, s := range str { - if strings.Contains(b, s) != true { - assert.Fail(t, fmt.Sprintf("buffer %s must contain %s\n", b, s)) - } - } +func AssertDefaultContextFields(t *testing.T, entry logger.Entry) { + assert.Equal(t, "client", (*entry.Context)["http_kind"].Value) + assert.Contains(t, *entry.Context, "http_method") + assert.Contains(t, *entry.Context, "http_url") + assert.Contains(t, *entry.Context, "http_start_time") + assert.Contains(t, *entry.Context, "http_request_deadline") }