accesslog middleware: more examples and usecase, e.g. log latency per handler and sessions values or authentication

relative to: #1601

_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||<h2>Username: admin</h2><h3>Password: admin</h3>|
+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|

_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("<h1>HTML Response</h1>")
 }
+
+func adminHandler(ctx iris.Context) {
+	username, password, _ := ctx.Request().BasicAuth()
+	// of course you don't want that in production:
+	ctx.HTML("<h2>Username: %s</h2><h3>Password: %s</h3>", 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")
+}

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