From d6867e1f9e92c8c25314327b3a4174fd4a6f4d5c Mon Sep 17 00:00:00 2001 From: "Gerasimos (Makis) Maropoulos" Date: Tue, 8 Sep 2020 13:44:50 +0300 Subject: [PATCH] accesslog middleware: add total bytes received and sent relative to: https://github.com/kataras/iris/issues/1601 --- VERSION | 2 +- .../accesslog/access.log.sample | 12 +- .../logging/request-logger/accesslog/main.go | 16 +- context/response_recorder.go | 71 +++++++++ middleware/accesslog/accesslog.go | 137 +++++++++++++----- middleware/accesslog/accesslog_test.go | 4 +- middleware/accesslog/log.go | 34 ++++- 7 files changed, 223 insertions(+), 53 deletions(-) diff --git a/VERSION b/VERSION index b56d45d5..55445b79 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -12.1.8:https://github.com/kataras/iris/releases/tag/v12.1.8 \ No newline at end of file +master:https://github.com/kataras/iris/tree/master \ No newline at end of file diff --git a/_examples/logging/request-logger/accesslog/access.log.sample b/_examples/logging/request-logger/accesslog/access.log.sample index 316986fe..4080fbad 100644 --- a/_examples/logging/request-logger/accesslog/access.log.sample +++ b/_examples/logging/request-logger/accesslog/access.log.sample @@ -1,6 +1,6 @@ -2020-08-22 00:44:20|993.3µs|POST|/read_body||200|{"id":10,"name":"Tim","age":22}|{"message":"OK"}| -2020-08-22 00:44:30|0s|POST|/read_body||400||error(invalid character 'a' looking for beginning of object key string)|| -2020-08-22 03:02:41|1ms|GET|/|a=1 b=2|200||

Hello index

| -2020-08-22 03:15:29|968.8µs|GET|/public|file=public|404||| -2020-08-22 03:03:42|0s|GET|/user/kataras|username=kataras|200||Hello, kataras!| -2020-08-22 03:05:40|0s|GET|/user/kataras|username=kataras a_query_parameter=name|200||Hello, kataras!| +2020-09-08 13:34:42|0s|POST|/read_body||200|324 B|217 B|{"name":"John","email":"example@example.com"}|{"data":{"email":"example@example.com","name":"John"},"message":"OK"}| +2020-09-08 13:40:28|0s|POST|/read_body||400||85 B|error(invalid character '\r' in string literal)|| +2020-09-08 13:41:05|1.0024ms|GET|/|a=1 b=2|200|767 B|251 B||

Hello index

