improvements on the new accesslog middleware

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

_examples/logging/request-logger/accesslog/main.go

@@ -1,18 +1,48 @@
 package main // See https://github.com/kataras/iris/issues/1601
 
 import (
+	"time"
+
 	"github.com/kataras/iris/v12"
 	"github.com/kataras/iris/v12/middleware/accesslog"
+
+	rotatelogs "github.com/lestrrat-go/file-rotatelogs"
 )
 
 func main() {
-	app := iris.New()
-	ac := accesslog.File("./access.log")
+	pathToAccessLog := "./access_log.%Y%m%d%H%M"
+	w, err := rotatelogs.New(
+		pathToAccessLog,
+		rotatelogs.WithMaxAge(24*time.Hour),
+		rotatelogs.WithRotationTime(time.Hour))
+	if err != nil {
+		panic(err)
+	}
+	ac := accesslog.New()
+	ac.SetOutput(w)
+	/*
+		Use a file directly:
+		ac := accesslog.File("./access.log")
+
+		Log after the response was sent:
+		ac.Async = true
+
+		Custom Time Format:
+		ac.TimeFormat = ""
+
+		Add second output:
+		ac.AddOutput(os.Stdout)
+
+		Change format (after output was set):
+		ac.SetFormatter(&accesslog.JSON{Indent: "  "})
+	*/
+
 	defer ac.Close()
 	iris.RegisterOnInterrupt(func() {
 		ac.Close()
 	})
 
+	app := iris.New()
 	// Register the middleware (UseRouter to catch http errors too).
 	app.UseRouter(ac.Handler)
 	//

context/context.go

@@ -163,13 +163,14 @@ func (ctx *Context) Clone() *Context {
 		queryCopy[k] = v
 	}
 
+	req := ctx.request.Clone(ctx.request.Context())
 	return &Context{
 		app:                 ctx.app,
 		values:              valuesCopy,
 		params:              RequestParams{Store: paramsCopy},
 		query:               queryCopy,
 		writer:              ctx.writer.Clone(),
-		request:             ctx.request,
+		request:             req,
 		currentHandlerIndex: stopExecutionIndex,
 		proceeded:           atomic.LoadUint32(&ctx.proceeded),
 		currentRoute:        ctx.currentRoute,

middleware/accesslog/accesslog.go

@@ -29,6 +29,12 @@ type AccessLog struct {
 	// If not empty then each one of them is called on `Close` method.
 	Closers []io.Closer
 
+	// If true then the middleware will fire the logs in a separate
+	// go routine, making the request to finish first.
+	// The log will be printed based on a copy of the Request's Context instead.
+	//
+	// Defaults to false.
+	Async bool
 	// If not empty then it overrides the Application's configuration's TimeFormat field.
 	TimeFormat string
 	// Force minify request and response contents.
@@ -39,14 +45,19 @@ type AccessLog struct {
 	// Enable response body logging.
 	// Note that, if this is true then it uses a response recorder.
 	ResponseBody bool
+
+	formatter Formatter
 }
 
 // New returns a new AccessLog value with the default values.
 // Writes to the Application's logger.
 // Register by its `Handler` method.
 // See `File` package-level function too.
+//
+// Example: https://github.com/kataras/iris/tree/master/_examples/logging/request-logger/accesslog
 func New() *AccessLog {
 	return &AccessLog{
+		Async:        false,
 		BodyMinify:   true,
 		RequestBody:  true,
 		ResponseBody: true,
@@ -85,6 +96,7 @@ func (ac *AccessLog) Write(p []byte) (int, error) {
 
 // SetOutput sets the log's output destination. Accepts one or more io.Writer values.
 // Also, if a writer is a Closer, then it is automatically appended to the Closers.
+// Call it before `SetFormatter` and `Handler` methods.
 func (ac *AccessLog) SetOutput(writers ...io.Writer) *AccessLog {
 	for _, w := range writers {
 		if closer, ok := w.(io.Closer); ok {
@@ -97,6 +109,7 @@ func (ac *AccessLog) SetOutput(writers ...io.Writer) *AccessLog {
 }
 
 // AddOutput appends an io.Writer value to the existing writer.
+// Call it before `SetFormatter` and `Handler` methods.
 func (ac *AccessLog) AddOutput(writers ...io.Writer) *AccessLog {
 	if ac.Writer != nil { // prepend if one exists.
 		writers = append([]io.Writer{ac.Writer}, writers...)
@@ -105,6 +118,19 @@ func (ac *AccessLog) AddOutput(writers ...io.Writer) *AccessLog {
 	return ac.SetOutput(writers...)
 }
 
+// SetFormatter sets a custom formatter to print the logs.
+// Any custom output writers should be
+// already registered before calling this method.
+// Returns this AccessLog instance.
+//
+// Usage:
+// ac.SetFormatter(&accesslog.JSON{Indent: "  "})
+func (ac *AccessLog) SetFormatter(f Formatter) *AccessLog {
+	f.SetOutput(ac.Writer) // inject the writer here.
+	ac.formatter = f
+	return ac
+}
+
 // Close calls each registered Closer's Close method.
 // Exits when all close methods have been executed.
 func (ac *AccessLog) Close() (err error) {
@@ -152,11 +178,18 @@ func (ac *AccessLog) Handler(ctx *context.Context) {
 	ctx.Next()
 
 	latency := time.Since(startTime)
-	ac.after(ctx, latency, method, path)
+	if ac.Async {
+		ctxCopy := ctx.Clone()
+		go ac.after(ctxCopy, latency, method, path)
+	} else {
+		// wait to finish before proceed with response end.
+		ac.after(ctx, latency, method, path)
+	}
 }
 
 func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path string) {
 	var (
+		now  = time.Now()
 		code = ctx.GetStatusCode() // response status code
 		// request and response data or error reading them.
 		requestBody  string
@@ -203,6 +236,27 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path
 		}
 	}
 
+	if f := ac.formatter; f != nil {
+		log := &Log{
+			Logger:     ac,
+			Now:        now,
+			Timestamp:  now.Unix(),
+			Latency:    lat,
+			Method:     method,
+			Path:       path,
+			Query:      ctx.URLParamsSorted(),
+			PathParams: ctx.Params().Store,
+			// TODO: Fields:
+			Request:  requestBody,
+			Response: responseBody,
+			Ctx:      ctx,
+		}
+
+		if f.Format(log) { // OK, it's handled, exit now.
+			return
+		}
+	}
+
 	var buf strings.Builder
 
 	if !context.StatusCodeNotSuccessful(code) {
@@ -239,7 +293,7 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path
 	// the number of separators are the same, in order to be easier
 	// for 3rd-party programs to read the result log file.
 	fmt.Fprintf(w, "%s|%s|%s|%s|%s|%d|%s|%s|\n",
-		time.Now().Format(timeFormat),
+		now.Format(timeFormat),
 		lat,
 		method,
 		path,

middleware/accesslog/log.go

@@ -0,0 +1,94 @@
+package accesslog
+
+import (
+	"encoding/json"
+	"io"
+	"sync"
+	"time"
+
+	"github.com/kataras/iris/v12/context"
+	"github.com/kataras/iris/v12/core/memstore"
+)
+
+// Log represents the log data specifically for the accesslog middleware.
+type Log struct {
+	// The AccessLog instance this Log was created of.
+	Logger *AccessLog `json:"-"`
+
+	// The time the log is created.
+	Now time.Time `json:"-"`
+	// Timestamp the Now's unix timestamp (seconds).
+	Timestamp int64 `json:"timestamp"`
+
+	// Request-Response latency.
+	Latency time.Duration `json:"latency"`
+	// Init request's Method and Path.
+	Method string `json:"method"`
+	Path   string `json:"path"`
+	// Sorted URL Query arguments.
+	Query []memstore.StringEntry
+	// Dynamic path parameters.
+	PathParams []memstore.Entry
+	// Fields any data information useful to represent this Log.
+	Fields context.Map `json:"fields,omitempty"`
+
+	// The Request and Response raw bodies.
+	// If they are escaped (e.g. JSON),
+	// A third-party software can read it through:
+	// data, _ := strconv.Unquote(log.Request)
+	// err := json.Unmarshal([]byte(data), &customStruct)
+	Request  string `json:"request"`
+	Response string `json:"response"`
+
+	// A copy of the Request's Context when Async is true (safe to use concurrently),
+	// otherwise it's the current Context (not safe for concurrent access).
+	Ctx *context.Context `json:"-"`
+}
+
+// Formatter is responsible to print a Log to the accesslog's writer.
+type Formatter interface {
+	// Format should print the Log.
+	// Returns true on handle successfully,
+	// otherwise the log will be printed using the default formatter.
+	Format(log *Log) bool
+	// SetWriter should inject the accesslog's output.
+	SetOutput(dest io.Writer)
+}
+
+// JSON is a Formatter type for JSON logs.
+type JSON struct {
+	Prefix, Indent string
+	EscapeHTML     bool
+
+	enc *json.Encoder
+	mu  sync.Mutex
+}
+
+// SetOutput creates the json encoder writes to the "dest".
+// It's called automatically by the middleware when this Formatter is used.
+func (f *JSON) SetOutput(dest io.Writer) {
+	if dest == nil {
+		return
+	}
+
+	// All logs share the same accesslog's writer and it cannot change during serve-time.
+	enc := json.NewEncoder(dest)
+	enc.SetEscapeHTML(f.EscapeHTML)
+	enc.SetIndent(f.Prefix, f.Indent)
+	f.enc = enc
+}
+
+// Format prints the logs in JSON format.
+func (f *JSON) Format(log *Log) bool {
+	f.mu.Lock()
+	if f.enc == nil {
+		// If no custom writer is given then f.enc is nil,
+		// this code block should only be executed once.
+		// Also, the app's logger's writer cannot change during serve-time,
+		// so all logs share the same instance output.
+		f.SetOutput(log.Ctx.Application().Logger().Printer)
+	}
+	err := f.enc.Encode(log)
+	f.mu.Unlock()
+	return err == nil
+}