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 {