| +2020-09-08 13:41:26|0s|GET|/public||404|765 B|83 B||| +2020-09-08 13:41:36|0s|GET|/user/kataras|username=kataras|200|771 B|91 B||Hello, kataras!| +2020-09-08 13:41:47|0s|GET|/user/kataras|username=kataras a_query_parameter=name|200|774 B|91 B||Hello, kataras!| diff --git a/_examples/logging/request-logger/accesslog/main.go b/_examples/logging/request-logger/accesslog/main.go index be6a9585..cd8cd911 100644 --- a/_examples/logging/request-logger/accesslog/main.go +++ b/_examples/logging/request-logger/accesslog/main.go @@ -25,23 +25,31 @@ func main() { Use a file directly: ac := accesslog.File("./access.log") - Log after the response was sent: + Log after the response was sent (defaults to false): ac.Async = true Force-protect writer with locks. On this example this is not required: ac.LockWriter = true" + // To disable request and response calculations + // (enabled by default but slows down the whole operation if Async is false): + ac.RequestBody = false + ac.ResponseBody = false + ac.BytesReceived = false + ac.BytesSent = false + Add second output: ac.AddOutput(app.Logger().Printer) Change format (after output was set): ac.SetFormatter(&accesslog.JSON{Indent: " "}) - Change the format and customize the order - with the Template format: + Modify the output format and customize the order + with the Template formatter: ac.SetFormatter(&accesslog.Template{ - Text: "{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Method}}|{{.Path}}|{{.RequestValuesLine}}|{{.Code}}|{{.Request}}|{{.Response}}|\n", + Text: "{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Method}}|{{.Path}}|{{.RequestValuesLine}}|{{.Code}}|{{.BytesReceivedLine}}|{{.BytesSentLine}}|{{.Request}}|{{.Response}}|\n", + // Default ^ }) Set custom request fields: diff --git a/context/response_recorder.go b/context/response_recorder.go index 9da74609..eff606af 100644 --- a/context/response_recorder.go +++ b/context/response_recorder.go @@ -1,8 +1,13 @@ package context import ( + "bytes" "errors" + "fmt" + "io/ioutil" "net/http" + "net/textproto" + "strconv" "sync" ) @@ -38,6 +43,8 @@ type ResponseRecorder struct { chunks []byte // the saved headers headers http.Header + + result *http.Response } var _ ResponseWriter = (*ResponseRecorder)(nil) @@ -53,6 +60,7 @@ func (w *ResponseRecorder) Naive() http.ResponseWriter { func (w *ResponseRecorder) BeginRecord(underline ResponseWriter) { w.ResponseWriter = underline w.headers = underline.Header() + w.result = nil w.ResetBody() } @@ -288,3 +296,66 @@ func (w *ResponseRecorder) Push(target string, opts *http.PushOptions) (err erro return ErrPushNotSupported } + +// Result returns the response generated by the handler. +// It does set all provided headers. +// +// Result must only be called after the handler has finished running. +func (w *ResponseRecorder) Result() *http.Response { // a modified copy of net/http/httptest + if w.result != nil { + return w.result + } + + headers := w.headers.Clone() + + for k, v := range w.ResponseWriter.Header() { + headers[k] = v + } + /* + dateFound := false + for k := range headers { + if strings.ToLower(k) == "date" { + dateFound = true + break + } + } + + if !dateFound { + headers["Date"] = []string{time.Now().Format(http.TimeFormat)} + } + */ + + res := &http.Response{ + Proto: "HTTP/1.1", + ProtoMajor: 1, + ProtoMinor: 1, + StatusCode: w.StatusCode(), + Header: headers, + } + if res.StatusCode == 0 { + res.StatusCode = 200 + } + res.Status = fmt.Sprintf("%03d %s", res.StatusCode, http.StatusText(res.StatusCode)) + if w.chunks != nil { + res.Body = ioutil.NopCloser(bytes.NewReader(w.chunks)) + } else { + res.Body = http.NoBody + } + res.ContentLength = parseContentLength(res.Header.Get("Content-Length")) + + w.result = res + return res +} + +// copy of net/http/httptest +func parseContentLength(cl string) int64 { + cl = textproto.TrimString(cl) + if cl == "" { + return -1 + } + n, err := strconv.ParseUint(cl, 10, 63) + if err != nil { + return -1 + } + return int64(n) +} diff --git a/middleware/accesslog/accesslog.go b/middleware/accesslog/accesslog.go index 91ca4129..0fe27244 100644 --- a/middleware/accesslog/accesslog.go +++ b/middleware/accesslog/accesslog.go @@ -4,6 +4,7 @@ import ( "bytes" "fmt" "io" + "net/http/httputil" "os" "sync" "time" @@ -85,6 +86,15 @@ type AccessLog struct { // The time format for current time on log print. // Defaults to the Iris Application's TimeFormat. TimeFormat string + + // The actual number of bytes received and sent on the network (headers + body). + // It is kind of "slow" operation as it uses the httputil to dumb request + // and response to get the total amount of bytes (headers + body). + BytesReceived bool + BytesSent bool + // Note: We could calculate only the bodies, which is a fast operation if we already + // have RequestBody and ResponseBody set to true but this is not an accurate measurement. + // Force minify request and response contents. BodyMinify bool // Enable request body logging. @@ -111,9 +121,11 @@ type AccessLog struct { // Example: https://github.com/kataras/iris/tree/master/_examples/logging/request-logger/accesslog func New(w io.Writer) *AccessLog { ac := &AccessLog{ - BodyMinify: true, - RequestBody: true, - ResponseBody: true, + BytesReceived: true, + BytesSent: true, + BodyMinify: true, + RequestBody: true, + ResponseBody: true, } if w == nil { @@ -238,6 +250,15 @@ func (ac *AccessLog) Close() (err error) { return } +func (ac *AccessLog) shouldReadRequestBody() bool { + return ac.RequestBody || ac.BytesReceived + +} + +func (ac *AccessLog) shouldReadResponseBody() bool { + return ac.ResponseBody || ac.BytesSent +} + // Handler prints request information to the output destination. // It is the main method of the AccessLog middleware. // @@ -255,12 +276,12 @@ func (ac *AccessLog) Handler(ctx *context.Context) { ) // Enable response recording. - if ac.ResponseBody { + if ac.shouldReadResponseBody() { ctx.Record() } // Enable reading the request body // multiple times (route handler and this middleware). - if ac.RequestBody { + if ac.shouldReadRequestBody() { ctx.RecordBody() } @@ -280,44 +301,75 @@ func (ac *AccessLog) Handler(ctx *context.Context) { func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path string) { var ( // request and response data or error reading them. - requestBody string - responseBody string + requestBody string + responseBody string + bytesReceived int + bytesSent int ) - // any error handler stored ( ctx.SetErr or StopWith(Plain)Error ) - if ctxErr := ctx.GetErr(); ctxErr != nil { - requestBody = fmt.Sprintf("error(%s)", ctxErr.Error()) - } else if ac.RequestBody { - requestData, err := ctx.GetBody() - if err != nil { + if ac.shouldReadRequestBody() { + // any error handler stored ( ctx.SetErr or StopWith(Plain)Error ) + if ctxErr := ctx.GetErr(); ctxErr != nil { + // If there is an error here + // we may need to NOT read the body for security reasons, e.g. + // unauthorized user tries to send a malicious body. requestBody = fmt.Sprintf("error(%s)", ctxErr.Error()) } else { - if ac.BodyMinify { - if minified, err := ctx.Application().Minifier().Bytes(ctx.GetContentTypeRequested(), requestData); err == nil { - requestBody = string(minified) + requestData, err := ctx.GetBody() + requestBodyLength := len(requestData) + if err != nil && ac.RequestBody { + requestBody = fmt.Sprintf("error(%s)", err) + } else if requestBodyLength > 0 { + if ac.RequestBody { + if ac.BodyMinify { + if minified, err := ctx.Application().Minifier().Bytes(ctx.GetContentTypeRequested(), requestData); err == nil { + requestBody = string(minified) + } + } + /* Some content types, like the text/plain, + no need minifier. Should be printed with spaces and \n. */ + if requestBody == "" { + requestBody = string(requestData) + } } } - /* Some content types, like the text/plain, - no need minifier. Should be printed with spaces and \n. */ - if requestBody == "" { - requestBody = string(requestData) + + if ac.BytesReceived { + // Unfortunally the DumpRequest cannot read the body + // length as expected (see postman's i/o values) + // so we had to read the data length manually even if RequestBody/ResponseBody + // are false, extra operation if they are enabled is to minify their log entry representation. + + b, _ := httputil.DumpRequest(ctx.Request(), false) + bytesReceived = len(b) + requestBodyLength } } } - if ac.RequestBody { - if responseData := ctx.Recorder().Body(); len(responseData) > 0 { + if ac.shouldReadResponseBody() { + responseData := ctx.Recorder().Body() + responseBodyLength := len(responseData) + if ac.ResponseBody && responseBodyLength > 0 { if ac.BodyMinify { - if minified, err := ctx.Application().Minifier().Bytes(ctx.GetContentType(), ctx.Recorder().Body()); err == nil { + if minified, err := ctx.Application().Minifier().Bytes(ctx.GetContentType(), responseData); err == nil { responseBody = string(minified) } - } if responseBody == "" { responseBody = string(responseData) } } + + if ac.BytesSent { + resp := ctx.Recorder().Result() + b, _ := httputil.DumpResponse(resp, false) + dateLengthProx := 38 /* it's actually ~37 */ + if resp.Header.Get("Date") != "" { + dateLengthProx = 0 // dump response calculated it. + } + bytesSent = len(b) + responseBodyLength + dateLengthProx + } } // Grab any custom fields. @@ -350,6 +402,7 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path // original request's method and path. method, path, requestBody, responseBody, + bytesReceived, bytesSent, ctx.Params(), ctx.URLParamsSorted(), fields, ); err != nil { ctx.Application().Logger().Errorf("accesslog: %v", err) @@ -358,7 +411,7 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path // Print writes a log manually. // The `Handler` method calls it. -func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeFormat string, code int, method, path, reqBody, respBody string, params *context.RequestParams, query []memstore.StringEntry, fields []memstore.Entry) error { +func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeFormat string, code int, method, path, reqBody, respBody string, bytesReceived, bytesSent int, params *context.RequestParams, query []memstore.StringEntry, fields []memstore.Entry) error { var now time.Time if ac.Clock != nil { @@ -369,20 +422,22 @@ func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeForm if f := ac.formatter; f != nil { log := &Log{ - Logger: ac, - Now: now, - TimeFormat: timeFormat, - Timestamp: now.Unix(), - Latency: latency, - Method: method, - Path: path, - Code: code, - Query: query, - PathParams: params.Store, - Fields: fields, - Request: reqBody, - Response: respBody, - Ctx: ctx, // ctx should only be used here, it may be nil on testing. + Logger: ac, + Now: now, + TimeFormat: timeFormat, + Timestamp: now.Unix(), + Latency: latency, + Method: method, + Path: path, + Code: code, + Query: query, + PathParams: params.Store, + Fields: fields, + BytesReceived: bytesReceived, + BytesSent: bytesSent, + Request: reqBody, + Response: respBody, + Ctx: ctx, // ctx should only be used here, it may be nil on testing. } if err := f.Format(log); err != nil { @@ -399,13 +454,15 @@ func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeForm // the number of separators are the same, in order to be easier // for 3rd-party programs to read the result log file. - _, err := fmt.Fprintf(ac, "%s|%s|%s|%s|%s|%d|%s|%s|\n", + _, err := fmt.Fprintf(ac, "%s|%s|%s|%s|%s|%d|%s|%s|%s|%s|\n", now.Format(timeFormat), latency, method, path, requestValues, code, + formatBytes(bytesReceived), + formatBytes(bytesSent), reqBody, respBody, ) diff --git a/middleware/accesslog/accesslog_test.go b/middleware/accesslog/accesslog_test.go index 7773c152..5e3caf1b 100644 --- a/middleware/accesslog/accesslog_test.go +++ b/middleware/accesslog/accesslog_test.go @@ -30,7 +30,7 @@ func TestAccessLogPrint_Simple(t *testing.T) { for i := 0; i < goroutinesN; i++ { wg.Add(1) - expected += "0001-01-01 00:00:00|1s|GET|/path_value?url_query=url_query_value|path_param=path_param_value url_query=url_query_value custom=custom_value|200|Incoming|Outcoming|\n" + expected += "0001-01-01 00:00:00|1s|GET|/path_value?url_query=url_query_value|path_param=path_param_value url_query=url_query_value custom=custom_value|200|||Incoming|Outcoming|\n" go func() { defer wg.Done() @@ -44,6 +44,8 @@ func TestAccessLogPrint_Simple(t *testing.T) { "/path_value?url_query=url_query_value", "Incoming", "Outcoming", + 0, + 0, &context.RequestParams{ Store: []memstore.Entry{ {Key: "path_param", ValueRaw: "path_param_value"}, diff --git a/middleware/accesslog/log.go b/middleware/accesslog/log.go index 8c84338a..e5212eed 100644 --- a/middleware/accesslog/log.go +++ b/middleware/accesslog/log.go @@ -40,6 +40,10 @@ type Log struct { // Fields any data information useful to represent this Log. Fields []memstore.Entry `json:"fields,omitempty"` + // The actual number of bytes received and sent on the network (headers + body). + BytesReceived int `json:"bytes_received"` + BytesSent int `json:"bytes_sent"` + // The Request and Response raw bodies. // If they are escaped (e.g. JSON), // A third-party software can read it through: @@ -59,6 +63,34 @@ func (l *Log) RequestValuesLine() string { return parseRequestValues(l.Code, l.Ctx.Params(), l.Ctx.URLParamsSorted(), l.Fields) } +// BytesReceivedLine returns the formatted bytes received length. +func (l *Log) BytesReceivedLine() string { + return formatBytes(l.BytesReceived) +} + +// BytesSentLine returns the formatted bytes sent length. +func (l *Log) BytesSentLine() string { + return formatBytes(l.BytesSent) +} + +func formatBytes(b int) string { + if b <= 0 { + return "" + } + + const unit = 1024 + if b < unit { + return fmt.Sprintf("%d B", b) + } + div, exp := int64(unit), 0 + for n := b / unit; n >= unit; n /= unit { + div *= unit + exp++ + } + return fmt.Sprintf("%.1f %cB", + float64(b)/float64(div), "KMGTPE"[exp]) +} + func parseRequestValues(code int, pathParams *context.RequestParams, query []memstore.StringEntry, fields memstore.Store) (requestValues string) { var buf strings.Builder @@ -178,7 +210,7 @@ func (f *Template) SetOutput(dest io.Writer) { f.dest = dest } -const defaultTmplText = "{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Method}}|{{.Path}}|{{.RequestValuesLine}}|{{.Code}}|{{.Request}}|{{.Response}}|\n" +const defaultTmplText = "{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Method}}|{{.Path}}|{{.RequestValuesLine}}|{{.Code}}|{{.BytesReceivedLine}}|{{.BytesSentLine}}|{{.Request}}|{{.Response}}|\n" // Format prints the logs in text/template format. func (f *Template) Format(log *Log) error {