From e63d1041d20c22c4984649959fb76a315885bb55 Mon Sep 17 00:00:00 2001 From: "Gerasimos (Makis) Maropoulos" Date: Fri, 11 Sep 2020 09:38:55 +0300 Subject: [PATCH] accesslog: add IP in builtin fields, change the format a bit. Default func: remove compression middleware, force-set debug log level, replace the old request logger with the accesslog one, use request id middlewareand keep recovery --- .gitignore | 2 +- .../request-logger/accesslog-broker/main.go | 4 +- .../request-logger/accesslog-template/main.go | 13 +++--- .../accesslog/access.log.sample | 18 ++++---- .../logging/request-logger/accesslog/main.go | 5 ++- core/router/api_builder.go | 2 +- iris.go | 43 +++++++++++++++---- middleware/accesslog/accesslog.go | 39 +++++++++++------ middleware/accesslog/accesslog_test.go | 7 +-- middleware/accesslog/log.go | 8 ++-- 10 files changed, 95 insertions(+), 46 deletions(-) diff --git a/.gitignore b/.gitignore index f4787c15..c2def0f3 100644 --- a/.gitignore +++ b/.gitignore @@ -4,6 +4,6 @@ coverage.out package-lock.json go.sum node_modules -/_examples/issue-*/ +issue-*/ /_examples/feature-*/ _examples/**/uploads/* diff --git a/_examples/logging/request-logger/accesslog-broker/main.go b/_examples/logging/request-logger/accesslog-broker/main.go index ed970ba1..5a9dc132 100644 --- a/_examples/logging/request-logger/accesslog-broker/main.go +++ b/_examples/logging/request-logger/accesslog-broker/main.go @@ -18,9 +18,9 @@ func main() { */ ac := accesslog.File("./access.log") - ac.AddOutput(os.Stdout) + defer ac.Close() - ac.TimeFormat = "2006-01-02 15:04:05" + ac.AddOutput(os.Stdout) // Set to false to print errors as one line: // ac.KeepMultiLineError = false diff --git a/_examples/logging/request-logger/accesslog-template/main.go b/_examples/logging/request-logger/accesslog-template/main.go index 5401a067..2502a1d1 100644 --- a/_examples/logging/request-logger/accesslog-template/main.go +++ b/_examples/logging/request-logger/accesslog-template/main.go @@ -3,6 +3,7 @@ package main import ( "github.com/kataras/iris/v12" "github.com/kataras/iris/v12/middleware/accesslog" + "github.com/kataras/iris/v12/middleware/requestid" ) func main() { @@ -14,21 +15,23 @@ func main() { app := iris.New() ac := accesslog.File("./access.log").AddOutput(app.Logger().Printer) - ac.TimeFormat = "2006-01-02 15:04:05" // 1. Register a field. ac.AddFields(func(ctx iris.Context, fields *accesslog.Fields) { - fields.Set("IP", ctx.RemoteAddr()) + fields.Set("Request ID", ctx.GetID()) }) // 2. Use Template formatter's `Text` value // to define a log line format. ac.SetFormatter(&accesslog.Template{ - Text: `{{.Now.Format .TimeFormat}} {{.Path}} {{.Code}} {{.Fields.Get "IP" }} -`, /* 2020-09-10 21:38:13 / 200 ::1 */ + Text: `{{.Now.Format .TimeFormat}} {{.Path}} {{.Code}} {{.IP}} {{.Fields.Get "Request ID" }} +`, /* 2020-09-11 09:30:10 / 200 ::1 050a0979-c5e4-4c2b-9f08-cb456628edb1 */ }) // 3. Register the middleware. That's all. app.UseRouter(ac.Handler) + // Register the request id middleware, after the logger, this maps the Context.GetID(). + // Remember: the accesslog runs the next handlers before itself to provide some fields. + app.UseRouter(requestid.New()) app.Get("/", index) @@ -42,7 +45,7 @@ func index(ctx iris.Context) { /* Use a custom *template.Template: // 2.1 The log line format: -text := `{{.Now.Format .TimeFormat}} {{.Path}} {{.Code}} {{.Fields.Get "IP" }} +text := `{{.Now.Format .TimeFormat}} {{.Path}} {{.Code}} {{.IP}} {{.Fields.Get "Request ID" }} ` // // 2.2 Parse the template, optionally using custom Template Functions. diff --git a/_examples/logging/request-logger/accesslog/access.log.sample b/_examples/logging/request-logger/accesslog/access.log.sample index 45979b0d..0b9d9ea0 100644 --- a/_examples/logging/request-logger/accesslog/access.log.sample +++ b/_examples/logging/request-logger/accesslog/access.log.sample @@ -1,9 +1,9 @@ -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!| -2020-09-08 20:37:33|0s|GET|/admin|auth=admin:admin|200|608 B|164 B||

