From 61a9eff43e21f4deca4b5cf9f03935d7896ff64c Mon Sep 17 00:00:00 2001 From: "Gerasimos (Makis) Maropoulos" Date: Wed, 9 Sep 2020 08:21:10 +0300 Subject: [PATCH] accesslog middleware: more examples and usecase, e.g. log latency per handler and sessions values or authentication relative to: #1601 --- .../accesslog/access.log.sample | 3 + .../logging/request-logger/accesslog/main.go | 87 ++++++++++++++++--- middleware/accesslog/accesslog.go | 68 ++++++++++----- 3 files changed, 125 insertions(+), 33 deletions(-) diff --git a/_examples/logging/request-logger/accesslog/access.log.sample b/_examples/logging/request-logger/accesslog/access.log.sample index 4080fbad..2e25ae5f 100644 --- a/_examples/logging/request-logger/accesslog/access.log.sample +++ b/_examples/logging/request-logger/accesslog/access.log.sample @@ -4,3 +4,6 @@ 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:19:13|2.0053069s|GET|/fields|fieldsHandler_latency=2s|200|570 B|130 B||OK| diff --git a/_examples/logging/request-logger/accesslog/main.go b/_examples/logging/request-logger/accesslog/main.go index cd8cd911..621654d6 100644 --- a/_examples/logging/request-logger/accesslog/main.go +++ b/_examples/logging/request-logger/accesslog/main.go @@ -5,11 +5,15 @@ import ( "github.com/kataras/iris/v12" "github.com/kataras/iris/v12/middleware/accesslog" + "github.com/kataras/iris/v12/middleware/basicauth" + "github.com/kataras/iris/v12/middleware/requestid" + "github.com/kataras/iris/v12/sessions" rotatelogs "github.com/lestrrat-go/file-rotatelogs" ) -func main() { +func makeAccessLog() *accesslog.AccessLog { + // Optionally, let's Go with log rotation. pathToAccessLog := "./access_log.%Y%m%d%H%M" w, err := rotatelogs.New( pathToAccessLog, @@ -18,9 +22,36 @@ func main() { if err != nil { panic(err) } + + // Initialize a new access log middleware. + // Accepts an `io.Writer`. ac := accesslog.New(w) ac.TimeFormat = "2006-01-02 15:04:05" + // Example of adding more than one field to the logger. + // Here we logging all the session values this request has. + // + // You can also add fields per request handler, + // look below to the `fieldsHandler` function. + // Note that this method can override a key stored by a handler's fields. + ac.AddFields(func(ctx iris.Context, fields *accesslog.Fields) { + if sess := sessions.Get(ctx); sess != nil { + fields.Set("session_id", sess.ID()) + + sess.Visit(func(k string, v interface{}) { + fields.Set(k, v) + }) + } + }) + // Add a custom field of "auth" when basic auth is available. + ac.AddFields(func(ctx iris.Context, fields *accesslog.Fields) { + if username, password, ok := ctx.Request().BasicAuth(); ok { + fields.Set("auth", username+":"+password) + } + }) + + return ac + /* Use a file directly: ac := accesslog.File("./access.log") @@ -41,6 +72,8 @@ func main() { Add second output: ac.AddOutput(app.Logger().Printer) + OR: + accesslog.New(io.MultiWriter(w, os.Stdout)) Change format (after output was set): ac.SetFormatter(&accesslog.JSON{Indent: " "}) @@ -51,17 +84,11 @@ func main() { Text: "{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Method}}|{{.Path}}|{{.RequestValuesLine}}|{{.Code}}|{{.BytesReceivedLine}}|{{.BytesSentLine}}|{{.Request}}|{{.Response}}|\n", // Default ^ }) - - Set custom request fields: - ac.AddField(func(ctx iris.Context) (string, interface{}) { - v := ctx.RemoteAddr() - if v == "" { - return "", nil - } - // the log entry name and its value. - return "IP", v - }) */ +} + +func main() { + ac := makeAccessLog() defer ac.Close() iris.RegisterOnInterrupt(func() { @@ -73,12 +100,25 @@ func main() { app.UseRouter(ac.Handler) // + // Register other middlewares... + app.UseRouter(requestid.New()) + // Register some routes... app.HandleDir("/", iris.Dir("./public")) app.Get("/user/{username}", userHandler) app.Post("/read_body", readBodyHandler) app.Get("/html_response", htmlResponse) + + basicAuth := basicauth.Default(map[string]string{ + "admin": "admin", + }) + app.Get("/admin", basicAuth, adminHandler) + + sess := sessions.New(sessions.Config{Cookie: "my_session_id", AllowReclaim: true}) + app.Get("/session", sess.Handler(), sessionHandler) + + app.Get("/fields", fieldsHandler) // app.Listen(":8080") @@ -101,3 +141,28 @@ func userHandler(ctx iris.Context) { func htmlResponse(ctx iris.Context) { ctx.HTML("

