accesslog middleware: add total bytes received and sent

relative to: https://github.com/kataras/iris/issues/1601

VERSION

@@ -1 +1 @@
-12.1.8:https://github.com/kataras/iris/releases/tag/v12.1.8
+master:https://github.com/kataras/iris/tree/master

_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-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-08-22 00:44:30|0s|POST|/read_body||400||error(invalid character 'a' looking for beginning of object key string)||
+2020-09-08 13:40:28|0s|POST|/read_body||400||85 B|error(invalid character '\r' in string literal)||
-2020-08-22 03:02:41|1ms|GET|/|a=1 b=2|200||<h1>Hello index</h1>|
+2020-09-08 13:41:05|1.0024ms|GET|/|a=1 b=2|200|767 B|251 B||<h1>Hello index</h1>|
-2020-08-22 03:15:29|968.8µs|GET|/public|file=public|404|||
+2020-09-08 13:41:26|0s|GET|/public||404|765 B|83 B|||
-2020-08-22 03:03:42|0s|GET|/user/kataras|username=kataras|200||Hello, kataras!|
+2020-09-08 13:41:36|0s|GET|/user/kataras|username=kataras|200|771 B|91 B||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:41:47|0s|GET|/user/kataras|username=kataras a_query_parameter=name|200|774 B|91 B||Hello, kataras!|

_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
+		Modify the output format and customize the order
-		with the Template format:
+		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:

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)
+}

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,
+		BytesReceived: true,
-		RequestBody:  true,
+		BytesSent:     true,
-		ResponseBody: 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
+		requestBody   string
-		responseBody string
+		responseBody  string
+		bytesReceived int
+		bytesSent     int
 	)
 
-	// any error handler stored ( ctx.SetErr or StopWith(Plain)Error )
+	if ac.shouldReadRequestBody() {
-	if ctxErr := ctx.GetErr(); ctxErr != nil {
+		//	any error handler stored ( ctx.SetErr or StopWith(Plain)Error )
-		requestBody = fmt.Sprintf("error(%s)", ctxErr.Error())
+		if ctxErr := ctx.GetErr(); ctxErr != nil {
-	} else if ac.RequestBody {
+			// If there is an error here
-		requestData, err := ctx.GetBody()
+			// we may need to NOT read the body for security reasons, e.g.
-		if err != nil {
+			// unauthorized user tries to send a malicious body.
 			requestBody = fmt.Sprintf("error(%s)", ctxErr.Error())
 		} else {
-			if ac.BodyMinify {
+			requestData, err := ctx.GetBody()
-				if minified, err := ctx.Application().Minifier().Bytes(ctx.GetContentTypeRequested(), requestData); err == nil {
+			requestBodyLength := len(requestData)
-					requestBody = string(minified)
+			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 ac.BytesReceived {
-			if requestBody == "" {
+				// Unfortunally the DumpRequest cannot read the body
-				requestBody = string(requestData)
+				// 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 ac.shouldReadResponseBody() {
-		if responseData := ctx.Recorder().Body(); len(responseData) > 0 {
+		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,
+			Logger:        ac,
-			Now:        now,
+			Now:           now,
-			TimeFormat: timeFormat,
+			TimeFormat:    timeFormat,
-			Timestamp:  now.Unix(),
+			Timestamp:     now.Unix(),
-			Latency:    latency,
+			Latency:       latency,
-			Method:     method,
+			Method:        method,
-			Path:       path,
+			Path:          path,
-			Code:       code,
+			Code:          code,
-			Query:      query,
+			Query:         query,
-			PathParams: params.Store,
+			PathParams:    params.Store,
-			Fields:     fields,
+			Fields:        fields,
-			Request:    reqBody,
+			BytesReceived: bytesReceived,
-			Response:   respBody,
+			BytesSent:     bytesSent,
-			Ctx:        ctx, // ctx should only be used here, it may be nil on testing.
+			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,
 	)

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"},

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 {