From a04fc42a30d1fedff3faa0e7fa49ea236d2f8a22 Mon Sep 17 00:00:00 2001 From: Anthony Moutte Date: Mon, 2 Dec 2019 11:36:05 +0100 Subject: [PATCH 1/5] init logger tripperware --- .gitignore | 16 +++ .travis.yml | 21 ++++ go.mod | 9 ++ go.sum | 75 ++++++++++++++ middleware.go | 61 ++++++++++++ middleware_test.go | 155 +++++++++++++++++++++++++++++ options.go | 77 +++++++++++++++ tripperware.go | 70 +++++++++++++ tripperware_test.go | 232 ++++++++++++++++++++++++++++++++++++++++++++ 9 files changed, 716 insertions(+) create mode 100644 .gitignore create mode 100644 .travis.yml create mode 100644 go.mod create mode 100644 go.sum create mode 100644 middleware.go create mode 100644 middleware_test.go create mode 100644 options.go create mode 100644 tripperware.go create mode 100644 tripperware_test.go diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..b36bf06 --- /dev/null +++ b/.gitignore @@ -0,0 +1,16 @@ +# Created by .ignore support plugin (hsz.mobi) +### Go template +# Binaries for programs and plugins +*.exe +*.exe~ +*.dll +*.so +*.dylib + +# Test binary, build with `go test -c` +*.test + +# Output of the go coverage tool, specifically when used with LiteIDE +*.out + +vendor diff --git a/.travis.yml b/.travis.yml new file mode 100644 index 0000000..f765fb4 --- /dev/null +++ b/.travis.yml @@ -0,0 +1,21 @@ +language: go + +cache: + directories: + - $GOPATH/pkg/mod + +# The coverprofile for multiple packages works in go 1.10 +# see https://tip.golang.org/doc/go1.10#test +go: + - master + +before_script: + - curl -L https://codeclimate.com/downloads/test-reporter/test-reporter-latest-linux-amd64 > ./cc-test-reporter + - chmod +x ./cc-test-reporter + - ./cc-test-reporter before-build + +script: + - go test --race -gcflags=-l -coverprofile c.out ./... + +after_script: + - CC_TEST_REPORTER_ID=$CC_TEST_REPORTER_ID ./cc-test-reporter after-build --exit-code $TRAVIS_TEST_RESULT diff --git a/go.mod b/go.mod new file mode 100644 index 0000000..6163d9b --- /dev/null +++ b/go.mod @@ -0,0 +1,9 @@ +module github.com/gol4ng/logger-http + +go 1.13 + +require ( + github.com/gol4ng/httpware/v2 v2.1.1 + github.com/gol4ng/logger v0.3.0 + github.com/stretchr/testify v1.4.0 +) diff --git a/go.sum b/go.sum new file mode 100644 index 0000000..66b84c8 --- /dev/null +++ b/go.sum @@ -0,0 +1,75 @@ +bou.ke/monkey v1.0.1 h1:zEMLInw9xvNakzUUPjfS4Ds6jYPqCFx3m7bRmG5NH2U= +bou.ke/monkey v1.0.1/go.mod h1:FgHuK96Rv2Nlf+0u1OOVDpCMdsWyOFmeeketDHE7LIg= +github.com/alecthomas/template v0.0.0-20160405071501-a0175ee3bccc/go.mod h1:LOuyumcjzFXgccqObfd/Ljyb9UuFJ6TxHnclSeseNhc= +github.com/alecthomas/units v0.0.0-20151022065526-2efee857e7cf/go.mod h1:ybxpYRFXyAe+OPACYpWeL0wqObRcbAqCMya13uyzqw0= +github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973/go.mod h1:Dwedo/Wpr24TaqPxmxbtue+5NUziq4I4S80YR8gNf3Q= +github.com/beorn7/perks v1.0.0 h1:HWo1m869IqiPhD389kmkxeTalrjNbbJTC8LXupb+sl0= +github.com/beorn7/perks v1.0.0/go.mod h1:KWe93zE9D1o94FZ5RNwFwVgaQK1VOXiVxmqh+CedLV8= +github.com/davecgh/go-spew v1.1.0 h1:ZDRjVQ15GmhC3fiQ8ni8+OwkZQO4DARzQgrnXU1Liz8= +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-kit/kit v0.8.0/go.mod h1:xBxKIO96dXMWWy0MnWVtmwkA9/13aqxPnvrjFYMA2as= +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/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= +github.com/google/go-cmp v0.3.0 h1:crn/baboCvb5fXaQ0IJ1SGTsTVrWpDsCWC8EGETZijY= +github.com/google/go-cmp v0.3.0/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMywk6iLU= +github.com/json-iterator/go v1.1.6/go.mod h1:+SdeFBvtyEkXs7REEP0seUULqWtbJapLOCVDaaPEHmU= +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/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= +github.com/modern-go/reflect2 v1.0.1/go.mod h1:bx2lNnkwVCuqBIxFjflWJWanXIb3RllmbCylyMrvgv0= +github.com/mwitkow/go-conntrack v0.0.0-20161129095857-cc309e4a2223/go.mod h1:qRWi+5nqEBWmkhHvq77mSJWrCKwh8bxhgT7d/eI7P4U= +github.com/pkg/errors v0.8.0/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= +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/prometheus/client_golang v0.9.1/go.mod h1:7SWBe2y4D6OKWSNQJUaRYU/AaXPKyh/dDVn+NZz0KFw= +github.com/prometheus/client_golang v1.0.0 h1:vrDKnkGzuGvhNAL56c7DBz29ZL+KxnoR0x7enabFceM= +github.com/prometheus/client_golang v1.0.0/go.mod h1:db9x61etRT2tGnBNRi70OPL5FsnadC4Ky3P0J6CfImo= +github.com/prometheus/client_model v0.0.0-20180712105110-5c3871d89910/go.mod h1:MbSGuTsp3dbXC40dX6PRTWyKYBIrTGTE9sqQNg2J8bo= +github.com/prometheus/client_model v0.0.0-20190129233127-fd36f4220a90 h1:S/YWwWx/RA8rT8tKFRuGUZhuA90OyIBpPCXkcbwU8DE= +github.com/prometheus/client_model v0.0.0-20190129233127-fd36f4220a90/go.mod h1:xMI15A0UPsDsEKsMN9yxemIoYk6Tm2C1GtYGdfGttqA= +github.com/prometheus/common v0.4.1 h1:K0MGApIoQvMw27RTdJkPbr3JZ7DNbtxQNyi5STVM6Kw= +github.com/prometheus/common v0.4.1/go.mod h1:TNfzLD0ON7rHzMJeJkieUDPYmFC7Snx/y86RQel1bk4= +github.com/prometheus/procfs v0.0.0-20181005140218-185b4288413d/go.mod h1:c3At6R/oaqEKCNdg8wHV1ftS6bRYblBhIjjI8uT2IGk= +github.com/prometheus/procfs v0.0.2 h1:6LJUbpNm42llc4HRCuvApCSWB/WfhuNo9K98Q9sNGfs= +github.com/prometheus/procfs v0.0.2/go.mod h1:TjEm7ze935MbeOT/UhFTIMYKhuLP4wbCsTZCD3I8kEA= +github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo= +github.com/stretchr/objx v0.1.0 h1:4G4v2dO3VZwixGIRoQ5Lfboy6nUhCyYzaqnIAPPhYs4= +github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= +github.com/stretchr/objx v0.1.1 h1:2vfRuCMp5sSVIDSqO8oNnWJq7mPa6KVP3iPIwFBuy8A= +github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= +github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs= +github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= +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/net v0.0.0-20181114220301-adae6a3d119a/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= +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/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= +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/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= diff --git a/middleware.go b/middleware.go new file mode 100644 index 0000000..933163f --- /dev/null +++ b/middleware.go @@ -0,0 +1,61 @@ +package logger_http + +import ( + "fmt" + "net/http" + "time" + + "github.com/gol4ng/httpware/v2" + middleware2 "github.com/gol4ng/httpware/v2/middleware" + "github.com/gol4ng/logger" + "github.com/gol4ng/logger/middleware" +) + +// Middleware will decorate the http.Handler to add support of gol4ng/logger +func Middleware(log logger.LoggerInterface, opts ...Option) httpware.Middleware { + o := evaluateClientOpt(opts...) + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(writer http.ResponseWriter, req *http.Request) { + startTime := time.Now() + + ctx := req.Context() + currentLogger := logger.FromContext(ctx, log) + baseContext := o.loggerContextProvider(req) + currentContext := feedContext(baseContext, ctx, req, startTime).Add("http_kind", "server") + + if wrappableLogger, ok := currentLogger.(logger.WrappableLoggerInterface); ok { + currentLogger = wrappableLogger.WrapNew(middleware.Context(currentContext)) + } + writerInterceptor := middleware2.NewResponseWriterInterceptor(writer) + defer func() { + duration := time.Since(startTime) + currentContext.Add("http_duration", duration.Seconds()) + + if err := recover(); err != nil { + currentContext.Add("http_panic", err) + _ = currentLogger.Critical(fmt.Sprintf("http server panic %s %s [duration:%s]", req.Method, req.URL, duration), currentContext) + panic(err) + } + + currentContext.Add("http_status", http.StatusText(writerInterceptor.StatusCode)). + Add("http_status_code", writerInterceptor.StatusCode). + Add("http_response_length", len(writerInterceptor.Body)) + + _ = 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), + currentContext, + ) + }() + + next.ServeHTTP(writerInterceptor, req) + }) + } +} diff --git a/middleware_test.go b/middleware_test.go new file mode 100644 index 0000000..131c073 --- /dev/null +++ b/middleware_test.go @@ -0,0 +1,155 @@ +package logger_http_test + +import ( + "context" + "net/http" + "net/http/httptest" + "testing" + "time" + + "github.com/gol4ng/logger" + "github.com/gol4ng/logger-http" + "github.com/gol4ng/logger/formatter" + "github.com/gol4ng/logger/handler" + "github.com/stretchr/testify/assert" +) + +func TestMiddleware(t *testing.T) { + req := httptest.NewRequest(http.MethodGet, "http://127.0.0.1/my-fake-url", nil) + ctx, _ := context.WithTimeout(req.Context(), 3*time.Second) + req = req.WithContext(ctx) + responseWriter := &httptest.ResponseRecorder{} + + h := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + // not equal because req.WithContext create another request object + assert.NotEqual(t, responseWriter, w) + w.Write([]byte(`OK`)) + }) + + output := &Output{} + myLogger := logger.NewLogger( + handler.Stream(output, formatter.NewDefaultFormatter()), + ) + + logger_http.Middleware(myLogger)(h).ServeHTTP(responseWriter, req) + output.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":"`, + }) +} + +func TestMiddleware_WithPanic(t *testing.T) { + req := httptest.NewRequest(http.MethodGet, "http://127.0.0.1/my-fake-url", nil) + ctx, _ := context.WithTimeout(req.Context(), 3*time.Second) + req = req.WithContext(ctx) + responseWriter := &httptest.ResponseRecorder{} + + h := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + panic("my handler panic") + }) + + output := &Output{} + myLogger := logger.NewLogger( + handler.Stream(output, formatter.NewDefaultFormatter()), + ) + + assert.PanicsWithValue(t, "my handler panic", func() { + logger_http.Middleware(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"`, + + `"http_url":"http://127.0.0.1`, + `"http_duration":`, + `"http_start_time":"`, + `"http_request_deadline":"`, + }) +} + +func TestMiddleware_WithContext(t *testing.T) { + req := httptest.NewRequest(http.MethodGet, "http://127.0.0.1/my-fake-url", nil) + ctx, _ := context.WithTimeout(req.Context(), 3*time.Second) + req = req.WithContext(ctx) + responseWriter := &httptest.ResponseRecorder{} + + h := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + // not equal because req.WithContext create another request object + assert.NotEqual(t, responseWriter, w) + w.Write([]byte(`OK`)) + }) + + output := &Output{} + myLogger := logger.NewLogger( + handler.Stream(output, formatter.NewDefaultFormatter()), + ) + + logger_http.Middleware(myLogger, logger_http.WithLoggerContext(func(request *http.Request) *logger.Context { + return logger.NewContext().Add("base_context_key", "base_context_value") + }))(h).ServeHTTP(responseWriter, req) + + output.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":"`, + }) +} + +func TestMiddleware_WithLevels(t *testing.T) { + req := httptest.NewRequest(http.MethodGet, "http://127.0.0.1/my-fake-url", nil) + ctx, _ := context.WithTimeout(req.Context(), 3*time.Second) + req = req.WithContext(ctx) + responseWriter := &httptest.ResponseRecorder{} + + h := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + // not equal because req.WithContext create another request object + assert.NotEqual(t, responseWriter, w) + w.Write([]byte(`OK`)) + }) + + output := &Output{} + myLogger := logger.NewLogger( + handler.Stream(output, formatter.NewDefaultFormatter()), + ) + + logger_http.Middleware(myLogger, logger_http.WithLevels(func(statusCode int) logger.Level { + return logger.EmergencyLevel + }))(h).ServeHTTP(responseWriter, req) + + output.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":"`, + }) +} diff --git a/options.go b/options.go new file mode 100644 index 0000000..9fffc75 --- /dev/null +++ b/options.go @@ -0,0 +1,77 @@ +package logger_http + +import ( + "context" + "net/http" + "time" + + "github.com/gol4ng/logger" +) + +type options struct { + loggerContextProvider LoggerContextProvider + levelFunc CodeToLevel +} + +// LoggerContextProvider function defines the default logger context values +type LoggerContextProvider func(*http.Request) *logger.Context + +// CodeToLevel function defines the mapping between http.StatusCode and logger.Level +type CodeToLevel func(statusCode int) logger.Level + +var ( + defaultOptions = &options{ + loggerContextProvider: func(_ *http.Request) *logger.Context { + return nil + }, + levelFunc: func(statusCode int) logger.Level { + switch { + case statusCode < http.StatusBadRequest: + return logger.InfoLevel + case statusCode < http.StatusInternalServerError: + return logger.WarningLevel + } + return logger.ErrorLevel + }, + } +) + +func evaluateClientOpt(opts ...Option) *options { + optCopy := &options{} + *optCopy = *defaultOptions + for _, o := range opts { + o(optCopy) + } + return optCopy +} + +type Option func(*options) + +// WithLoggerContext will provide default logger context values +func WithLoggerContext(f LoggerContextProvider) Option { + return func(o *options) { + o.loggerContextProvider = f + } +} + +// WithLevels customizes the function for the mapping between http.StatusCode and logger.Level +func WithLevels(f CodeToLevel) Option { + return func(o *options) { + o.levelFunc = f + } +} + +func feedContext(baseContext *logger.Context, ctx context.Context, req *http.Request, startTime time.Time) *logger.Context { + c := logger.NewContext(). + Add("http_method", req.Method). + Add("http_url", req.URL.String()). + Add("http_start_time", startTime.Format(time.RFC3339)) + + if baseContext != nil { + c.Merge(*baseContext) + } + if d, ok := ctx.Deadline(); ok { + c.Add("http_request_deadline", d.Format(time.RFC3339)) + } + return c +} diff --git a/tripperware.go b/tripperware.go new file mode 100644 index 0000000..7dca41f --- /dev/null +++ b/tripperware.go @@ -0,0 +1,70 @@ +package logger_http + +import ( + "fmt" + "net/http" + "time" + + "github.com/gol4ng/httpware/v2" + "github.com/gol4ng/logger" + "github.com/gol4ng/logger/middleware" +) + +// Tripperware will decorate the http.Client Transport to add support of gol4ng/logger +func Tripperware(log logger.LoggerInterface, opts ...Option) func(next http.RoundTripper) http.RoundTripper { + o := evaluateClientOpt(opts...) + return func(next http.RoundTripper) http.RoundTripper { + return httpware.RoundTripFunc(func(req *http.Request) (resp *http.Response, err error) { + startTime := time.Now() + + ctx := req.Context() + currentLogger := logger.FromContext(ctx, log) + baseContext := o.loggerContextProvider(req) + currentContext := feedContext(baseContext, ctx, req, startTime).Add("http_kind", "client") + + if wrappableLogger, ok := currentLogger.(logger.WrappableLoggerInterface); ok { + currentLogger = wrappableLogger.WrapNew(middleware.Context(currentContext)) + } + + defer func() { + if err := recover(); err != nil { + duration := time.Since(startTime) + currentContext.Add("http_duration", duration.Seconds()) + currentContext.Add("http_panic", err) + _ = currentLogger.Critical(fmt.Sprintf("http client panic %s %s [duration:%s]", req.Method, req.URL, duration), currentContext) + panic(err) + } + }() + + resp, err = next.RoundTrip(req) + duration := time.Since(startTime) + currentContext.Add("http_duration", duration.Seconds()) + if err != nil { + currentContext.Add("http_error", err) + currentContext.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, time.Since(startTime), err), currentContext) + return resp, err + } + currentContext.Add("http_status", resp.Status). + Add("http_status_code", resp.StatusCode). + Add("http_response_length", resp.ContentLength) + + _ = 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), + currentContext, + ) + + return resp, err + }) + } +} diff --git a/tripperware_test.go b/tripperware_test.go new file mode 100644 index 0000000..9b1e2de --- /dev/null +++ b/tripperware_test.go @@ -0,0 +1,232 @@ +package logger_http_test + +import ( + "bytes" + "context" + "fmt" + "net/http" + "net/http/httptest" + "strings" + "testing" + "time" + + "github.com/gol4ng/httpware/v2" + "github.com/gol4ng/logger" + "github.com/gol4ng/logger/formatter" + "github.com/gol4ng/logger/handler" + "github.com/stretchr/testify/assert" + + "github.com/gol4ng/logger-http" +) + +func TestTripperware(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) { + assert.Equal(t, req.URL.String(), "/my-fake-url") + rw.Write([]byte(`OK`)) + })) + defer server.Close() + + output := &Output{} + myLogger := logger.NewLogger( + handler.Stream(output, formatter.NewDefaultFormatter()), + ) + + c := http.Client{ + Transport: logger_http.Tripperware(myLogger)(http.DefaultTransport), + } + + ctx := context.Background() + ctx, _ = context.WithTimeout(ctx, 3*time.Second) + req, _ := http.NewRequestWithContext(ctx, http.MethodGet, server.URL+"/my-fake-url", nil) + + _, err := c.Do(req) + assert.Nil(t, err) + output.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":"`, + }) +} + +func TestTripperware_WithError(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) { + assert.Fail(t, "server must not be called") + })) + defer server.Close() + + output := &Output{} + myLogger := logger.NewLogger( + handler.Stream(output, formatter.NewDefaultFormatter()), + ) + + c := http.Client{ + Transport: logger_http.Tripperware(myLogger)(http.DefaultTransport), + } + + ctx := context.Background() + ctx, _ = context.WithTimeout(ctx, 3*time.Second) + req, _ := http.NewRequestWithContext(ctx, http.MethodGet, "http://a.zz/my-fake-url", nil) + + _, err := c.Do(req) + assert.Contains(t, err.Error(), "no such host") + output.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":`, + }) +} + +func TestTripperware_WithPanic(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) { + assert.Fail(t, "server must not be called") + })) + defer server.Close() + + output := &Output{} + myLogger := logger.NewLogger( + handler.Stream(output, formatter.NewDefaultFormatter()), + ) + + transportPanic := httpware.RoundTripFunc(func(req *http.Request) (*http.Response, error) { + panic("my transport panic") + }) + c := http.Client{ + Transport: logger_http.Tripperware(myLogger)(transportPanic), + } + + assert.Panics(t, func() { + ctx := context.Background() + ctx, _ = context.WithTimeout(ctx, 3*time.Second) + req, _ := http.NewRequestWithContext(ctx, http.MethodGet, "http://a.zz/my-fake-url", nil) + + c.Do(req) + }) + + output.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":`, + }) +} + +func TestTripperware_WithContext(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) { + assert.Equal(t, req.URL.String(), "/my-fake-url") + rw.Write([]byte(`OK`)) + })) + defer server.Close() + + output := &Output{} + myLogger := logger.NewLogger( + handler.Stream(output, formatter.NewDefaultFormatter()), + ) + + c := http.Client{ + Transport: logger_http.Tripperware(myLogger, logger_http.WithLoggerContext(func(request *http.Request) *logger.Context { + return logger.NewContext().Add("base_context_key", "base_context_value") + }))(http.DefaultTransport), + } + + ctx := context.Background() + ctx, _ = context.WithTimeout(ctx, 3*time.Second) + req, _ := http.NewRequestWithContext(ctx, http.MethodGet, server.URL+"/my-fake-url", nil) + + _, err := c.Do(req) + assert.Nil(t, err) + output.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"`, + }) +} + +func TestTripperware_WithLevels(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) { + assert.Equal(t, req.URL.String(), "/my-fake-url") + rw.Write([]byte(`OK`)) + })) + defer server.Close() + + output := &Output{} + myLogger := logger.NewLogger( + handler.Stream(output, formatter.NewDefaultFormatter()), + ) + + c := http.Client{ + Transport: logger_http.Tripperware(myLogger, logger_http.WithLevels(func(statusCode int) logger.Level { + return logger.EmergencyLevel + }))(http.DefaultTransport), + } + + ctx := context.Background() + ctx, _ = context.WithTimeout(ctx, 3*time.Second) + req, _ := http.NewRequestWithContext(ctx, http.MethodGet, server.URL+"/my-fake-url", nil) + + _, err := c.Do(req) + assert.Nil(t, err) + output.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 +} + +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)) + } + } +} From 9eae1563a7ac8808ff5e9192f9db42d400fc620c Mon Sep 17 00:00:00 2001 From: Anthony Moutte Date: Fri, 6 Dec 2019 09:53:36 +0100 Subject: [PATCH 2/5] move file --- README.md | 42 +++++++++++ middleware.go | 61 ---------------- middleware/correlation_id.go | 31 ++++++++ middleware/logger.go | 53 ++++++++++++++ .../logger_test.go | 27 +++++-- options.go | 53 ++++++++------ tripperware.go | 70 ------------------- tripperware/correlation_id.go | 31 ++++++++ tripperware/logger.go | 59 ++++++++++++++++ .../logger_test.go | 13 ++-- 10 files changed, 277 insertions(+), 163 deletions(-) delete mode 100644 middleware.go create mode 100644 middleware/correlation_id.go create mode 100644 middleware/logger.go rename middleware_test.go => middleware/logger_test.go (86%) delete mode 100644 tripperware.go create mode 100644 tripperware/correlation_id.go create mode 100644 tripperware/logger.go rename tripperware_test.go => tripperware/logger_test.go (92%) diff --git a/README.md b/README.md index 79f29e7..b52b3c9 100644 --- a/README.md +++ b/README.md @@ -1,2 +1,44 @@ # logger-http + +[![Build Status](https://travis-ci.org/gol4ng/logger-http.svg?branch=master)](https://travis-ci.org/gol4ng/logger-http) +[![GoDoc](https://godoc.org/github.com/gol4ng/logger-http?status.svg)](https://godoc.org/github.com/gol4ng/logger-http) + Gol4ng logger sub package for http + +## Installation + +`go get -u github.com/gol4ng/logger-http` + +## Quick Start + +Log you `http.Client` request + +```go +package main + +import ( + "net/http" + "os" + + "github.com/gol4ng/logger" + "github.com/gol4ng/logger-http" + "github.com/gol4ng/logger/formatter" + "github.com/gol4ng/logger/handler" +) + +func main(){ + // logger will print on STDOUT with default line format + myLogger := logger.NewLogger(handler.Stream(os.Stdout, formatter.NewDefaultFormatter())) + + c := http.Client{ + Transport: logger_http.Tripperware(myLogger)(http.DefaultTransport), + } + + c.Get("http://google.com") + // Will log + // http client GET http://google.com [status_code:301, duration:27.524999ms, content_length:219] {"http_duration":0.027524999,"http_status":"301 Moved Permanently","http_status_code":301,"http_response_length":219,"http_method":"GET","http_url":"http://google.com","http_start_time":"2019-12-03T10:47:38+01:00","http_kind":"client"} + // http client GET http://www.google.com/ [status_code:200, duration:51.047002ms, content_length:-1] {"http_kind":"client","http_duration":0.051047002,"http_status":"200 OK","http_status_code":200,"http_response_length":-1,"http_method":"GET","http_url":"http://www.google.com/","http_start_time":"2019-12-03T10:47:38+01:00"} +} +``` + +Log you incoming http server request diff --git a/middleware.go b/middleware.go deleted file mode 100644 index 933163f..0000000 --- a/middleware.go +++ /dev/null @@ -1,61 +0,0 @@ -package logger_http - -import ( - "fmt" - "net/http" - "time" - - "github.com/gol4ng/httpware/v2" - middleware2 "github.com/gol4ng/httpware/v2/middleware" - "github.com/gol4ng/logger" - "github.com/gol4ng/logger/middleware" -) - -// Middleware will decorate the http.Handler to add support of gol4ng/logger -func Middleware(log logger.LoggerInterface, opts ...Option) httpware.Middleware { - o := evaluateClientOpt(opts...) - return func(next http.Handler) http.Handler { - return http.HandlerFunc(func(writer http.ResponseWriter, req *http.Request) { - startTime := time.Now() - - ctx := req.Context() - currentLogger := logger.FromContext(ctx, log) - baseContext := o.loggerContextProvider(req) - currentContext := feedContext(baseContext, ctx, req, startTime).Add("http_kind", "server") - - if wrappableLogger, ok := currentLogger.(logger.WrappableLoggerInterface); ok { - currentLogger = wrappableLogger.WrapNew(middleware.Context(currentContext)) - } - writerInterceptor := middleware2.NewResponseWriterInterceptor(writer) - defer func() { - duration := time.Since(startTime) - currentContext.Add("http_duration", duration.Seconds()) - - if err := recover(); err != nil { - currentContext.Add("http_panic", err) - _ = currentLogger.Critical(fmt.Sprintf("http server panic %s %s [duration:%s]", req.Method, req.URL, duration), currentContext) - panic(err) - } - - currentContext.Add("http_status", http.StatusText(writerInterceptor.StatusCode)). - Add("http_status_code", writerInterceptor.StatusCode). - Add("http_response_length", len(writerInterceptor.Body)) - - _ = 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), - currentContext, - ) - }() - - next.ServeHTTP(writerInterceptor, req) - }) - } -} diff --git a/middleware/correlation_id.go b/middleware/correlation_id.go new file mode 100644 index 0000000..62e55f2 --- /dev/null +++ b/middleware/correlation_id.go @@ -0,0 +1,31 @@ +package middleware + +import ( + "net/http" + + "github.com/gol4ng/httpware/v2" + "github.com/gol4ng/httpware/v2/correlation_id" + middleware2 "github.com/gol4ng/httpware/v2/middleware" + "github.com/gol4ng/logger" + "github.com/gol4ng/logger/middleware" +) + +// CorrelationId will decorate the http.Handler to add support of gol4ng/logger +func CorrelationId(log logger.LoggerInterface, options ...correlation_id.Option) httpware.Middleware { + config := correlation_id.GetConfig(options...) + orig := middleware2.CorrelationId(options...) + return func(next http.Handler) http.Handler { + return orig(http.HandlerFunc(func(writer http.ResponseWriter, req *http.Request) { + ctx := req.Context() + currentLogger := logger.FromContext(ctx, log) + if wrappableLogger, ok := currentLogger.(logger.WrappableLoggerInterface); ok { + logger.InjectInContext(ctx, wrappableLogger.Wrap( + middleware.Context( + logger.NewContext().Add(config.HeaderName, ctx.Value(config.HeaderName)), + ), + )) + } + next.ServeHTTP(writer, req) + })) + } +} diff --git a/middleware/logger.go b/middleware/logger.go new file mode 100644 index 0000000..4577812 --- /dev/null +++ b/middleware/logger.go @@ -0,0 +1,53 @@ +package middleware + +import ( + "fmt" + "net/http" + "time" + + "github.com/gol4ng/httpware/v2" + middleware2 "github.com/gol4ng/httpware/v2/middleware" + "github.com/gol4ng/logger" + "github.com/gol4ng/logger-http" +) + +func Logger(log logger.LoggerInterface, opts ...logger_http.Option) httpware.Middleware { + o := logger_http.EvaluateServerOpt(opts...) + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(writer http.ResponseWriter, req *http.Request) { + startTime := time.Now() + ctx := req.Context() + + currentLogger := logger.FromContext(ctx, log) + currentLoggerContext := logger_http.FeedContext(o.LoggerContextProvider(req), ctx, req, startTime).Add("http_kind", "server") + + writerInterceptor := middleware2.NewResponseWriterInterceptor(writer) + defer func() { + duration := time.Since(startTime) + currentLoggerContext.Add("http_duration", duration.Seconds()) + + 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) + panic(err) + } + + currentLoggerContext.Add("http_status", http.StatusText(writerInterceptor.StatusCode)). + Add("http_status_code", writerInterceptor.StatusCode). + Add("http_response_length", len(writerInterceptor.Body)) + + _ = 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, + ) + }() + + _ = currentLogger.Debug(fmt.Sprintf("http server received %s %s", req.Method, req.URL), currentLoggerContext) + next.ServeHTTP(writerInterceptor, req) + }) + } +} diff --git a/middleware_test.go b/middleware/logger_test.go similarity index 86% rename from middleware_test.go rename to middleware/logger_test.go index 131c073..5eb8086 100644 --- a/middleware_test.go +++ b/middleware/logger_test.go @@ -1,14 +1,18 @@ -package logger_http_test +package middleware_test import ( + "bytes" "context" + "fmt" "net/http" "net/http/httptest" + "strings" "testing" "time" "github.com/gol4ng/logger" "github.com/gol4ng/logger-http" + "github.com/gol4ng/logger-http/middleware" "github.com/gol4ng/logger/formatter" "github.com/gol4ng/logger/handler" "github.com/stretchr/testify/assert" @@ -31,7 +35,7 @@ func TestMiddleware(t *testing.T) { handler.Stream(output, formatter.NewDefaultFormatter()), ) - logger_http.Middleware(myLogger)(h).ServeHTTP(responseWriter, req) + middleware.Logger(myLogger)(h).ServeHTTP(responseWriter, req) output.Constains(t, []string{ ` http server GET http://127.0.0.1/my-fake-url [status_code:200, duration:`, `content_length:2] {`, @@ -64,7 +68,7 @@ func TestMiddleware_WithPanic(t *testing.T) { ) assert.PanicsWithValue(t, "my handler panic", func() { - logger_http.Middleware(myLogger)(h).ServeHTTP(responseWriter, req) + middleware.Logger(myLogger)(h).ServeHTTP(responseWriter, req) }) output.Constains(t, []string{ @@ -96,7 +100,7 @@ func TestMiddleware_WithContext(t *testing.T) { handler.Stream(output, formatter.NewDefaultFormatter()), ) - logger_http.Middleware(myLogger, logger_http.WithLoggerContext(func(request *http.Request) *logger.Context { + 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, req) @@ -134,7 +138,7 @@ func TestMiddleware_WithLevels(t *testing.T) { handler.Stream(output, formatter.NewDefaultFormatter()), ) - logger_http.Middleware(myLogger, logger_http.WithLevels(func(statusCode int) logger.Level { + middleware.Logger(myLogger, logger_http.WithLevels(func(statusCode int) logger.Level { return logger.EmergencyLevel }))(h).ServeHTTP(responseWriter, req) @@ -153,3 +157,16 @@ func TestMiddleware_WithLevels(t *testing.T) { `"http_request_deadline":"`, }) } + +type Output struct { + bytes.Buffer +} + +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)) + } + } +} diff --git a/options.go b/options.go index 9fffc75..13953ff 100644 --- a/options.go +++ b/options.go @@ -8,9 +8,9 @@ import ( "github.com/gol4ng/logger" ) -type options struct { - loggerContextProvider LoggerContextProvider - levelFunc CodeToLevel +type Options struct { + LoggerContextProvider LoggerContextProvider + LevelFunc CodeToLevel } // LoggerContextProvider function defines the default logger context values @@ -20,11 +20,13 @@ type LoggerContextProvider func(*http.Request) *logger.Context type CodeToLevel func(statusCode int) logger.Level var ( - defaultOptions = &options{ - loggerContextProvider: func(_ *http.Request) *logger.Context { - return nil + defaultOptions = &Options{ + LoggerContextProvider: func(request *http.Request) *logger.Context { + return logger.NewContext(). + Add("http_header", request.Header). + Add("http_body", request.GetBody) }, - levelFunc: func(statusCode int) logger.Level { + LevelFunc: func(statusCode int) logger.Level { switch { case statusCode < http.StatusBadRequest: return logger.InfoLevel @@ -36,8 +38,8 @@ var ( } ) -func evaluateClientOpt(opts ...Option) *options { - optCopy := &options{} +func EvaluateClientOpt(opts ...Option) *Options { + optCopy := &Options{} *optCopy = *defaultOptions for _, o := range opts { o(optCopy) @@ -45,33 +47,42 @@ func evaluateClientOpt(opts ...Option) *options { return optCopy } -type Option func(*options) +func EvaluateServerOpt(opts ...Option) *Options { + optCopy := &Options{} + *optCopy = *defaultOptions + for _, o := range opts { + o(optCopy) + } + return optCopy +} + +type Option func(*Options) // WithLoggerContext will provide default logger context values func WithLoggerContext(f LoggerContextProvider) Option { - return func(o *options) { - o.loggerContextProvider = f + return func(o *Options) { + o.LoggerContextProvider = f } } // WithLevels customizes the function for the mapping between http.StatusCode and logger.Level func WithLevels(f CodeToLevel) Option { - return func(o *options) { - o.levelFunc = f + return func(o *Options) { + o.LevelFunc = f } } -func feedContext(baseContext *logger.Context, ctx context.Context, req *http.Request, startTime time.Time) *logger.Context { - c := logger.NewContext(). +func FeedContext(loggerContext *logger.Context, ctx context.Context, req *http.Request, startTime time.Time) *logger.Context { + if loggerContext == nil { + loggerContext = logger.NewContext() + } + loggerContext. Add("http_method", req.Method). Add("http_url", req.URL.String()). Add("http_start_time", startTime.Format(time.RFC3339)) - if baseContext != nil { - c.Merge(*baseContext) - } if d, ok := ctx.Deadline(); ok { - c.Add("http_request_deadline", d.Format(time.RFC3339)) + loggerContext.Add("http_request_deadline", d.Format(time.RFC3339)) } - return c + return loggerContext } diff --git a/tripperware.go b/tripperware.go deleted file mode 100644 index 7dca41f..0000000 --- a/tripperware.go +++ /dev/null @@ -1,70 +0,0 @@ -package logger_http - -import ( - "fmt" - "net/http" - "time" - - "github.com/gol4ng/httpware/v2" - "github.com/gol4ng/logger" - "github.com/gol4ng/logger/middleware" -) - -// Tripperware will decorate the http.Client Transport to add support of gol4ng/logger -func Tripperware(log logger.LoggerInterface, opts ...Option) func(next http.RoundTripper) http.RoundTripper { - o := evaluateClientOpt(opts...) - return func(next http.RoundTripper) http.RoundTripper { - return httpware.RoundTripFunc(func(req *http.Request) (resp *http.Response, err error) { - startTime := time.Now() - - ctx := req.Context() - currentLogger := logger.FromContext(ctx, log) - baseContext := o.loggerContextProvider(req) - currentContext := feedContext(baseContext, ctx, req, startTime).Add("http_kind", "client") - - if wrappableLogger, ok := currentLogger.(logger.WrappableLoggerInterface); ok { - currentLogger = wrappableLogger.WrapNew(middleware.Context(currentContext)) - } - - defer func() { - if err := recover(); err != nil { - duration := time.Since(startTime) - currentContext.Add("http_duration", duration.Seconds()) - currentContext.Add("http_panic", err) - _ = currentLogger.Critical(fmt.Sprintf("http client panic %s %s [duration:%s]", req.Method, req.URL, duration), currentContext) - panic(err) - } - }() - - resp, err = next.RoundTrip(req) - duration := time.Since(startTime) - currentContext.Add("http_duration", duration.Seconds()) - if err != nil { - currentContext.Add("http_error", err) - currentContext.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, time.Since(startTime), err), currentContext) - return resp, err - } - currentContext.Add("http_status", resp.Status). - Add("http_status_code", resp.StatusCode). - Add("http_response_length", resp.ContentLength) - - _ = 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), - currentContext, - ) - - return resp, err - }) - } -} diff --git a/tripperware/correlation_id.go b/tripperware/correlation_id.go new file mode 100644 index 0000000..7012542 --- /dev/null +++ b/tripperware/correlation_id.go @@ -0,0 +1,31 @@ +package tripperware + +import ( + "net/http" + + "github.com/gol4ng/httpware/v2" + "github.com/gol4ng/httpware/v2/correlation_id" + tripperware2 "github.com/gol4ng/httpware/v2/tripperware" + "github.com/gol4ng/logger" + "github.com/gol4ng/logger/middleware" +) + +// CorrelationId will decorate the http.Handler to add support of gol4ng/logger +func CorrelationId(log logger.LoggerInterface, options ...correlation_id.Option) httpware.Tripperware { + config := correlation_id.GetConfig(options...) + orig := tripperware2.CorrelationId(options...) + return func(next http.RoundTripper) http.RoundTripper { + return orig(httpware.RoundTripFunc(func(req *http.Request) (resp *http.Response, err error) { + ctx := req.Context() + currentLogger := logger.FromContext(ctx, log) + if wrappableLogger, ok := currentLogger.(logger.WrappableLoggerInterface); ok { + logger.InjectInContext(ctx, wrappableLogger.Wrap( + middleware.Context( + logger.NewContext().Add(config.HeaderName, ctx.Value(config.HeaderName)), + ), + )) + } + return next.RoundTrip(req) + })) + } +} diff --git a/tripperware/logger.go b/tripperware/logger.go new file mode 100644 index 0000000..c74c933 --- /dev/null +++ b/tripperware/logger.go @@ -0,0 +1,59 @@ +package tripperware + +import ( + "fmt" + "net/http" + "time" + + "github.com/gol4ng/httpware/v2" + "github.com/gol4ng/logger" + "github.com/gol4ng/logger-http" +) + +// Tripperware will decorate the http.Client Transport to add support of gol4ng/logger +func Logger(log logger.LoggerInterface, opts ...logger_http.Option) func(next http.RoundTripper) http.RoundTripper { + o := logger_http.EvaluateClientOpt(opts...) + return func(next http.RoundTripper) http.RoundTripper { + return httpware.RoundTripFunc(func(req *http.Request) (resp *http.Response, err error) { + startTime := time.Now() + ctx := req.Context() + + currentLogger := logger.FromContext(ctx, log) + currentLoggerContext := logger_http.FeedContext(o.LoggerContextProvider(req), ctx, req, startTime).Add("http_kind", "client") + + defer func() { + duration := time.Since(startTime) + currentLoggerContext.Add("http_duration", duration.Seconds()) + + 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) + panic(err) + } + if err != nil { + currentLoggerContext.Add("http_error", err) + 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) + return + } + currentLoggerContext.Add("http_status", resp.Status). + Add("http_status_code", resp.StatusCode). + Add("http_response_length", resp.ContentLength) + + _ = 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, + ) + }() + + _ = currentLogger.Debug(fmt.Sprintf("http client gonna %s %s", req.Method, req.URL), currentLoggerContext) + return next.RoundTrip(req) + }) + } +} diff --git a/tripperware_test.go b/tripperware/logger_test.go similarity index 92% rename from tripperware_test.go rename to tripperware/logger_test.go index 9b1e2de..bfdf588 100644 --- a/tripperware_test.go +++ b/tripperware/logger_test.go @@ -1,4 +1,4 @@ -package logger_http_test +package tripperware_test import ( "bytes" @@ -12,6 +12,7 @@ import ( "github.com/gol4ng/httpware/v2" "github.com/gol4ng/logger" + "github.com/gol4ng/logger-http/tripperware" "github.com/gol4ng/logger/formatter" "github.com/gol4ng/logger/handler" "github.com/stretchr/testify/assert" @@ -32,7 +33,7 @@ func TestTripperware(t *testing.T) { ) c := http.Client{ - Transport: logger_http.Tripperware(myLogger)(http.DefaultTransport), + Transport: tripperware.Logger(myLogger)(http.DefaultTransport), } ctx := context.Background() @@ -70,7 +71,7 @@ func TestTripperware_WithError(t *testing.T) { ) c := http.Client{ - Transport: logger_http.Tripperware(myLogger)(http.DefaultTransport), + Transport: tripperware.Logger(myLogger)(http.DefaultTransport), } ctx := context.Background() @@ -111,7 +112,7 @@ func TestTripperware_WithPanic(t *testing.T) { panic("my transport panic") }) c := http.Client{ - Transport: logger_http.Tripperware(myLogger)(transportPanic), + Transport: tripperware.Logger(myLogger)(transportPanic), } assert.Panics(t, func() { @@ -148,7 +149,7 @@ func TestTripperware_WithContext(t *testing.T) { ) c := http.Client{ - Transport: logger_http.Tripperware(myLogger, logger_http.WithLoggerContext(func(request *http.Request) *logger.Context { + Transport: tripperware.Logger(myLogger, logger_http.WithLoggerContext(func(request *http.Request) *logger.Context { return logger.NewContext().Add("base_context_key", "base_context_value") }))(http.DefaultTransport), } @@ -190,7 +191,7 @@ func TestTripperware_WithLevels(t *testing.T) { ) c := http.Client{ - Transport: logger_http.Tripperware(myLogger, logger_http.WithLevels(func(statusCode int) logger.Level { + Transport: tripperware.Logger(myLogger, logger_http.WithLevels(func(statusCode int) logger.Level { return logger.EmergencyLevel }))(http.DefaultTransport), } From 8addd8597b246c9ee046f129a42680705c601b87 Mon Sep 17 00:00:00 2001 From: Anthony Moutte Date: Thu, 12 Dec 2019 12:03:39 +0100 Subject: [PATCH 3/5] fixup review --- middleware/correlation_id.go | 27 +++++++++++++++++---------- options.go | 12 +++++------- tripperware/correlation_id.go | 28 ++++++++++++++++++---------- 3 files changed, 40 insertions(+), 27 deletions(-) diff --git a/middleware/correlation_id.go b/middleware/correlation_id.go index 62e55f2..50580ae 100644 --- a/middleware/correlation_id.go +++ b/middleware/correlation_id.go @@ -5,26 +5,33 @@ import ( "github.com/gol4ng/httpware/v2" "github.com/gol4ng/httpware/v2/correlation_id" - middleware2 "github.com/gol4ng/httpware/v2/middleware" + http_middleware "github.com/gol4ng/httpware/v2/middleware" "github.com/gol4ng/logger" "github.com/gol4ng/logger/middleware" ) // CorrelationId will decorate the http.Handler to add support of gol4ng/logger -func CorrelationId(log logger.LoggerInterface, options ...correlation_id.Option) httpware.Middleware { +func CorrelationId(log logger.WrappableLoggerInterface, options ...correlation_id.Option) httpware.Middleware { config := correlation_id.GetConfig(options...) - orig := middleware2.CorrelationId(options...) + orig := http_middleware.CorrelationId(options...) return func(next http.Handler) http.Handler { return orig(http.HandlerFunc(func(writer http.ResponseWriter, req *http.Request) { ctx := req.Context() - currentLogger := logger.FromContext(ctx, log) - if wrappableLogger, ok := currentLogger.(logger.WrappableLoggerInterface); ok { - logger.InjectInContext(ctx, wrappableLogger.Wrap( - middleware.Context( - logger.NewContext().Add(config.HeaderName, ctx.Value(config.HeaderName)), - ), - )) + loggerContextMiddleware := middleware.Context( + logger.NewContext().Add(config.HeaderName, ctx.Value(config.HeaderName)), + ) + var decoratedLogger logger.LoggerInterface + requestLogger := logger.FromContext(ctx, nil) + if requestLogger != nil { + if wrappableLogger, ok := requestLogger.(logger.WrappableLoggerInterface); ok { + decoratedLogger = wrappableLogger.Wrap(loggerContextMiddleware) + } else { + _ = log.Notice("logger not wrappable correlationId not added to request logger", nil) + } + } else { + decoratedLogger = log.WrapNew(loggerContextMiddleware) } + logger.InjectInContext(ctx, decoratedLogger) next.ServeHTTP(writer, req) })) } diff --git a/options.go b/options.go index 13953ff..2b2d1b9 100644 --- a/options.go +++ b/options.go @@ -19,8 +19,8 @@ type LoggerContextProvider func(*http.Request) *logger.Context // CodeToLevel function defines the mapping between http.StatusCode and logger.Level type CodeToLevel func(statusCode int) logger.Level -var ( - defaultOptions = &Options{ +func newDefaultOptions() *Options { + return &Options{ LoggerContextProvider: func(request *http.Request) *logger.Context { return logger.NewContext(). Add("http_header", request.Header). @@ -36,11 +36,10 @@ var ( return logger.ErrorLevel }, } -) +} func EvaluateClientOpt(opts ...Option) *Options { - optCopy := &Options{} - *optCopy = *defaultOptions + optCopy := newDefaultOptions() for _, o := range opts { o(optCopy) } @@ -48,8 +47,7 @@ func EvaluateClientOpt(opts ...Option) *Options { } func EvaluateServerOpt(opts ...Option) *Options { - optCopy := &Options{} - *optCopy = *defaultOptions + optCopy := newDefaultOptions() for _, o := range opts { o(optCopy) } diff --git a/tripperware/correlation_id.go b/tripperware/correlation_id.go index 7012542..00fe973 100644 --- a/tripperware/correlation_id.go +++ b/tripperware/correlation_id.go @@ -5,26 +5,34 @@ import ( "github.com/gol4ng/httpware/v2" "github.com/gol4ng/httpware/v2/correlation_id" - tripperware2 "github.com/gol4ng/httpware/v2/tripperware" + http_tripperware "github.com/gol4ng/httpware/v2/tripperware" "github.com/gol4ng/logger" "github.com/gol4ng/logger/middleware" ) // CorrelationId will decorate the http.Handler to add support of gol4ng/logger -func CorrelationId(log logger.LoggerInterface, options ...correlation_id.Option) httpware.Tripperware { +func CorrelationId(log logger.WrappableLoggerInterface, options ...correlation_id.Option) httpware.Tripperware { config := correlation_id.GetConfig(options...) - orig := tripperware2.CorrelationId(options...) + orig := http_tripperware.CorrelationId(options...) return func(next http.RoundTripper) http.RoundTripper { return orig(httpware.RoundTripFunc(func(req *http.Request) (resp *http.Response, err error) { ctx := req.Context() - currentLogger := logger.FromContext(ctx, log) - if wrappableLogger, ok := currentLogger.(logger.WrappableLoggerInterface); ok { - logger.InjectInContext(ctx, wrappableLogger.Wrap( - middleware.Context( - logger.NewContext().Add(config.HeaderName, ctx.Value(config.HeaderName)), - ), - )) + loggerContextMiddleware := middleware.Context( + logger.NewContext().Add(config.HeaderName, ctx.Value(config.HeaderName)), + ) + var decoratedLogger logger.LoggerInterface + requestLogger := logger.FromContext(ctx, nil) + if requestLogger != nil { + if wrappableLogger, ok := requestLogger.(logger.WrappableLoggerInterface); ok { + decoratedLogger = wrappableLogger.Wrap(loggerContextMiddleware) + } else { + _ = log.Notice("logger not wrappable correlationId not added to request logger", nil) + } + } else { + decoratedLogger = log.WrapNew(loggerContextMiddleware) } + logger.InjectInContext(ctx, decoratedLogger) + return next.RoundTrip(req) })) } From 1278100ad8041063bd24cba5564c02f0419009f7 Mon Sep 17 00:00:00 2001 From: Anthony Moutte Date: Fri, 13 Dec 2019 09:03:21 +0100 Subject: [PATCH 4/5] inject logger --- README.md | 100 ++++++++++++++-- helpers.go | 14 +++ middleware/correlation_id.go | 34 ++++-- middleware/correlation_id_test.go | 182 +++++++++++++++++++++++++++++ middleware/inject_logger.go | 30 +++++ middleware/inject_logger_test.go | 56 +++++++++ middleware/logger.go | 6 +- middleware/logger_test.go | 79 ++++++------- mocks/RoundTripper.go | 34 ++++++ options.go | 13 ++- tripperware/correlation_id.go | 39 ++++--- tripperware/correlation_id_test.go | 178 ++++++++++++++++++++++++++++ tripperware/inject_logger.go | 21 ++++ tripperware/inject_logger_test.go | 64 ++++++++++ tripperware/logger.go | 3 +- tripperware/logger_test.go | 54 ++++----- 16 files changed, 802 insertions(+), 105 deletions(-) create mode 100644 helpers.go create mode 100644 middleware/correlation_id_test.go create mode 100644 middleware/inject_logger.go create mode 100644 middleware/inject_logger_test.go create mode 100644 mocks/RoundTripper.go create mode 100644 tripperware/correlation_id_test.go create mode 100644 tripperware/inject_logger.go create mode 100644 tripperware/inject_logger_test.go diff --git a/README.md b/README.md index b52b3c9..625b23f 100644 --- a/README.md +++ b/README.md @@ -3,7 +3,8 @@ [![Build Status](https://travis-ci.org/gol4ng/logger-http.svg?branch=master)](https://travis-ci.org/gol4ng/logger-http) [![GoDoc](https://godoc.org/github.com/gol4ng/logger-http?status.svg)](https://godoc.org/github.com/gol4ng/logger-http) -Gol4ng logger sub package for http +Gol4ng logger sub package for logging http +Related package [gol4ng/logger](https://github.com/gol4ng/logger) and [gol4ng/httpware](https://github.com/gol4ng/httpware) ## Installation @@ -11,7 +12,18 @@ Gol4ng logger sub package for http ## Quick Start -Log you `http.Client` request +You can refer at [gol4ng/httpware](https://github.com/gol4ng/httpware) documentation for the middleware/tripperware usage + +### Tripperware + +Log you're `http.Client` request + +``` + http client gonna GET http://google.com {"http_url":"http://google.com","http_start_time":"2019-12-13T17:01:13+01:00","http_kind":"client","Correlation-Id":"yhyBI94zyl","http_header":{"Correlation-Id":["yhyBI94zyl"]},"http_method":"GET"} + http client GET http://google.com [status_code:301, duration:39.70726ms, content_length:219] {"Correlation-Id":"yhyBI94zyl","http_start_time":"2019-12-13T17:01:13+01:00","http_method":"GET","http_duration":0.03970726,"http_response_length":219,"http_header":{"Correlation-Id":["yhyBI94zyl"]},"http_url":"http://google.com","http_status":"301 Moved Permanently","http_status_code":301,"http_kind":"client"} + http client gonna GET http://www.google.com/ {"http_kind":"client","Correlation-Id":"uQzaMO9JC0","http_header":{"Correlation-Id":["uQzaMO9JC0"],"Referer":["http://google.com"]},"http_method":"GET","http_url":"http://www.google.com/","http_start_time":"2019-12-13T17:01:13+01:00"} + http client GET http://www.google.com/ [status_code:200, duration:72.582736ms, content_length:-1] {"Correlation-Id":"uQzaMO9JC0","http_header":{"Correlation-Id":["uQzaMO9JC0"],"Referer":["http://google.com"]},"http_method":"GET","http_kind":"client","http_response_length":-1,"http_duration":0.072582736,"http_status_code":200,"http_url":"http://www.google.com/","http_start_time":"2019-12-13T17:01:13+01:00","http_status":"200 OK"} +``` ```go package main @@ -20,8 +32,9 @@ import ( "net/http" "os" + "github.com/gol4ng/httpware/v2" "github.com/gol4ng/logger" - "github.com/gol4ng/logger-http" + "github.com/gol4ng/logger-http/tripperware" "github.com/gol4ng/logger/formatter" "github.com/gol4ng/logger/handler" ) @@ -30,15 +43,86 @@ func main(){ // logger will print on STDOUT with default line format myLogger := logger.NewLogger(handler.Stream(os.Stdout, formatter.NewDefaultFormatter())) + clientStack := httpware.TripperwareStack( + tripperware.InjectLogger(myLogger), + tripperware.CorrelationId(), + tripperware.Logger(myLogger), + ) + c := http.Client{ - Transport: logger_http.Tripperware(myLogger)(http.DefaultTransport), + Transport: clientStack.DecorateRoundTripper(http.DefaultTransport), } c.Get("http://google.com") - // Will log - // http client GET http://google.com [status_code:301, duration:27.524999ms, content_length:219] {"http_duration":0.027524999,"http_status":"301 Moved Permanently","http_status_code":301,"http_response_length":219,"http_method":"GET","http_url":"http://google.com","http_start_time":"2019-12-03T10:47:38+01:00","http_kind":"client"} - // http client GET http://www.google.com/ [status_code:200, duration:51.047002ms, content_length:-1] {"http_kind":"client","http_duration":0.051047002,"http_status":"200 OK","http_status_code":200,"http_response_length":-1,"http_method":"GET","http_url":"http://www.google.com/","http_start_time":"2019-12-03T10:47:38+01:00"} + // Will log + // http client GET http://google.com [status_code:301, duration:27.524999ms, content_length:219] {"http_duration":0.027524999,"http_status":"301 Moved Permanently","http_status_code":301,"http_response_length":219,"http_method":"GET","http_url":"http://google.com","http_start_time":"2019-12-03T10:47:38+01:00","http_kind":"client"} + // http client GET http://www.google.com/ [status_code:200, duration:51.047002ms, content_length:-1] {"http_kind":"client","http_duration":0.051047002,"http_status":"200 OK","http_status_code":200,"http_response_length":-1,"http_method":"GET","http_url":"http://www.google.com/","http_start_time":"2019-12-03T10:47:38+01:00"} } ``` -Log you incoming http server request +### Middleware +Log you're incoming http server request + +``` + http server received GET / {"http_url":"/","http_start_time":"2019-12-13T17:15:30+01:00","http_kind":"server","Correlation-Id":"SBeEdhRhUl","http_header":{"Accept-Encoding":["gzip"],"Correlation-Id":["SBeEdhRhUl"],"User-Agent":["Go-http-client/1.1"]},"http_method":"GET"} + handler log info {"Correlation-Id":"SBeEdhRhUl"} + http server GET / [status_code:200, duration:290.156µs, content_length:0] {"http_kind":"server","http_duration":0.000290156,"http_status_code":200,"Correlation-Id":"SBeEdhRhUl","http_method":"GET","http_url":"/","http_start_time":"2019-12-13T17:15:30+01:00","http_status":"OK","http_response_length":0,"http_header":{"Accept-Encoding":["gzip"],"Correlation-Id":["SBeEdhRhUl"],"User-Agent":["Go-http-client/1.1"]}} +``` + +```go +package main + + import ( + "context" + "net" + "net/http" + "os" + + "github.com/gol4ng/httpware/v2" + "github.com/gol4ng/logger" + "github.com/gol4ng/logger-http/middleware" + "github.com/gol4ng/logger/formatter" + "github.com/gol4ng/logger/handler" + ) + + func main() { + addr := ":5001" + + myLogger := logger.NewLogger( + handler.Stream(os.Stdout, formatter.NewDefaultFormatter()), + ) + + // we recommend to use MiddlewareStack to simplify managing all wanted middlewares + // caution middleware order matters + stack := httpware.MiddlewareStack( + //middleware.InjectLogger(myLogger), // we recommend to use http.Server.BaseContext instead of this middleware + middleware.CorrelationId(), + middleware.Logger(myLogger), + ) + + h := http.HandlerFunc(func(writer http.ResponseWriter, innerRequest *http.Request) { + l := logger.FromContext(innerRequest.Context(), myLogger) + l.Info("handler log info", nil) + }) + + server := http.Server{ + Addr: addr, + Handler: stack.DecorateHandler(h), + BaseContext: func(listener net.Listener) context.Context { + return logger.InjectInContext(context.Background(), myLogger) + }, + } + + go func() { + if err := server.ListenAndServe(); err != nil { + panic(err) + } + }() + + http.Get("http://localhost" + addr) + + // http server received GET / {"Correlation-Id":"zEDWO9gmZ6","http_header":{"Accept-Encoding":["gzip"],"Correlation-Id":["zEDWO9gmZ6"],"User-Agent":["Go-http-client/1.1"]},"http_method":"GET","http_url":"/","http_start_time":"2019-12-13T17:05:53+01:00","http_kind":"server"} + // handler log info {"Correlation-Id":"zEDWO9gmZ6"} + // http server GET / [status_code:200, duration:232.491µs, content_length:0] {"Correlation-Id":"zEDWO9gmZ6","http_header":{"Accept-Encoding":["gzip"],"Correlation-Id":["zEDWO9gmZ6"],"User-Agent":["Go-http-client/1.1"]},"http_method":"GET","http_url":"/","http_start_time":"2019-12-13T17:05:53+01:00","http_duration":0.000232491,"http_status":"OK","http_status_code":200,"http_kind":"server","http_response_length":0} + } +``` diff --git a/helpers.go b/helpers.go new file mode 100644 index 0000000..3952298 --- /dev/null +++ b/helpers.go @@ -0,0 +1,14 @@ +package logger_http + +import ( + "runtime" + "strconv" +) + +func MessageWithFileLine(message string, skip int) string { + _, file, line, ok := runtime.Caller(1 + skip) + if ok { + message += " a" + file + ":" + strconv.Itoa(line) + } + return message +} diff --git a/middleware/correlation_id.go b/middleware/correlation_id.go index 50580ae..1c5ff8a 100644 --- a/middleware/correlation_id.go +++ b/middleware/correlation_id.go @@ -1,6 +1,7 @@ package middleware import ( + "fmt" "net/http" "github.com/gol4ng/httpware/v2" @@ -8,30 +9,39 @@ import ( http_middleware "github.com/gol4ng/httpware/v2/middleware" "github.com/gol4ng/logger" "github.com/gol4ng/logger/middleware" + + logger_http "github.com/gol4ng/logger-http" ) -// CorrelationId will decorate the http.Handler to add support of gol4ng/logger -func CorrelationId(log logger.WrappableLoggerInterface, options ...correlation_id.Option) httpware.Middleware { +// CorrelationId is a decoration of CorrelationId(github.com/gol4ng/httpware/v2/middleware) +// it will add correlationId to gol4ng/logger context +// this middleware require request context with a WrappableLoggerInterface in order to properly add +// correlationID to the logger context +// eg: +// stack := httpware.MiddlewareStack( +// middleware.InjectLogger(l), // << Inject logger before CorrelationId +// middleware.CorrelationId(), +// ) +func CorrelationId(options ...correlation_id.Option) httpware.Middleware { + warning := logger_http.MessageWithFileLine("correlationId need a wrappable logger", 1) config := correlation_id.GetConfig(options...) orig := http_middleware.CorrelationId(options...) return func(next http.Handler) http.Handler { return orig(http.HandlerFunc(func(writer http.ResponseWriter, req *http.Request) { ctx := req.Context() - loggerContextMiddleware := middleware.Context( - logger.NewContext().Add(config.HeaderName, ctx.Value(config.HeaderName)), - ) - var decoratedLogger logger.LoggerInterface requestLogger := logger.FromContext(ctx, nil) + injected := false if requestLogger != nil { if wrappableLogger, ok := requestLogger.(logger.WrappableLoggerInterface); ok { - decoratedLogger = wrappableLogger.Wrap(loggerContextMiddleware) - } else { - _ = log.Notice("logger not wrappable correlationId not added to request logger", nil) + req = req.WithContext(logger.InjectInContext(ctx, wrappableLogger.WrapNew(middleware.Context( + logger.NewContext().Add(config.HeaderName, ctx.Value(config.HeaderName)), + )))) + injected = true } - } else { - decoratedLogger = log.WrapNew(loggerContextMiddleware) } - logger.InjectInContext(ctx, decoratedLogger) + if !injected { + fmt.Println(warning) + } next.ServeHTTP(writer, req) })) } diff --git a/middleware/correlation_id_test.go b/middleware/correlation_id_test.go new file mode 100644 index 0000000..abb9138 --- /dev/null +++ b/middleware/correlation_id_test.go @@ -0,0 +1,182 @@ +package middleware_test + +import ( + "bytes" + "fmt" + "io" + "math/rand" + "net/http" + "net/http/httptest" + "os" + "sync" + "testing" + + "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" + "github.com/stretchr/testify/assert" + + http_middleware "github.com/gol4ng/logger-http/middleware" +) + +func TestCorrelationId(t *testing.T) { + correlation_id.DefaultIdGenerator = correlation_id.NewRandomIdGenerator( + rand.New(correlation_id.NewLockedSource(rand.NewSource(1))), + ) + + loggerOutput := &Output{} + myLogger := logger.NewLogger( + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), + ) + + request := httptest.NewRequest(http.MethodGet, "http://fake-addr", nil) + request = request.WithContext(logger.InjectInContext(request.Context(), myLogger)) + responseWriter := &httptest.ResponseRecorder{} + + var handlerRequest *http.Request + h := http.HandlerFunc(func(writer http.ResponseWriter, innerRequest *http.Request) { + // not equal because request.WithContext create another request object + 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) + }) + + myLogger.Info("info log before request", logger.NewContext().Add("ctxvalue", "before")) + http_middleware.CorrelationId()(h).ServeHTTP(responseWriter, request) + myLogger.Info("info log after request", logger.NewContext().Add("ctxvalue", "after")) + + respHeaderValue := responseWriter.Header().Get(correlation_id.HeaderName) + reqContextValue := handlerRequest.Context().Value(correlation_id.HeaderName).(string) + assert.Equal(t, "p1LGIehp1s", request.Header.Get(correlation_id.HeaderName)) + 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"}`, + }) +} + +func TestCorrelationId_WithoutWrappableLogger(t *testing.T) { + correlation_id.DefaultIdGenerator = correlation_id.NewRandomIdGenerator( + rand.New(correlation_id.NewLockedSource(rand.NewSource(1))), + ) + + loggerOutput := &Output{} + myLogger := logger.NewLogger( + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), + ) + + request := httptest.NewRequest(http.MethodGet, "http://fake-addr", nil) + // WE DO NOT INJECT LOGGER IN REQUEST CONTEXT + //request = request.WithContext(logger.InjectInContext(request.Context(), myLogger)) + responseRecorder := &httptest.ResponseRecorder{} + + var handlerRequest *http.Request + h := http.HandlerFunc(func(writer http.ResponseWriter, innerRequest *http.Request) { + // not equal because request.WithContext create another request object + assert.NotEqual(t, request, innerRequest) + assert.Equal(t, "p1LGIehp1s", innerRequest.Header.Get(correlation_id.HeaderName)) + handlerRequest = innerRequest + assert.Nil(t, logger.FromContext(innerRequest.Context(), nil)) + }) + + myLogger.Info("info log before request", logger.NewContext().Add("ctxvalue", "before")) + output := getStdout(func() { + http_middleware.CorrelationId()(h).ServeHTTP(responseRecorder, request) + }) + myLogger.Info("info log after request", logger.NewContext().Add("ctxvalue", "after")) + + respHeaderValue := responseRecorder.Header().Get(correlation_id.HeaderName) + reqContextValue := handlerRequest.Context().Value(correlation_id.HeaderName).(string) + assert.Equal(t, "p1LGIehp1s", request.Header.Get(correlation_id.HeaderName)) + assert.True(t, len(respHeaderValue) == 10) + assert.True(t, len(reqContextValue) == 10) + assert.True(t, respHeaderValue == reqContextValue) + 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"}`, + }) +} + +// Use to get os.Stdout +var mu = sync.Mutex{} + +func lock() func() { + mu.Lock() + return func() { + mu.Unlock() + } +} + +func getStdout(f func()) string { + defer lock()() + // keep original os.Stdout + orig := os.Stdout + r, w, err := os.Pipe() + if err != nil { + panic(err) + } + // replace os.Stdout + os.Stdout = w + defer func() { + os.Stdout = orig + }() + + f() + w.Close() + + var buf bytes.Buffer + io.Copy(&buf, r) + + return buf.String() +} + +// ===================================================================================================================== +// ========================================= EXAMPLES ================================================================== +// ===================================================================================================================== + +func ExampleCorrelationId() { + port := ":5001" + + myLogger := logger.NewLogger( + handler.Stream(os.Stdout, formatter.NewDefaultFormatter()), + ) + + // we recommend to use MiddlewareStack to simplify managing all wanted middlewares + // caution middleware order matters + stack := httpware.MiddlewareStack( + http_middleware.InjectLogger(myLogger), + http_middleware.CorrelationId( + correlation_id.WithHeaderName("my-personal-header-name"), + correlation_id.WithIdGenerator(func(request *http.Request) string { + return "my-fixed-request-id" + }), + ), + ) + + h := http.HandlerFunc(func(writer http.ResponseWriter, innerRequest *http.Request) { + l := logger.FromContext(innerRequest.Context(), myLogger) + l.Info("handler log info", nil) + }) + + go func() { + if err := http.ListenAndServe(port, stack.DecorateHandler(h)); err != nil { + panic(err) + } + }() + + resp, err := http.Get("http://localhost" + port) + fmt.Printf("%s: %v %v\n", "my-personal-header-name", resp.Header.Get("my-personal-header-name"), err) + + //Output: + // handler log info {"my-personal-header-name":"my-fixed-request-id"} + // my-personal-header-name: my-fixed-request-id +} diff --git a/middleware/inject_logger.go b/middleware/inject_logger.go new file mode 100644 index 0000000..4fb8ac4 --- /dev/null +++ b/middleware/inject_logger.go @@ -0,0 +1,30 @@ +package middleware + +import ( + "net/http" + + "github.com/gol4ng/httpware/v2" + "github.com/gol4ng/logger" +) + +// InjectLogger will inject logger on request context if not exist +// this injection is made for every incoming request so prefer to +// use http.Server in order to create base context +// eg: +// server := &http.Server{ +// BaseContext: func(listener net.Listener) context.Context { +// return logger.InjectInContext(context.Background(), l) +// }, +// ... +// } +func InjectLogger(log logger.LoggerInterface) httpware.Middleware { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(writer http.ResponseWriter, req *http.Request) { + ctx := req.Context() + if logger.FromContext(ctx, nil) == nil { + req = req.WithContext(logger.InjectInContext(ctx, log)) + } + next.ServeHTTP(writer, req) + }) + } +} diff --git a/middleware/inject_logger_test.go b/middleware/inject_logger_test.go new file mode 100644 index 0000000..7e2cfc3 --- /dev/null +++ b/middleware/inject_logger_test.go @@ -0,0 +1,56 @@ +package middleware_test + +import ( + "context" + "net/http" + "net/http/httptest" + "testing" + "time" + + "github.com/gol4ng/httpware/v2" + "github.com/gol4ng/logger" + "github.com/stretchr/testify/assert" + + "github.com/gol4ng/logger-http/middleware" +) + +func TestInjectLogger(t *testing.T) { + myLogger := logger.NewNopLogger() + + request := httptest.NewRequest(http.MethodGet, "http://127.0.0.1/my-fake-url", nil) + ctx, _ := context.WithTimeout(request.Context(), 3*time.Second) + request = request.WithContext(ctx) + responseWriter := &httptest.ResponseRecorder{} + + h := http.HandlerFunc(func(writer http.ResponseWriter, innerRequest *http.Request) { + requestLogger := logger.FromContext(innerRequest.Context(), nil) + // not equal because request.WithContext create another request object + assert.NotEqual(t, request, innerRequest) + assert.Equal(t, myLogger, requestLogger) + writer.Write([]byte(`OK`)) + }) + + middleware.InjectLogger(myLogger)(h).ServeHTTP(responseWriter, request) +} + +func TestInjectLogger_AlreadyInjected(t *testing.T) { + request := httptest.NewRequest(http.MethodGet, "http://127.0.0.1/my-fake-url", nil) + ctx, _ := context.WithTimeout(request.Context(), 3*time.Second) + request = request.WithContext(ctx) + responseWriter := &httptest.ResponseRecorder{} + + myLogger := logger.NewNopLogger() + myLogger2 := logger.NewNopLogger() + + h := func(writer http.ResponseWriter, innerRequest *http.Request) { + // not equal because request.WithContext create another request object + assert.NotEqual(t, request, innerRequest) + assert.Equal(t, myLogger, logger.FromContext(innerRequest.Context(), nil)) + writer.Write([]byte(`OK`)) + } + + httpware.MiddlewareStack( + middleware.InjectLogger(myLogger), + middleware.InjectLogger(myLogger2), // this tripperware not inject logger because logger already injected + ).DecorateHandlerFunc(h).ServeHTTP(responseWriter, request) +} diff --git a/middleware/logger.go b/middleware/logger.go index 4577812..61b3d13 100644 --- a/middleware/logger.go +++ b/middleware/logger.go @@ -6,11 +6,13 @@ import ( "time" "github.com/gol4ng/httpware/v2" - middleware2 "github.com/gol4ng/httpware/v2/middleware" + http_middleware "github.com/gol4ng/httpware/v2/middleware" "github.com/gol4ng/logger" + "github.com/gol4ng/logger-http" ) +// Logger will decorate the http.Handler to add support of gol4ng/logger func Logger(log logger.LoggerInterface, opts ...logger_http.Option) httpware.Middleware { o := logger_http.EvaluateServerOpt(opts...) return func(next http.Handler) http.Handler { @@ -21,7 +23,7 @@ func Logger(log logger.LoggerInterface, opts ...logger_http.Option) httpware.Mid currentLogger := logger.FromContext(ctx, log) currentLoggerContext := logger_http.FeedContext(o.LoggerContextProvider(req), ctx, req, startTime).Add("http_kind", "server") - writerInterceptor := middleware2.NewResponseWriterInterceptor(writer) + writerInterceptor := http_middleware.NewResponseWriterInterceptor(writer) defer func() { duration := time.Since(startTime) currentLoggerContext.Add("http_duration", duration.Seconds()) diff --git a/middleware/logger_test.go b/middleware/logger_test.go index 5eb8086..e4f27d2 100644 --- a/middleware/logger_test.go +++ b/middleware/logger_test.go @@ -11,32 +11,33 @@ import ( "time" "github.com/gol4ng/logger" - "github.com/gol4ng/logger-http" - "github.com/gol4ng/logger-http/middleware" "github.com/gol4ng/logger/formatter" "github.com/gol4ng/logger/handler" "github.com/stretchr/testify/assert" + + "github.com/gol4ng/logger-http" + "github.com/gol4ng/logger-http/middleware" ) -func TestMiddleware(t *testing.T) { - req := httptest.NewRequest(http.MethodGet, "http://127.0.0.1/my-fake-url", nil) - ctx, _ := context.WithTimeout(req.Context(), 3*time.Second) - req = req.WithContext(ctx) +func TestLogger(t *testing.T) { + request := httptest.NewRequest(http.MethodGet, "http://127.0.0.1/my-fake-url", nil) + ctx, _ := context.WithTimeout(request.Context(), 3*time.Second) + request = request.WithContext(ctx) responseWriter := &httptest.ResponseRecorder{} - h := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - // not equal because req.WithContext create another request object - assert.NotEqual(t, responseWriter, w) - w.Write([]byte(`OK`)) + h := http.HandlerFunc(func(writer http.ResponseWriter, innerRequest *http.Request) { + // not equal because request.WithContext create another request object + assert.NotEqual(t, responseWriter, writer) + writer.Write([]byte(`OK`)) }) - output := &Output{} + loggerOutput := &Output{} myLogger := logger.NewLogger( - handler.Stream(output, formatter.NewDefaultFormatter()), + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), ) - middleware.Logger(myLogger)(h).ServeHTTP(responseWriter, req) - output.Constains(t, []string{ + 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"`, @@ -52,7 +53,7 @@ func TestMiddleware(t *testing.T) { }) } -func TestMiddleware_WithPanic(t *testing.T) { +func TestLogger_WithPanic(t *testing.T) { req := httptest.NewRequest(http.MethodGet, "http://127.0.0.1/my-fake-url", nil) ctx, _ := context.WithTimeout(req.Context(), 3*time.Second) req = req.WithContext(ctx) @@ -83,28 +84,28 @@ func TestMiddleware_WithPanic(t *testing.T) { }) } -func TestMiddleware_WithContext(t *testing.T) { - req := httptest.NewRequest(http.MethodGet, "http://127.0.0.1/my-fake-url", nil) - ctx, _ := context.WithTimeout(req.Context(), 3*time.Second) - req = req.WithContext(ctx) +func TestLogger_WithContext(t *testing.T) { + request := httptest.NewRequest(http.MethodGet, "http://127.0.0.1/my-fake-url", nil) + ctx, _ := context.WithTimeout(request.Context(), 3*time.Second) + request = request.WithContext(ctx) responseWriter := &httptest.ResponseRecorder{} - h := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - // not equal because req.WithContext create another request object - assert.NotEqual(t, responseWriter, w) - w.Write([]byte(`OK`)) + h := http.HandlerFunc(func(writer http.ResponseWriter, innerRequest *http.Request) { + // not equal because request.WithContext create another request object + assert.NotEqual(t, responseWriter, writer) + writer.Write([]byte(`OK`)) }) - output := &Output{} + loggerOutput := &Output{} myLogger := logger.NewLogger( - handler.Stream(output, formatter.NewDefaultFormatter()), + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), ) 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, req) + }))(h).ServeHTTP(responseWriter, request) - output.Constains(t, []string{ + 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"`, @@ -121,28 +122,28 @@ func TestMiddleware_WithContext(t *testing.T) { }) } -func TestMiddleware_WithLevels(t *testing.T) { - req := httptest.NewRequest(http.MethodGet, "http://127.0.0.1/my-fake-url", nil) - ctx, _ := context.WithTimeout(req.Context(), 3*time.Second) - req = req.WithContext(ctx) +func TestLogger_WithLevels(t *testing.T) { + request := httptest.NewRequest(http.MethodGet, "http://127.0.0.1/my-fake-url", nil) + ctx, _ := context.WithTimeout(request.Context(), 3*time.Second) + request = request.WithContext(ctx) responseWriter := &httptest.ResponseRecorder{} - h := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - // not equal because req.WithContext create another request object - assert.NotEqual(t, responseWriter, w) - w.Write([]byte(`OK`)) + h := http.HandlerFunc(func(writer http.ResponseWriter, innerRequest *http.Request) { + // not equal because request.WithContext create another request object + assert.NotEqual(t, responseWriter, writer) + writer.Write([]byte(`OK`)) }) - output := &Output{} + loggerOutput := &Output{} myLogger := logger.NewLogger( - handler.Stream(output, formatter.NewDefaultFormatter()), + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), ) middleware.Logger(myLogger, logger_http.WithLevels(func(statusCode int) logger.Level { return logger.EmergencyLevel - }))(h).ServeHTTP(responseWriter, req) + }))(h).ServeHTTP(responseWriter, request) - output.Constains(t, []string{ + 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"`, diff --git a/mocks/RoundTripper.go b/mocks/RoundTripper.go new file mode 100644 index 0000000..4324c4c --- /dev/null +++ b/mocks/RoundTripper.go @@ -0,0 +1,34 @@ +// Code generated by mockery v1.0.0. DO NOT EDIT. + +package mocks + +import http "net/http" +import mock "github.com/stretchr/testify/mock" + +// RoundTripper is an autogenerated mock type for the RoundTripper type +type RoundTripper struct { + mock.Mock +} + +// RoundTrip provides a mock function with given fields: _a0 +func (_m *RoundTripper) RoundTrip(_a0 *http.Request) (*http.Response, error) { + ret := _m.Called(_a0) + + var r0 *http.Response + if rf, ok := ret.Get(0).(func(*http.Request) *http.Response); ok { + r0 = rf(_a0) + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).(*http.Response) + } + } + + var r1 error + if rf, ok := ret.Get(1).(func(*http.Request) error); ok { + r1 = rf(_a0) + } else { + r1 = ret.Error(1) + } + + return r0, r1 +} diff --git a/options.go b/options.go index 2b2d1b9..9fcf308 100644 --- a/options.go +++ b/options.go @@ -22,9 +22,7 @@ type CodeToLevel func(statusCode int) logger.Level func newDefaultOptions() *Options { return &Options{ LoggerContextProvider: func(request *http.Request) *logger.Context { - return logger.NewContext(). - Add("http_header", request.Header). - Add("http_body", request.GetBody) + return logger.NewContext().Add("http_header", request.Header) }, LevelFunc: func(statusCode int) logger.Level { switch { @@ -40,6 +38,15 @@ func newDefaultOptions() *Options { func EvaluateClientOpt(opts ...Option) *Options { optCopy := newDefaultOptions() + baseOptCopy := optCopy.LoggerContextProvider + optCopy.LoggerContextProvider = func(request *http.Request) *logger.Context { + ctx := baseOptCopy(request) + // TODO + //if reader, err := request.GetBody(); err == nil { + // ctx.Add("http_body", reader.Read()) + //} + return ctx + } for _, o := range opts { o(optCopy) } diff --git a/tripperware/correlation_id.go b/tripperware/correlation_id.go index 00fe973..2d00832 100644 --- a/tripperware/correlation_id.go +++ b/tripperware/correlation_id.go @@ -1,6 +1,7 @@ package tripperware import ( + "fmt" "net/http" "github.com/gol4ng/httpware/v2" @@ -8,31 +9,43 @@ import ( http_tripperware "github.com/gol4ng/httpware/v2/tripperware" "github.com/gol4ng/logger" "github.com/gol4ng/logger/middleware" + + logger_http "github.com/gol4ng/logger-http" ) -// CorrelationId will decorate the http.Handler to add support of gol4ng/logger -func CorrelationId(log logger.WrappableLoggerInterface, options ...correlation_id.Option) httpware.Tripperware { +// CorrelationId is a decoration of CorrelationId(github.com/gol4ng/httpware/v2/tripperware) +// it will add correlationId to gol4ng/logger context +// this tripperware require request context with a WrappableLoggerInterface in order to properly add +// correlationID to the logger context +// eg: +// stack := httpware.TripperwareStack( +// tripperware.InjectLogger(l), // << Inject logger before CorrelationId +// tripperware.CorrelationId(), +// ) +// OR +// ctx := logger.InjectInContext(context.Background(), yourWrappableLogger) +// req, _ := http.NewRequestWithContext(ctx, http.MethodGet, "http://a.zz.fr", nil) +// http.Client{}.Do(req) +func CorrelationId(options ...correlation_id.Option) httpware.Tripperware { + warning := logger_http.MessageWithFileLine("correlationId need a wrappable logger", 1) config := correlation_id.GetConfig(options...) orig := http_tripperware.CorrelationId(options...) return func(next http.RoundTripper) http.RoundTripper { return orig(httpware.RoundTripFunc(func(req *http.Request) (resp *http.Response, err error) { ctx := req.Context() - loggerContextMiddleware := middleware.Context( - logger.NewContext().Add(config.HeaderName, ctx.Value(config.HeaderName)), - ) - var decoratedLogger logger.LoggerInterface requestLogger := logger.FromContext(ctx, nil) + injected := false if requestLogger != nil { if wrappableLogger, ok := requestLogger.(logger.WrappableLoggerInterface); ok { - decoratedLogger = wrappableLogger.Wrap(loggerContextMiddleware) - } else { - _ = log.Notice("logger not wrappable correlationId not added to request logger", nil) + req = req.WithContext(logger.InjectInContext(ctx, wrappableLogger.WrapNew(middleware.Context( + logger.NewContext().Add(config.HeaderName, ctx.Value(config.HeaderName)), + )))) + injected = true } - } else { - decoratedLogger = log.WrapNew(loggerContextMiddleware) } - logger.InjectInContext(ctx, decoratedLogger) - + if !injected { + fmt.Println(warning) + } return next.RoundTrip(req) })) } diff --git a/tripperware/correlation_id_test.go b/tripperware/correlation_id_test.go new file mode 100644 index 0000000..ec425e5 --- /dev/null +++ b/tripperware/correlation_id_test.go @@ -0,0 +1,178 @@ +package tripperware_test + +import ( + "bytes" + "io" + "math/rand" + "net/http" + "net/http/httptest" + "os" + "sync" + "testing" + + "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" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/mock" + + "github.com/gol4ng/logger-http/mocks" + "github.com/gol4ng/logger-http/tripperware" +) + +func TestCorrelationId(t *testing.T) { + correlation_id.DefaultIdGenerator = correlation_id.NewRandomIdGenerator( + rand.New(correlation_id.NewLockedSource(rand.NewSource(1))), + ) + + loggerOutput := &Output{} + myLogger := logger.NewLogger( + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), + ) + + roundTripperMock := &mocks.RoundTripper{} + request := httptest.NewRequest(http.MethodPost, "http://fake-addr", nil) + request = request.WithContext(logger.InjectInContext(request.Context(), myLogger)) + response := &http.Response{ + Status: "OK", + StatusCode: http.StatusOK, + ContentLength: 30, + } + + var handlerReq *http.Request + roundTripperMock.On("RoundTrip", mock.AnythingOfType("*http.Request")).Return(response, nil).Run(func(args mock.Arguments) { + innerRequest := args.Get(0).(*http.Request) + 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) + }) + + myLogger.Info("info log before request", logger.NewContext().Add("ctxvalue", "before")) + resultResponse, err := tripperware.CorrelationId()(roundTripperMock).RoundTrip(request) + myLogger.Info("info log after request", logger.NewContext().Add("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"}`, + }) +} + +func TestCorrelationId_WithoutWrappableLogger(t *testing.T) { + correlation_id.DefaultIdGenerator = correlation_id.NewRandomIdGenerator( + rand.New(correlation_id.NewLockedSource(rand.NewSource(1))), + ) + + loggerOutput := &Output{} + myLogger := logger.NewLogger( + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), + ) + + roundTripperMock := &mocks.RoundTripper{} + request := httptest.NewRequest(http.MethodPost, "http://fake-addr", nil) + // WE DO NOT INJECT LOGGER IN REQUEST CONTEXT + //request = request.WithContext(logger.InjectInContext(request.Context(), myLogger)) + response := &http.Response{ + Status: "OK", + StatusCode: http.StatusOK, + ContentLength: 30, + } + + var handlerRequest *http.Request + roundTripperMock.On("RoundTrip", mock.AnythingOfType("*http.Request")).Return(response, nil).Run(func(args mock.Arguments) { + innerRequest := args.Get(0).(*http.Request) + assert.NotEqual(t, request, innerRequest) + assert.Equal(t, "p1LGIehp1s", innerRequest.Header.Get(correlation_id.HeaderName)) + handlerRequest = innerRequest + assert.Nil(t, logger.FromContext(innerRequest.Context(), nil)) + }) + + var resultResponse *http.Response + var err error + myLogger.Info("info log before request", logger.NewContext().Add("ctxvalue", "before")) + output := getStdout(func() { + resultResponse, err = tripperware.CorrelationId()(roundTripperMock).RoundTrip(request) + }) + myLogger.Info("info log after request", logger.NewContext().Add("ctxvalue", "after")) + + assert.Nil(t, err) + assert.Equal(t, response, resultResponse) + assert.Equal(t, "p1LGIehp1s", handlerRequest.Header.Get(correlation_id.HeaderName)) + assert.Equal(t, "", response.Header.Get(correlation_id.HeaderName)) + 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"}`, + }) +} + +// Use to get os.Stdout +var mu = sync.Mutex{} + +func lock() func() { + mu.Lock() + return func() { + mu.Unlock() + } +} + +func getStdout(f func()) string { + defer lock()() + // keep original os.Stdout + orig := os.Stdout + r, w, err := os.Pipe() + if err != nil { + panic(err) + } + // replace os.Stdout + os.Stdout = w + defer func() { + os.Stdout = orig + }() + + f() + w.Close() + + var buf bytes.Buffer + io.Copy(&buf, r) + + return buf.String() +} + +// ===================================================================================================================== +// ========================================= EXAMPLES ================================================================== +// ===================================================================================================================== + +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()), + ) + + clientStack := httpware.TripperwareStack( + tripperware.InjectLogger(myLogger), + tripperware.CorrelationId( + correlation_id.WithHeaderName("my-personal-header-name"), + correlation_id.WithIdGenerator(func(request *http.Request) string { + return "my-fixed-request-id" + }), + ), + ) + + c := http.Client{ + Transport: clientStack.DecorateRoundTripper(http.DefaultTransport), + } + + c.Get("http://google.com") + // Output: +} diff --git a/tripperware/inject_logger.go b/tripperware/inject_logger.go new file mode 100644 index 0000000..9eae52a --- /dev/null +++ b/tripperware/inject_logger.go @@ -0,0 +1,21 @@ +package tripperware + +import ( + "net/http" + + "github.com/gol4ng/httpware/v2" + "github.com/gol4ng/logger" +) + +// InjectLogger will inject logger on request context if not exist +func InjectLogger(log logger.LoggerInterface) httpware.Tripperware { + return func(next http.RoundTripper) http.RoundTripper { + return httpware.RoundTripFunc(func(req *http.Request) (resp *http.Response, err error) { + ctx := req.Context() + if logger.FromContext(ctx, nil) == nil { + req = req.WithContext(logger.InjectInContext(ctx, log)) + } + return next.RoundTrip(req) + }) + } +} diff --git a/tripperware/inject_logger_test.go b/tripperware/inject_logger_test.go new file mode 100644 index 0000000..c48078b --- /dev/null +++ b/tripperware/inject_logger_test.go @@ -0,0 +1,64 @@ +package tripperware_test + +import ( + "net/http" + "net/http/httptest" + "testing" + + "github.com/gol4ng/httpware/v2" + "github.com/gol4ng/logger" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/mock" + + "github.com/gol4ng/logger-http/mocks" + "github.com/gol4ng/logger-http/tripperware" +) + +func TestInjectLogger(t *testing.T) { + myLogger := logger.NewNopLogger() + + roundTripperMock := &mocks.RoundTripper{} + req := httptest.NewRequest(http.MethodPost, "http://fake-addr", nil) + resp := &http.Response{ + Status: "OK", + StatusCode: http.StatusOK, + ContentLength: 30, + } + + roundTripperMock.On("RoundTrip", mock.AnythingOfType("*http.Request")).Return(resp, nil).Run(func(args mock.Arguments) { + innerReq := args.Get(0).(*http.Request) + assert.Equal(t, myLogger, logger.FromContext(innerReq.Context(), nil)) + }) + + resp2, err := tripperware.InjectLogger(myLogger)(roundTripperMock).RoundTrip(req) + assert.Nil(t, err) + assert.Equal(t, resp, resp2) +} + +func TestInjectLogger_AlreadyInjected(t *testing.T) { + myLogger := logger.NewNopLogger() + myLogger2 := logger.NewNopLogger() + + roundTripperMock := &mocks.RoundTripper{} + request := httptest.NewRequest(http.MethodPost, "http://fake-addr", nil) + response := &http.Response{ + Status: "OK", + StatusCode: http.StatusOK, + ContentLength: 30, + } + + roundTripperMock.On("RoundTrip", mock.AnythingOfType("*http.Request")).Return(response, nil).Run(func(args mock.Arguments) { + innerRequest := args.Get(0).(*http.Request) + // not equal because request.WithContext create another request object + assert.NotEqual(t, request, innerRequest) + assert.Equal(t, myLogger, logger.FromContext(innerRequest.Context(), nil)) + }) + + stack := httpware.TripperwareStack( + tripperware.InjectLogger(myLogger), + tripperware.InjectLogger(myLogger2), // this tripperware not inject logger because logger already injected + ) + resultResponse, err := stack.DecorateRoundTripper(roundTripperMock).RoundTrip(request) + assert.Nil(t, err) + assert.Equal(t, response, resultResponse) +} diff --git a/tripperware/logger.go b/tripperware/logger.go index c74c933..046f3eb 100644 --- a/tripperware/logger.go +++ b/tripperware/logger.go @@ -7,10 +7,11 @@ import ( "github.com/gol4ng/httpware/v2" "github.com/gol4ng/logger" + "github.com/gol4ng/logger-http" ) -// Tripperware will decorate the http.Client Transport to add support of gol4ng/logger +// Logger will decorate the http.Client to add support of gol4ng/logger func Logger(log logger.LoggerInterface, opts ...logger_http.Option) func(next http.RoundTripper) http.RoundTripper { o := logger_http.EvaluateClientOpt(opts...) return func(next http.RoundTripper) http.RoundTripper { diff --git a/tripperware/logger_test.go b/tripperware/logger_test.go index bfdf588..20c6273 100644 --- a/tripperware/logger_test.go +++ b/tripperware/logger_test.go @@ -10,14 +10,14 @@ import ( "testing" "time" + "github.com/stretchr/testify/assert" "github.com/gol4ng/httpware/v2" "github.com/gol4ng/logger" - "github.com/gol4ng/logger-http/tripperware" "github.com/gol4ng/logger/formatter" "github.com/gol4ng/logger/handler" - "github.com/stretchr/testify/assert" "github.com/gol4ng/logger-http" + "github.com/gol4ng/logger-http/tripperware" ) func TestTripperware(t *testing.T) { @@ -27,9 +27,9 @@ func TestTripperware(t *testing.T) { })) defer server.Close() - output := &Output{} + loggerOutput := &Output{} myLogger := logger.NewLogger( - handler.Stream(output, formatter.NewDefaultFormatter()), + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), ) c := http.Client{ @@ -38,11 +38,11 @@ func TestTripperware(t *testing.T) { ctx := context.Background() ctx, _ = context.WithTimeout(ctx, 3*time.Second) - req, _ := http.NewRequestWithContext(ctx, http.MethodGet, server.URL+"/my-fake-url", nil) + request, _ := http.NewRequestWithContext(ctx, http.MethodGet, server.URL+"/my-fake-url", nil) - _, err := c.Do(req) + _, err := c.Do(request) assert.Nil(t, err) - output.Constains(t, []string{ + loggerOutput.Constains(t, []string{ ` http client GET http://127.0.0.1`, `/my-fake-url [status_code:200, duration:`, `content_length:2] {`, @@ -65,9 +65,9 @@ func TestTripperware_WithError(t *testing.T) { })) defer server.Close() - output := &Output{} + loggerOutput := &Output{} myLogger := logger.NewLogger( - handler.Stream(output, formatter.NewDefaultFormatter()), + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), ) c := http.Client{ @@ -76,11 +76,11 @@ func TestTripperware_WithError(t *testing.T) { ctx := context.Background() ctx, _ = context.WithTimeout(ctx, 3*time.Second) - req, _ := http.NewRequestWithContext(ctx, http.MethodGet, "http://a.zz/my-fake-url", nil) + request, _ := http.NewRequestWithContext(ctx, http.MethodGet, "http://a.zz/my-fake-url", nil) - _, err := c.Do(req) + _, err := c.Do(request) assert.Contains(t, err.Error(), "no such host") - output.Constains(t, []string{ + loggerOutput.Constains(t, []string{ ` http client error GET http://a.zz/my-fake-url [duration:`, `dial tcp: lookup a.zz`, `no such host`, @@ -103,9 +103,9 @@ func TestTripperware_WithPanic(t *testing.T) { })) defer server.Close() - output := &Output{} + loggerOutput := &Output{} myLogger := logger.NewLogger( - handler.Stream(output, formatter.NewDefaultFormatter()), + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), ) transportPanic := httpware.RoundTripFunc(func(req *http.Request) (*http.Response, error) { @@ -118,12 +118,12 @@ func TestTripperware_WithPanic(t *testing.T) { assert.Panics(t, func() { ctx := context.Background() ctx, _ = context.WithTimeout(ctx, 3*time.Second) - req, _ := http.NewRequestWithContext(ctx, http.MethodGet, "http://a.zz/my-fake-url", nil) + request, _ := http.NewRequestWithContext(ctx, http.MethodGet, "http://a.zz/my-fake-url", nil) - c.Do(req) + c.Do(request) }) - output.Constains(t, []string{ + loggerOutput.Constains(t, []string{ ` http client panic GET http://a.zz/my-fake-url [duration:`, `"http_kind":"client"`, `"http_method":"GET"`, @@ -143,9 +143,9 @@ func TestTripperware_WithContext(t *testing.T) { })) defer server.Close() - output := &Output{} + loggerOutput := &Output{} myLogger := logger.NewLogger( - handler.Stream(output, formatter.NewDefaultFormatter()), + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), ) c := http.Client{ @@ -156,11 +156,11 @@ func TestTripperware_WithContext(t *testing.T) { ctx := context.Background() ctx, _ = context.WithTimeout(ctx, 3*time.Second) - req, _ := http.NewRequestWithContext(ctx, http.MethodGet, server.URL+"/my-fake-url", nil) + request, _ := http.NewRequestWithContext(ctx, http.MethodGet, server.URL+"/my-fake-url", nil) - _, err := c.Do(req) + _, err := c.Do(request) assert.Nil(t, err) - output.Constains(t, []string{ + loggerOutput.Constains(t, []string{ ` http client GET http://127.0.0.1`, `/my-fake-url [status_code:200, duration:`, `content_length:2] {`, @@ -185,9 +185,9 @@ func TestTripperware_WithLevels(t *testing.T) { })) defer server.Close() - output := &Output{} + loggerOutput := &Output{} myLogger := logger.NewLogger( - handler.Stream(output, formatter.NewDefaultFormatter()), + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), ) c := http.Client{ @@ -198,11 +198,11 @@ func TestTripperware_WithLevels(t *testing.T) { ctx := context.Background() ctx, _ = context.WithTimeout(ctx, 3*time.Second) - req, _ := http.NewRequestWithContext(ctx, http.MethodGet, server.URL+"/my-fake-url", nil) + request, _ := http.NewRequestWithContext(ctx, http.MethodGet, server.URL+"/my-fake-url", nil) - _, err := c.Do(req) + _, err := c.Do(request) assert.Nil(t, err) - output.Constains(t, []string{ + loggerOutput.Constains(t, []string{ ` http client GET http://127.0.0.1`, `/my-fake-url [status_code:200, duration:`, `content_length:2] {`, From 378fc8dd2b0ca82cf93c5c82797a91ce80d6ac57 Mon Sep 17 00:00:00 2001 From: Anthony Moutte Date: Fri, 13 Dec 2019 17:42:32 +0100 Subject: [PATCH 5/5] fix test unit --- helpers.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/helpers.go b/helpers.go index 3952298..3d8aff2 100644 --- a/helpers.go +++ b/helpers.go @@ -8,7 +8,7 @@ import ( func MessageWithFileLine(message string, skip int) string { _, file, line, ok := runtime.Caller(1 + skip) if ok { - message += " a" + file + ":" + strconv.Itoa(line) + message += " " + file + ":" + strconv.Itoa(line) } return message }