diff --git a/go.mod b/go.mod index 462c792..0407e14 100644 --- a/go.mod +++ b/go.mod @@ -22,15 +22,15 @@ require ( github.com/magiconair/properties v1.8.7 // indirect github.com/mattn/go-colorable v0.1.13 // indirect github.com/mattn/go-isatty v0.0.19 // indirect - github.com/pelletier/go-toml/v2 v2.0.9 // indirect + github.com/pelletier/go-toml/v2 v2.1.0 // indirect github.com/pmezard/go-difflib v1.0.0 // indirect github.com/spf13/afero v1.9.5 // indirect github.com/spf13/jwalterweatherman v1.1.0 // indirect github.com/spf13/pflag v1.0.5 // indirect github.com/subosito/gotenv v1.6.0 // indirect - golang.org/x/crypto v0.12.0 // indirect - golang.org/x/sys v0.11.0 // indirect - golang.org/x/text v0.12.0 // indirect + golang.org/x/crypto v0.13.0 // indirect + golang.org/x/sys v0.12.0 // indirect + golang.org/x/text v0.13.0 // indirect gopkg.in/ini.v1 v1.67.0 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect ) diff --git a/go.sum b/go.sum index 483d783..b2d127e 100644 --- a/go.sum +++ b/go.sum @@ -156,8 +156,8 @@ github.com/mattn/go-isatty v0.0.19 h1:JITubQf0MOLdlGRuRq+jtsDlekdYPia9ZFsB8h/APP github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= github.com/mitchellh/mapstructure v1.5.0 h1:jeMsZIYE/09sWLaz43PL7Gy6RuMjD2eJVyuac5Z2hdY= github.com/mitchellh/mapstructure v1.5.0/go.mod h1:bFUtVrKA4DC2yAKiSyO/QUcy7e+RRV2QTWOzhPopBRo= -github.com/pelletier/go-toml/v2 v2.0.9 h1:uH2qQXheeefCCkuBBSLi7jCiSmj3VRh2+Goq2N7Xxu0= -github.com/pelletier/go-toml/v2 v2.0.9/go.mod h1:tJU2Z3ZkXwnxa4DPO899bsyIoywizdUvyaeZurnPPDc= +github.com/pelletier/go-toml/v2 v2.1.0 h1:FnwAJ4oYMvbT/34k9zzHuZNrhlz48GB3/s6at6/MHO4= +github.com/pelletier/go-toml/v2 v2.1.0/go.mod h1:tJU2Z3ZkXwnxa4DPO899bsyIoywizdUvyaeZurnPPDc= github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4= github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pkg/sftp v1.13.1/go.mod h1:3HaPG6Dq1ILlpPZRO0HVMrsydcdLt6HRDccSgb87qRg= @@ -211,8 +211,8 @@ golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8U golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto= golang.org/x/crypto v0.0.0-20210421170649-83a5a9bb288b/go.mod h1:T9bdIzuCu7OtxOm1hfPfRQxPLYneinmdGuTeoZ9dtd4= golang.org/x/crypto v0.0.0-20220722155217-630584e8d5aa/go.mod h1:IxCIyHEi3zRg3s0A5j5BB6A9Jmi73HwBIUl50j+osU4= -golang.org/x/crypto v0.12.0 h1:tFM/ta59kqch6LlvYnPa0yx5a83cL2nHflFhYKvv9Yk= -golang.org/x/crypto v0.12.0/go.mod h1:NF0Gs7EO5K4qLn+Ylc+fih8BSTeIjAP05siRnAh98yw= +golang.org/x/crypto v0.13.0 h1:mvySKfSWJ+UKUii46M40LOvyWfN0s2U+46/jDd0e6Ck= +golang.org/x/crypto v0.13.0/go.mod h1:y6Z2r+Rw4iayiXXAIxJIDAJ1zMW4yaTpebo8fPOliYc= golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA= golang.org/x/exp v0.0.0-20190306152737-a1d7652674e8/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA= golang.org/x/exp v0.0.0-20190510132918-efd6b22b2522/go.mod h1:ZjyILWgesfNpC6sMxTJOJm9Kp84zZh5NQWvqDGG3Qr8= @@ -337,8 +337,8 @@ golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBc golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220908164124-27713097b956/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.11.0 h1:eG7RXZHdqOJ1i+0lgLgCpSXAp6M3LYlAo6osgSi0xOM= -golang.org/x/sys v0.11.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.12.0 h1:CM0HF96J0hcLAwsHPJZjfdNzs0gftsLfgKt57wWHJ0o= +golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= golang.org/x/text v0.0.0-20170915032832-14c0d48ead0c/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= @@ -348,8 +348,8 @@ golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= golang.org/x/text v0.3.4/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= golang.org/x/text v0.3.7/go.mod h1:u+2+/6zg+i71rQMx5EYifcz6MCKuco9NR6JIITiCfzQ= -golang.org/x/text v0.12.0 h1:k+n5B8goJNdU7hSvEtMUz3d1Q6D/XW4COJSJR6fN0mc= -golang.org/x/text v0.12.0/go.mod h1:TvPlkZtksWOMsz7fbANvkp4WM8x/WCo/om8BMLbz+aE= +golang.org/x/text v0.13.0 h1:ablQoSUd0tRdKxZewP80B+BaqeKJuVhuRxj/dkrun3k= +golang.org/x/text v0.13.0/go.mod h1:TvPlkZtksWOMsz7fbANvkp4WM8x/WCo/om8BMLbz+aE= golang.org/x/time v0.0.0-20181108054448-85acf8d2951c/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ= golang.org/x/time v0.0.0-20190308202827-9d24e82272b4/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ= golang.org/x/time v0.0.0-20191024005414-555d28b269f0/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ= diff --git a/httplog/recover_test.go b/httplog/recover_test.go index 9725297..0195a03 100644 --- a/httplog/recover_test.go +++ b/httplog/recover_test.go @@ -15,7 +15,7 @@ import ( ) func TestRecover(t *testing.T) { - MaxRequestBodyLog = 10 + MaxBodyLog = 10 RecoverBasePath = "iken/httplog/" tests := []struct { diff --git a/httplog/request.go b/httplog/request.go index 26b400a..2926892 100644 --- a/httplog/request.go +++ b/httplog/request.go @@ -17,20 +17,20 @@ const ( HTTPStatusCode = "http.status_code" HTTPMethod = "http.method" HTTPURLDetailsPath = "http.url_details.path" + NetworkBytesRead = "network.bytes_read" NetworkBytesWritten = "network.bytes_written" Operation = "op" - Request = "request.body" + Request = "request" RequestID = "http.request_id" RequestHeaders = "request.headers" - RequestSize = "network.bytes_read" RequestError = "request.body_error" - Response = "response.body" + Response = "response" TraceID = "trace_id" UserID = "usr.id" ) -// MaxRequestBodyLog controls the maximum request body that can be logged. Anything greater will be truncated. -var MaxRequestBodyLog = 24 * 1024 +// MaxBodyLog controls the maximum request/response body that can be logged. Anything greater will be truncated. +var MaxBodyLog uint32 = 24 * 1024 // now is a utility used for automated testing (overriding the runtime clock). var now = time.Now @@ -108,7 +108,7 @@ func RequestLogger(shouldLog FnShouldLog) func(http.Handler) http.Handler { //no Dur(Duration, now().Sub(start)) if logResponse { - l = l.Bytes(Response, responseBuffer.Bytes()) + l = logctx.AddBytes(l, Response, responseBuffer.Bytes(), MaxBodyLog) } logger := l.Logger() @@ -128,20 +128,16 @@ func RequestLogger(shouldLog FnShouldLog) func(http.Handler) http.Handler { //no } } -func logBody(logContext zerolog.Context, r *http.Request) zerolog.Context { +func logBody(l zerolog.Context, r *http.Request) zerolog.Context { body, err := httputil.DumpBody(r) if err != nil { - logContext = logContext.Str(RequestError, err.Error()) + l = l.Str(RequestError, err.Error()) } else { size := len(body) - logContext = logContext.Int(RequestSize, size) + l = l.Int(NetworkBytesRead, size) - if size > MaxRequestBodyLog { - logContext = logContext.Bytes(Request, body[:MaxRequestBodyLog]) - } else { - logContext = logContext.Bytes(Request, body) - } + l = logctx.AddBytes(l, Request, body, MaxBodyLog) } - return logContext + return l } diff --git a/httplog/request_test.go b/httplog/request_test.go index be34037..f9e13b5 100644 --- a/httplog/request_test.go +++ b/httplog/request_test.go @@ -18,7 +18,7 @@ import ( ) func TestRequestLogger(t *testing.T) { - MaxRequestBodyLog = 10 + MaxBodyLog = 10 RecoverBasePath = "iken/httplog/" tests := []struct { @@ -38,15 +38,15 @@ func TestRequestLogger(t *testing.T) { {"default err", nil, bytes.NewBufferString("DO NOT LOG ME"), false, http.HandlerFunc(statusNext(503)), `{"level":"error","http.method":"FOO","http.url_details.path":"/BAR","request.headers":{"FOO":"/BAR HTTP/1.1","Host":"example.com"},"http.status_code":503,"network.bytes_written":11,"duration":0.1,"message":"503 FOO /BAR"} `}, {"no logs", doLogs(false, false, false), bytes.NewBufferString("DO NOT LOG ME"), false, http.HandlerFunc(emptyNext), ""}, - {"all logs", LogAll, bytes.NewBufferString("LOG ME"), false, http.HandlerFunc(bodyNext), `{"level":"info","http.method":"FOO","http.url_details.path":"/BAR","request.headers":{"FOO":"/BAR HTTP/1.1","Host":"example.com"},"network.bytes_read":6,"request.body":"LOG ME","http.status_code":200,"network.bytes_written":4,"duration":0.1,"response.body":"TEST","message":"200 FOO /BAR"} + {"all logs", LogAll, bytes.NewBufferString("LOG ME"), false, http.HandlerFunc(bodyNext), `{"level":"info","http.method":"FOO","http.url_details.path":"/BAR","request.headers":{"FOO":"/BAR HTTP/1.1","Host":"example.com"},"network.bytes_read":6,"request.body":"LOG ME","request.size":6,"response.body":"TEST","response.size":4,"http.status_code":200,"network.bytes_written":4,"duration":0.1,"response.body":"TEST","message":"200 FOO /BAR"} `}, - {"request Body", LogRequestBody, bytes.NewBufferString("LOG ME"), false, http.HandlerFunc(bodyNext), `{"level":"info","http.method":"FOO","http.url_details.path":"/BAR","request.headers":{"FOO":"/BAR HTTP/1.1","Host":"example.com"},"network.bytes_read":6,"request.body":"LOG ME","http.status_code":200,"network.bytes_written":4,"duration":0.1,"message":"200 FOO /BAR"} + {"request Body", LogRequestBody, bytes.NewBufferString("LOG ME"), false, http.HandlerFunc(bodyNext), `{"level":"info","http.method":"FOO","http.url_details.path":"/BAR","request.headers":{"FOO":"/BAR HTTP/1.1","Host":"example.com"},"network.bytes_read":6,"request.body":"LOG ME","request.size":6,"http.status_code":200,"network.bytes_written":4,"duration":0.1,"message":"200 FOO /BAR"} `}, - {"request Body read", LogRequestBody, bytes.NewBufferString("LOG ME"), false, http.HandlerFunc(readNext), `{"level":"info","http.method":"FOO","http.url_details.path":"/BAR","request.headers":{"FOO":"/BAR HTTP/1.1","Host":"example.com"},"network.bytes_read":6,"request.body":"LOG ME","http.status_code":200,"network.bytes_written":6,"duration":0.1,"message":"200 FOO /BAR"} + {"request Body read", LogRequestBody, bytes.NewBufferString("LOG ME"), false, http.HandlerFunc(readNext), `{"level":"info","http.method":"FOO","http.url_details.path":"/BAR","request.headers":{"FOO":"/BAR HTTP/1.1","Host":"example.com"},"network.bytes_read":6,"request.body":"LOG ME","request.size":6,"http.status_code":200,"network.bytes_written":6,"duration":0.1,"message":"200 FOO /BAR"} `}, - {"response Body", doLogs(true, false, true), bytes.NewBufferString("LOG ME"), false, http.HandlerFunc(bodyNext), `{"level":"info","http.method":"FOO","http.url_details.path":"/BAR","request.headers":{"FOO":"/BAR HTTP/1.1","Host":"example.com"},"http.status_code":200,"network.bytes_written":4,"duration":0.1,"response.body":"TEST","message":"200 FOO /BAR"} + {"response Body", doLogs(true, false, true), bytes.NewBufferString("LOG ME"), false, http.HandlerFunc(bodyNext), `{"level":"info","http.method":"FOO","http.url_details.path":"/BAR","request.headers":{"FOO":"/BAR HTTP/1.1","Host":"example.com"},"http.status_code":200,"network.bytes_written":4,"response.size":4,"duration":0.1,"response.body":"TEST","message":"200 FOO /BAR"} `}, - {"request Body too big", LogRequestBody, bytes.NewBufferString("12345678901"), false, http.HandlerFunc(readNext), `{"level":"info","http.method":"FOO","http.url_details.path":"/BAR","request.headers":{"FOO":"/BAR HTTP/1.1","Host":"example.com"},"network.bytes_read":11,"request.body":"1234567890","http.status_code":200,"network.bytes_written":11,"duration":0.1,"message":"200 FOO /BAR"} + {"request Body too big", LogRequestBody, bytes.NewBufferString("12345678901"), false, http.HandlerFunc(readNext), `{"level":"info","http.method":"FOO","http.url_details.path":"/BAR","request.headers":{"FOO":"/BAR HTTP/1.1","Host":"example.com"},"network.bytes_read":11,"request.body":"1234567890","request.size":11,"request.truncated":true,"request.truncatedSize":10,"http.status_code":200,"network.bytes_written":11,"duration":0.1,"message":"200 FOO /BAR"} `}, {"error body", LogRequestBody, BadReader{}, false, http.HandlerFunc(readNext), `{"level":"info","http.method":"FOO","http.url_details.path":"/BAR","request.headers":{"FOO":"/BAR HTTP/1.1","Host":"example.com"},"request.body_error":"buf.ReadFrom:BadReader","http.status_code":200,"network.bytes_written":0,"duration":0.1,"message":"200 FOO /BAR"} `}, diff --git a/logctx/utils.go b/logctx/utils.go index aaa8df5..d7afc71 100644 --- a/logctx/utils.go +++ b/logctx/utils.go @@ -38,3 +38,27 @@ func AddMapToContext(ctx context.Context, fields map[string]any) { return c.Fields(fields) }) } + +// AddBytesToContext adds the key/value to the log context. +func AddBytesToContext(ctx context.Context, key string, value []byte, maxSize uint32) { + zerolog.Ctx(ctx).UpdateContext(func(c zerolog.Context) zerolog.Context { + return AddBytes(c, key, value, maxSize) + }) +} + +// AddBytes adds the key/value (truncated by maxSize) to the log context. +func AddBytes(ctx zerolog.Context, key string, value []byte, maxSize uint32) zerolog.Context { + size := len(value) + + ctx = ctx.Int(key+".size", size) + + if size > int(maxSize) { + ctx = ctx.Bytes(key+".body", value[:maxSize]) + ctx = ctx.Bool(key+".truncated", true) + ctx = ctx.Uint32(key+".truncatedSize", maxSize) + } else { + ctx = ctx.Bytes(key+".body", value) + } + + return ctx +} diff --git a/logctx/utils_test.go b/logctx/utils_test.go index c78528d..5fd2d5e 100644 --- a/logctx/utils_test.go +++ b/logctx/utils_test.go @@ -24,13 +24,16 @@ func TestLogContext(t *testing.T) { logctx.AddStrToContext(ctx2, "key", "value") + logctx.AddBytesToContext(ctx2, "small", []byte("12345"), 5) + logctx.AddBytesToContext(ctx2, "large", []byte("123456789"), 5) + zerolog.Ctx(ctx).Log().Msg("ctx") zerolog.Ctx(ctx2).Log().Msg("ctx2") - assert.Equal(t, logBuffer.String(), `{"key":1,"test":"value","test2":"value2","message":"ctx"} -{"key":"value","message":"ctx2"} -`) + assert.Equal(t, `{"key":1,"test":"value","test2":"value2","message":"ctx"} +{"key":"value","small.size":5,"small.body":"12345","large.size":9,"large.body":"12345","large.truncated":true,"large.truncatedSize":5,"message":"ctx2"} +`, logBuffer.String()) // ensure NewContext does not propagate cancel cancel() assert.Error(t, ctx.Err())