diff --git a/_examples/logging/request-logger/accesslog/main.go b/_examples/logging/request-logger/accesslog/main.go index e2cfb16c..7b03fc07 100644 --- a/_examples/logging/request-logger/accesslog/main.go +++ b/_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) // diff --git a/context/context.go b/context/context.go index a0311277..1512b8d7 100644 --- a/context/context.go +++ b/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, diff --git a/middleware/accesslog/accesslog.go b/middleware/accesslog/accesslog.go index 75068e67..09c4e00a 100644 --- a/middleware/accesslog/accesslog.go +++ b/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, diff --git a/middleware/accesslog/log.go b/middleware/accesslog/log.go new file mode 100644 index 00000000..dc1f1cd0 --- /dev/null +++ b/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 +}