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/README.md b/README.md index 79f29e7..625b23f 100644 --- a/README.md +++ b/README.md @@ -1,2 +1,128 @@ # logger-http -Gol4ng logger sub package for 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 logging http +Related package [gol4ng/logger](https://github.com/gol4ng/logger) and [gol4ng/httpware](https://github.com/gol4ng/httpware) + +## Installation + +`go get -u github.com/gol4ng/logger-http` + +## Quick Start + +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 + +import ( + "net/http" + "os" + + "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" +) + +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: 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"} +} +``` + +### 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/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/helpers.go b/helpers.go new file mode 100644 index 0000000..3d8aff2 --- /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 += " " + file + ":" + strconv.Itoa(line) + } + return message +} diff --git a/middleware/correlation_id.go b/middleware/correlation_id.go new file mode 100644 index 0000000..1c5ff8a --- /dev/null +++ b/middleware/correlation_id.go @@ -0,0 +1,48 @@ +package middleware + +import ( + "fmt" + "net/http" + + "github.com/gol4ng/httpware/v2" + "github.com/gol4ng/httpware/v2/correlation_id" + 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 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() + requestLogger := logger.FromContext(ctx, nil) + injected := false + if requestLogger != nil { + if wrappableLogger, ok := requestLogger.(logger.WrappableLoggerInterface); ok { + req = req.WithContext(logger.InjectInContext(ctx, wrappableLogger.WrapNew(middleware.Context( + logger.NewContext().Add(config.HeaderName, ctx.Value(config.HeaderName)), + )))) + injected = true + } + } + 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 new file mode 100644 index 0000000..61b3d13 --- /dev/null +++ b/middleware/logger.go @@ -0,0 +1,55 @@ +package middleware + +import ( + "fmt" + "net/http" + "time" + + "github.com/gol4ng/httpware/v2" + 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 { + 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 := http_middleware.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/logger_test.go b/middleware/logger_test.go new file mode 100644 index 0000000..e4f27d2 --- /dev/null +++ b/middleware/logger_test.go @@ -0,0 +1,173 @@ +package middleware_test + +import ( + "bytes" + "context" + "fmt" + "net/http" + "net/http/httptest" + "strings" + "testing" + "time" + + "github.com/gol4ng/logger" + "github.com/gol4ng/logger/formatter" + "github.com/gol4ng/logger/handler" + "github.com/stretchr/testify/assert" + + "github.com/gol4ng/logger-http" + "github.com/gol4ng/logger-http/middleware" +) + +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(writer http.ResponseWriter, innerRequest *http.Request) { + // not equal because request.WithContext create another request object + assert.NotEqual(t, responseWriter, writer) + writer.Write([]byte(`OK`)) + }) + + loggerOutput := &Output{} + myLogger := logger.NewLogger( + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), + ) + + middleware.Logger(myLogger)(h).ServeHTTP(responseWriter, request) + loggerOutput.Constains(t, []string{ + ` http server GET http://127.0.0.1/my-fake-url [status_code:200, duration:`, + `content_length:2] {`, + `"http_kind":"server"`, + `"http_method":"GET"`, + `"http_response_length":2`, + `"http_status":"OK"`, + `"http_status_code":200`, + + `"http_url":"http://127.0.0.1`, + `"http_duration":`, + `"http_start_time":"`, + `"http_request_deadline":"`, + }) +} + +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) + 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() { + middleware.Logger(myLogger)(h).ServeHTTP(responseWriter, req) + }) + + output.Constains(t, []string{ + ` http server panic GET http://127.0.0.1/my-fake-url [duration:`, + `"http_kind":"server"`, + `"http_method":"GET"`, + + `"http_url":"http://127.0.0.1`, + `"http_duration":`, + `"http_start_time":"`, + `"http_request_deadline":"`, + }) +} + +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(writer http.ResponseWriter, innerRequest *http.Request) { + // not equal because request.WithContext create another request object + assert.NotEqual(t, responseWriter, writer) + writer.Write([]byte(`OK`)) + }) + + loggerOutput := &Output{} + myLogger := logger.NewLogger( + 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, request) + + loggerOutput.Constains(t, []string{ + ` http server GET http://127.0.0.1/my-fake-url [status_code:200, duration:`, + `content_length:2] {`, + `"http_kind":"server"`, + `"http_method":"GET"`, + `"http_response_length":2`, + `"http_status":"OK"`, + `"http_status_code":200`, + `"base_context_key":"base_context_value"`, + + `"http_url":"http://127.0.0.1`, + `"http_duration":`, + `"http_start_time":"`, + `"http_request_deadline":"`, + }) +} + +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(writer http.ResponseWriter, innerRequest *http.Request) { + // not equal because request.WithContext create another request object + assert.NotEqual(t, responseWriter, writer) + writer.Write([]byte(`OK`)) + }) + + loggerOutput := &Output{} + myLogger := logger.NewLogger( + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), + ) + + middleware.Logger(myLogger, logger_http.WithLevels(func(statusCode int) logger.Level { + return logger.EmergencyLevel + }))(h).ServeHTTP(responseWriter, request) + + loggerOutput.Constains(t, []string{ + ` http server GET http://127.0.0.1/my-fake-url [status_code:200, duration:`, + `content_length:2] {`, + `"http_kind":"server"`, + `"http_method":"GET"`, + `"http_response_length":2`, + `"http_status":"OK"`, + `"http_status_code":200`, + + `"http_url":"http://127.0.0.1`, + `"http_duration":`, + `"http_start_time":"`, + `"http_request_deadline":"`, + }) +} + +type Output struct { + bytes.Buffer +} + +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/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 new file mode 100644 index 0000000..9fcf308 --- /dev/null +++ b/options.go @@ -0,0 +1,93 @@ +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 + +func newDefaultOptions() *Options { + return &Options{ + LoggerContextProvider: func(request *http.Request) *logger.Context { + return logger.NewContext().Add("http_header", request.Header) + }, + 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 := 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) + } + return optCopy +} + +func EvaluateServerOpt(opts ...Option) *Options { + optCopy := newDefaultOptions() + 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(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 d, ok := ctx.Deadline(); ok { + loggerContext.Add("http_request_deadline", d.Format(time.RFC3339)) + } + return loggerContext +} diff --git a/tripperware/correlation_id.go b/tripperware/correlation_id.go new file mode 100644 index 0000000..2d00832 --- /dev/null +++ b/tripperware/correlation_id.go @@ -0,0 +1,52 @@ +package tripperware + +import ( + "fmt" + "net/http" + + "github.com/gol4ng/httpware/v2" + "github.com/gol4ng/httpware/v2/correlation_id" + 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 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() + requestLogger := logger.FromContext(ctx, nil) + injected := false + if requestLogger != nil { + if wrappableLogger, ok := requestLogger.(logger.WrappableLoggerInterface); ok { + req = req.WithContext(logger.InjectInContext(ctx, wrappableLogger.WrapNew(middleware.Context( + logger.NewContext().Add(config.HeaderName, ctx.Value(config.HeaderName)), + )))) + injected = true + } + } + 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 new file mode 100644 index 0000000..046f3eb --- /dev/null +++ b/tripperware/logger.go @@ -0,0 +1,60 @@ +package tripperware + +import ( + "fmt" + "net/http" + "time" + + "github.com/gol4ng/httpware/v2" + "github.com/gol4ng/logger" + + "github.com/gol4ng/logger-http" +) + +// 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 { + 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/logger_test.go b/tripperware/logger_test.go new file mode 100644 index 0000000..20c6273 --- /dev/null +++ b/tripperware/logger_test.go @@ -0,0 +1,233 @@ +package tripperware_test + +import ( + "bytes" + "context" + "fmt" + "net/http" + "net/http/httptest" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/gol4ng/httpware/v2" + "github.com/gol4ng/logger" + "github.com/gol4ng/logger/formatter" + "github.com/gol4ng/logger/handler" + + "github.com/gol4ng/logger-http" + "github.com/gol4ng/logger-http/tripperware" +) + +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() + + loggerOutput := &Output{} + myLogger := logger.NewLogger( + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), + ) + + c := http.Client{ + Transport: tripperware.Logger(myLogger)(http.DefaultTransport), + } + + ctx := context.Background() + ctx, _ = context.WithTimeout(ctx, 3*time.Second) + request, _ := http.NewRequestWithContext(ctx, http.MethodGet, server.URL+"/my-fake-url", nil) + + _, err := c.Do(request) + assert.Nil(t, err) + loggerOutput.Constains(t, []string{ + ` http client GET http://127.0.0.1`, + `/my-fake-url [status_code:200, duration:`, + `content_length:2] {`, + `"http_kind":"client"`, + `"http_method":"GET"`, + `"http_response_length":2`, + `"http_status":"200 OK"`, + `"http_status_code":200`, + + `"http_url":"http://127.0.0.1`, + `"http_duration":`, + `"http_start_time":"`, + `"http_request_deadline":"`, + }) +} + +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() + + loggerOutput := &Output{} + myLogger := logger.NewLogger( + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), + ) + + c := http.Client{ + Transport: tripperware.Logger(myLogger)(http.DefaultTransport), + } + + ctx := context.Background() + ctx, _ = context.WithTimeout(ctx, 3*time.Second) + request, _ := http.NewRequestWithContext(ctx, http.MethodGet, "http://a.zz/my-fake-url", nil) + + _, err := c.Do(request) + assert.Contains(t, err.Error(), "no such host") + loggerOutput.Constains(t, []string{ + ` http client error GET http://a.zz/my-fake-url [duration:`, + `dial tcp: lookup a.zz`, + `no such host`, + `"http_kind":"client"`, + `"http_method":"GET"`, + `"http_url":"http://a.zz/my-fake-url"`, + + `"http_error_message":"dial tcp: lookup a.zz`, + `"http_error":`, + + `"http_start_time":"`, + `"http_request_deadline":"`, + `"http_duration":`, + }) +} + +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() + + loggerOutput := &Output{} + myLogger := logger.NewLogger( + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), + ) + + transportPanic := httpware.RoundTripFunc(func(req *http.Request) (*http.Response, error) { + panic("my transport panic") + }) + c := http.Client{ + Transport: tripperware.Logger(myLogger)(transportPanic), + } + + assert.Panics(t, func() { + ctx := context.Background() + ctx, _ = context.WithTimeout(ctx, 3*time.Second) + request, _ := http.NewRequestWithContext(ctx, http.MethodGet, "http://a.zz/my-fake-url", nil) + + c.Do(request) + }) + + loggerOutput.Constains(t, []string{ + ` http client panic GET http://a.zz/my-fake-url [duration:`, + `"http_kind":"client"`, + `"http_method":"GET"`, + `"http_url":"http://a.zz/my-fake-url"`, + `"http_panic":"my transport panic"`, + + `"http_start_time":"`, + `"http_request_deadline":"`, + `"http_duration":`, + }) +} + +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() + + loggerOutput := &Output{} + myLogger := logger.NewLogger( + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), + ) + + c := http.Client{ + 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), + } + + ctx := context.Background() + ctx, _ = context.WithTimeout(ctx, 3*time.Second) + request, _ := http.NewRequestWithContext(ctx, http.MethodGet, server.URL+"/my-fake-url", nil) + + _, err := c.Do(request) + assert.Nil(t, err) + loggerOutput.Constains(t, []string{ + ` http client GET http://127.0.0.1`, + `/my-fake-url [status_code:200, duration:`, + `content_length:2] {`, + `"http_kind":"client"`, + `"http_method":"GET"`, + `"http_response_length":2`, + `"http_status":"200 OK"`, + `"http_status_code":200`, + + `"http_url":"http://127.0.0.1`, + `"http_duration":`, + `"http_start_time":"`, + `"http_request_deadline":"`, + `"base_context_key":"base_context_value"`, + }) +} + +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() + + loggerOutput := &Output{} + myLogger := logger.NewLogger( + handler.Stream(loggerOutput, formatter.NewDefaultFormatter()), + ) + + c := http.Client{ + Transport: tripperware.Logger(myLogger, logger_http.WithLevels(func(statusCode int) logger.Level { + return logger.EmergencyLevel + }))(http.DefaultTransport), + } + + ctx := context.Background() + ctx, _ = context.WithTimeout(ctx, 3*time.Second) + request, _ := http.NewRequestWithContext(ctx, http.MethodGet, server.URL+"/my-fake-url", nil) + + _, err := c.Do(request) + assert.Nil(t, err) + loggerOutput.Constains(t, []string{ + ` http client GET http://127.0.0.1`, + `/my-fake-url [status_code:200, duration:`, + `content_length:2] {`, + `"http_kind":"client"`, + `"http_method":"GET"`, + `"http_response_length":2`, + `"http_status":"200 OK"`, + `"http_status_code":200`, + + `"http_url":"http://127.0.0.1`, + `"http_duration":`, + `"http_start_time":"`, + `"http_request_deadline":"`, + }) +} + +type Output struct { + bytes.Buffer +} + +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)) + } + } +}