HTML Response

") } + +func adminHandler(ctx iris.Context) { + username, password, _ := ctx.Request().BasicAuth() + // of course you don't want that in production: + ctx.HTML("

Username: %s

Password: %s

", username, password) +} + +func sessionHandler(ctx iris.Context) { + sess := sessions.Get(ctx) + sess.Set("session_test_key", "session_test_value") + + ctx.WriteString("OK") +} + +func fieldsHandler(ctx iris.Context) { + now := time.Now() + logFields := accesslog.GetFields(ctx) + defer func() { + logFields.Set("fieldsHandler_latency", time.Since(now).Round(time.Second)) + }() + + // simulate a heavy job... + time.Sleep(2 * time.Second) + ctx.WriteString("OK") +} diff --git a/middleware/accesslog/accesslog.go b/middleware/accesslog/accesslog.go index 0fe27244..e237c438 100644 --- a/middleware/accesslog/accesslog.go +++ b/middleware/accesslog/accesslog.go @@ -9,13 +9,39 @@ import ( "sync" "time" + "github.com/kataras/iris/v12" "github.com/kataras/iris/v12/context" "github.com/kataras/iris/v12/core/memstore" ) -// FieldExtractor extracts a log's entry key with its corresponding value. -// If key or value is empty then this field is not printed. -type FieldExtractor func(*context.Context) (string, interface{}) +func init() { + context.SetHandlerName("iris/middleware/accesslog.*", "iris.accesslog") +} + +const accessLogFieldsContextKey = "iris.accesslog.request.fields" + +// 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) { + if v := ctx.Values().Get(accessLogFieldsContextKey); v != nil { + fields = v.(*Fields) + } else { + fields = new(Fields) + ctx.Values().Set(accessLogFieldsContextKey, fields) + } + + return +} + +type ( + + // Fields is a type alias for memstore.Store, used to set + // more than one field at serve-time. Same as FieldExtractor. + Fields = memstore.Store + // FieldSetter sets one or more fields at once. + FieldSetter func(*context.Context, *Fields) +) type ( // Clock is an interface which contains a single `Now` method. @@ -105,8 +131,8 @@ type AccessLog struct { ResponseBody bool // Map log fields with custom request values. - // See `Log.Fields`. - Fields []FieldExtractor + // See `AddFields` method. + FieldSetters []FieldSetter // Note: We could use a map but that way we lose the // order of registration so use a slice and // take the field key from the extractor itself. @@ -226,10 +252,11 @@ func (ac *AccessLog) SetFormatter(f Formatter) *AccessLog { return ac } -// AddField maps a log entry with a value extracted by the Request Context. -// Not safe for concurrent use. Call it before `Handler` method. -func (ac *AccessLog) AddField(extractors ...FieldExtractor) *AccessLog { - ac.Fields = append(ac.Fields, extractors...) +// AddFields maps one or more log entries with values extracted by the Request Context. +// You can also add fields per request handler, look the `GetFields` package-level function. +// Note that this method can override a key stored by a handler's fields. +func (ac *AccessLog) AddFields(setters ...FieldSetter) *AccessLog { + ac.FieldSetters = append(ac.FieldSetters, setters...) return ac } @@ -285,6 +312,12 @@ func (ac *AccessLog) Handler(ctx *context.Context) { ctx.RecordBody() } + // Set the fields context value so they can be modified + // on the following handlers chain. Same as `AddFields` but per-request. + // ctx.Values().Set(accessLogFieldsContextKey, new(Fields)) + // No need ^ The GetFields will set it if it's missing. + // So we initialize them whenever, and if, asked. + // Proceed to the handlers chain. ctx.Next() @@ -373,19 +406,10 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path } // Grab any custom fields. - var fields []memstore.Entry + fields := GetFields(ctx) - if n := len(ac.Fields); n > 0 { - fields = make([]memstore.Entry, 0, n) - - for _, extract := range ac.Fields { - key, value := extract(ctx) - if key == "" || value == nil { - continue - } - - fields = append(fields, memstore.Entry{Key: key, ValueRaw: value}) - } + for _, setter := range ac.FieldSetters { + setter(ctx, fields) } timeFormat := ac.TimeFormat @@ -403,7 +427,7 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path method, path, requestBody, responseBody, bytesReceived, bytesSent, - ctx.Params(), ctx.URLParamsSorted(), fields, + ctx.Params(), ctx.URLParamsSorted(), *fields, ); err != nil { ctx.Application().Logger().Errorf("accesslog: %v", err) }