Username: admin

Password: admin

| -2020-09-09 07:56:00|738.1µs|GET|/session|session_id=23fe763f-c9d5-4d65-9e1a-2cc8d23d1aa3 session_test_key=session_test_value|200|818 B|302 B||OK| -2020-09-09 08:36:47|2.0095505s|GET|/fields|job_latency=2s|200|544 B|130 B||OK| +2020-09-08 13:34:42|0s|200|POST|/read_body|::1||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|400|POST|/read_body|::1|||85 B|error(invalid character '\r' in string literal)|| +2020-09-08 13:41:05|1.0024ms|200|GET|/|a=1 b=2|767 B|251 B||

Hello index

| +2020-09-08 13:41:26|0s|404|GET|/public|::1||765 B|83 B||| +2020-09-08 13:41:36|0s|200|GET|/user/kataras|::1|username=kataras|771 B|91 B||Hello, kataras!| +2020-09-08 13:41:47|0s|200|GET|/user/kataras|::1|username=kataras a_query_parameter=name|774 B|91 B||Hello, kataras!| +2020-09-08 20:37:33|0s|200|GET|/admin|::1|auth=admin:admin|608 B|164 B||

Username: admin

Password: admin

| +2020-09-09 07:56:00|738.1µs|200|GET|/session|::1|session_id=23fe763f-c9d5-4d65-9e1a-2cc8d23d1aa3 session_test_key=session_test_value|818 B|302 B||OK| +2020-09-09 08:36:47|2.0095505s|200|GET|/fields|::1|job_latency=2s|544 B|130 B||OK| diff --git a/_examples/logging/request-logger/accesslog/main.go b/_examples/logging/request-logger/accesslog/main.go index 315d0a5d..24e7c205 100644 --- a/_examples/logging/request-logger/accesslog/main.go +++ b/_examples/logging/request-logger/accesslog/main.go @@ -26,7 +26,8 @@ func makeAccessLog() *accesslog.AccessLog { // Initialize a new access log middleware. // Accepts an `io.Writer`. ac := accesslog.New(w) - ac.TimeFormat = "2006-01-02 15:04:05" + defer ac.Close() + // ac.TimeFormat = "2006-01-02 15:04:05" // default // Example of adding more than one field to the logger. // Here we logging all the session values this request has. @@ -81,7 +82,7 @@ func makeAccessLog() *accesslog.AccessLog { 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}}|{{.BytesReceivedLine}}|{{.BytesSentLine}}|{{.Request}}|{{.Response}}|\n", + Text: "{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Code}}|{{.Method}}|{{.Path}}|{{.IP}}|{{.RequestValuesLine}}|{{.BytesReceivedLine}}|{{.BytesSentLine}}|{{.Request}}|{{.Response}}|\n", // Default ^ }) */ diff --git a/core/router/api_builder.go b/core/router/api_builder.go index 2904a982..46ee5526 100644 --- a/core/router/api_builder.go +++ b/core/router/api_builder.go @@ -961,7 +961,7 @@ func (api *APIBuilder) GetRouterFilters() map[Party]*Filter { // The context SHOULD call its `Next` method in order to proceed to // the next handler in the chain or the main request handler one. func (api *APIBuilder) UseRouter(handlers ...context.Handler) { - if len(handlers) == 0 { + if len(handlers) == 0 || handlers[0] == nil { return } diff --git a/iris.go b/iris.go index 9741ce9e..2927583f 100644 --- a/iris.go +++ b/iris.go @@ -19,8 +19,9 @@ import ( "github.com/kataras/iris/v12/core/netutil" "github.com/kataras/iris/v12/core/router" "github.com/kataras/iris/v12/i18n" - requestLogger "github.com/kataras/iris/v12/middleware/logger" + "github.com/kataras/iris/v12/middleware/accesslog" "github.com/kataras/iris/v12/middleware/recover" + "github.com/kataras/iris/v12/middleware/requestid" "github.com/kataras/iris/v12/view" "github.com/kataras/golog" @@ -128,14 +129,40 @@ func New() *Application { return app } -// Default returns a new Application instance which on build state registers -// html view engine on "./views" and load locales from "./locales/*/*". -// The return instance recovers on panics and logs the incoming http requests too. +// Default returns a new Application. +// Default with "debug" Logger Level. +// Localization enabled on "./locales" directory +// and HTML templates on "./views" or "./templates" directory. +// It runs with the AccessLog on "./access.log", +// Recovery and Request ID middleware already attached. func Default() *Application { app := New() + // Set default log level. + app.logger.SetLevel("debug") + app.logger.Debugf(`Log level set to "debug"`) + + // Register the accesslog middleware. + logFile, err := os.OpenFile("./access.log", os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0666) + if err == nil { + // Close the file on shutdown. + app.ConfigureHost(func(su *Supervisor) { + su.RegisterOnShutdown(func() { + logFile.Close() + }) + }) + + app.UseRouter(accesslog.New(logFile).Handler) + app.logger.Debugf("Using <%s> to log requests", logFile.Name()) + } + + // Register the requestid middleware + // before recover so current Context.GetID() contains the info on panic logs. + app.UseRouter(requestid.New()) + app.logger.Debugf("Using to identify requests") + + // Register the recovery, after accesslog and recover, + // before end-developer's middleware. app.UseRouter(recover.New()) - app.UseRouter(requestLogger.New()) - app.UseRouter(Compression) app.defaultMode = true @@ -544,7 +571,7 @@ func (app *Application) Build() error { if app.defaultMode { // the app.I18n and app.View will be not available until Build. if !app.I18n.Loaded() { for _, s := range []string{"./locales/*/*", "./locales/*", "./translations"} { - if _, err := os.Stat(s); os.IsNotExist(err) { + if _, err := os.Stat(s); err != nil { continue } @@ -559,7 +586,7 @@ func (app *Application) Build() error { if app.view.Len() == 0 { for _, s := range []string{"./views", "./templates", "./web/views"} { - if _, err := os.Stat(s); os.IsNotExist(err) { + if _, err := os.Stat(s); err != nil { continue } diff --git a/middleware/accesslog/accesslog.go b/middleware/accesslog/accesslog.go index c0ada885..89bc4541 100644 --- a/middleware/accesslog/accesslog.go +++ b/middleware/accesslog/accesslog.go @@ -10,7 +10,6 @@ import ( "sync" "time" - "github.com/kataras/iris/v12" "github.com/kataras/iris/v12/context" "github.com/kataras/iris/v12/core/memstore" ) @@ -27,7 +26,7 @@ const ( // GetFields returns the accesslog fields for this request. // Returns a store which the caller can use to // set/get/remove custom log fields. Use its `Set` method. -func GetFields(ctx iris.Context) (fields *Fields) { +func GetFields(ctx *context.Context) (fields *Fields) { if v := ctx.Values().Get(fieldsContextKey); v != nil { fields = v.(*Fields) } else { @@ -40,18 +39,18 @@ func GetFields(ctx iris.Context) (fields *Fields) { // Skip called when a specific route should be skipped from the logging process. // It's an easy to use alternative for iris.NewConditionalHandler. -func Skip(ctx iris.Context) { +func Skip(ctx *context.Context) { ctx.Values().Set(skipLogContextKey, struct{}{}) } // SkipHandler same as `Skip` but it can be used // as a middleware, it executes ctx.Next(). -func SkipHandler(ctx iris.Context) { +func SkipHandler(ctx *context.Context) { Skip(ctx) ctx.Next() } -func shouldSkip(ctx iris.Context) bool { +func shouldSkip(ctx *context.Context) bool { return ctx.Values().Get(skipLogContextKey) != nil } @@ -134,9 +133,11 @@ type AccessLog struct { // Defaults to false. Async bool // The time format for current time on log print. - // Defaults to the Iris Application's TimeFormat. + // Defaults to ""2006-01-02 15:04:05" on `New` function. + // Set it to empty to inherit the Iris Application's TimeFormat. TimeFormat string - + // IP displays the remote address. + IP bool // 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). @@ -197,10 +198,15 @@ const ( // Register by its `Handler` method. // See `File` package-level function too. // -// Example: https://github.com/kataras/iris/tree/master/_examples/logging/request-logger/accesslog +// Examples: +// https://github.com/kataras/iris/tree/master/_examples/logging/request-logger/accesslog +// https://github.com/kataras/iris/tree/master/_examples/logging/request-logger/accesslog-template +// https://github.com/kataras/iris/tree/master/_examples/logging/request-logger/accesslog-broker func New(w io.Writer) *AccessLog { ac := &AccessLog{ Clock: clockFunc(time.Now), + TimeFormat: "2006-01-02 15:04:05", + IP: true, BytesReceived: true, BytesSent: true, BodyMinify: true, @@ -527,6 +533,11 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path timeFormat = ctx.Application().ConfigurationReadOnly().GetTimeFormat() } + ip := "" + if ac.IP { + ip = ctx.RemoteAddr() + } + if err := ac.Print(ctx, // latency between begin and finish of the handlers chain. lat, @@ -535,6 +546,8 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path ctx.GetStatusCode(), // original request's method and path. method, path, + // remote ip. + ip, requestBody, responseBody, bytesReceived, bytesSent, ctx.Params(), ctx.URLParamsSorted(), *fields, @@ -545,7 +558,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, bytesReceived, bytesSent int, params *context.RequestParams, query []memstore.StringEntry, fields []memstore.Entry) (err error) { +func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeFormat string, code int, method, path, ip, reqBody, respBody string, bytesReceived, bytesSent int, params *context.RequestParams, query []memstore.StringEntry, fields []memstore.Entry) (err error) { now := ac.Clock.Now() if hasFormatter, hasBroker := ac.formatter != nil, ac.broker != nil; hasFormatter || hasBroker { @@ -555,9 +568,10 @@ func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeForm log.TimeFormat = timeFormat log.Timestamp = now.UnixNano() / 1000000 log.Latency = latency + log.Code = code log.Method = method log.Path = path - log.Code = code + log.IP = ip log.Query = query log.PathParams = params.Store log.Fields = fields @@ -593,13 +607,14 @@ 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|%s|%s|\n", + _, err = fmt.Fprintf(ac, "%s|%s|%d|%s|%s|%s|%s|%s|%s|%s|%s|\n", now.Format(timeFormat), latency, + code, method, path, + ip, requestValues, - code, formatBytes(bytesReceived), formatBytes(bytesSent), reqBody, diff --git a/middleware/accesslog/accesslog_test.go b/middleware/accesslog/accesslog_test.go index 7ff2bb67..3d414fb9 100644 --- a/middleware/accesslog/accesslog_test.go +++ b/middleware/accesslog/accesslog_test.go @@ -35,7 +35,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|200|GET|/path_value?url_query=url_query_value|::1|path_param=path_param_value url_query=url_query_value custom=custom_value|||Incoming|Outcoming|\n" go func() { defer wg.Done() @@ -47,6 +47,7 @@ func TestAccessLogPrint_Simple(t *testing.T) { 200, "GET", "/path_value?url_query=url_query_value", + "::1", "Incoming", "Outcoming", 0, @@ -73,7 +74,6 @@ func TestAccessLogPrint_Simple(t *testing.T) { func TestAccessLogBroker(t *testing.T) { w := new(bytes.Buffer) ac := New(w) - ac.TimeFormat = "2006-01-02 15:04:05" ac.Clock = TClock(time.Time{}) broker := ac.Broker() @@ -123,6 +123,7 @@ func TestAccessLogBroker(t *testing.T) { "", "", "", + "", 0, 0, &context.RequestParams{}, @@ -161,7 +162,6 @@ func (*noOpFormatter) Format(*Log) (bool, error) { func BenchmarkAccessLogAfter(b *testing.B) { ac := New(ioutil.Discard) ac.Clock = TClock(time.Time{}) - ac.TimeFormat = "2006-01-02 15:04:05" ac.BytesReceived = false ac.BytesSent = false ac.BodyMinify = false @@ -169,6 +169,7 @@ func BenchmarkAccessLogAfter(b *testing.B) { ac.ResponseBody = false ac.KeepMultiLineError = true ac.Async = false + ac.IP = false ac.SetFormatter(new(noOpFormatter)) // just to create the log structure.) ctx := new(context.Context) diff --git a/middleware/accesslog/log.go b/middleware/accesslog/log.go index bc9792ee..00e7d838 100644 --- a/middleware/accesslog/log.go +++ b/middleware/accesslog/log.go @@ -28,11 +28,13 @@ type Log struct { // Request-Response latency. Latency time.Duration `json:"latency"` + // The response status code. + Code int `json:"code"` // Init request's Method and Path. Method string `json:"method"` Path string `json:"path"` - // The response status code. - Code int `json:"code"` + // The Remote Address. + IP string `json:"ip,omitempty"` // Sorted URL Query arguments. Query []memstore.StringEntry `json:"query,omitempty"` // Dynamic path parameters. @@ -223,7 +225,7 @@ func (f *Template) SetOutput(dest io.Writer) { f.dest = dest } -const defaultTmplText = "{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Method}}|{{.Path}}|{{.RequestValuesLine}}|{{.Code}}|{{.BytesReceivedLine}}|{{.BytesSentLine}}|{{.Request}}|{{.Response}}|\n" +const defaultTmplText = "{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Code}}|{{.Method}}|{{.Path}}|{{.IP}}|{{.RequestValuesLine}}|{{.BytesReceivedLine}}|{{.BytesSentLine}}|{{.Request}}|{{.Response}}|\n" // Format prints the logs in text/template format. func (f *Template) Format(log *Log) (bool, error) {