From dac834cf119fc1b988a3852a892d000a503ed7da Mon Sep 17 00:00:00 2001 From: "Gerasimos (Makis) Maropoulos" Date: Mon, 7 Sep 2020 18:04:35 +0300 Subject: [PATCH] new accesslog middleware: require the writer inside its constructor so we can 'detect' if we must force-lock a writer relative to: https://github.com/kataras/iris/issues/1601 --- .../logging/request-logger/accesslog/main.go | 13 ++- middleware/accesslog/accesslog.go | 89 ++++++++++--------- middleware/accesslog/accesslog_test.go | 9 +- middleware/accesslog/log.go | 27 +++--- 4 files changed, 70 insertions(+), 68 deletions(-) diff --git a/_examples/logging/request-logger/accesslog/main.go b/_examples/logging/request-logger/accesslog/main.go index f19f3fd3..be6a9585 100644 --- a/_examples/logging/request-logger/accesslog/main.go +++ b/_examples/logging/request-logger/accesslog/main.go @@ -18,8 +18,8 @@ func main() { if err != nil { panic(err) } - ac := accesslog.New() - ac.SetOutput(w) + ac := accesslog.New(w) + ac.TimeFormat = "2006-01-02 15:04:05" /* Use a file directly: @@ -28,12 +28,9 @@ func main() { Log after the response was sent: ac.Async = true - Protect writer with locks. - On this example this is not required but enable it on os.Stdout and e.t.c: - ac.LockWriter = true - - Custom Time Format: - ac.TimeFormat = "" + Force-protect writer with locks. + On this example this is not required: + ac.LockWriter = true" Add second output: ac.AddOutput(app.Logger().Printer) diff --git a/middleware/accesslog/accesslog.go b/middleware/accesslog/accesslog.go index ccc5ba56..91ca4129 100644 --- a/middleware/accesslog/accesslog.go +++ b/middleware/accesslog/accesslog.go @@ -1,6 +1,7 @@ package accesslog import ( + "bytes" "fmt" "io" "os" @@ -47,18 +48,17 @@ var ( // and its `Handler` method to learn more. type AccessLog struct { mu sync.Mutex // ensures atomic writes. - // If not nil then it overrides the Application's Logger. - // Useful to write to a file. + // The destination writer. // If multiple output required, then define an `io.MultiWriter`. // See `SetOutput` and `AddOutput` methods too. Writer io.Writer // If enabled, it locks the underline Writer. // It should be turned off if the given `Writer` is already protected with a locker. - // It should be enabled when you don't know if the writer locks itself - // or when the writer is os.Stdout/os.Stderr and e.t.c. + // It is enabled when writer is os.Stdout/os.Stderr. + // You should manually set this field to true if you are not sure + // whether the underline Writer is protected. // - // Defaults to false, - // as the default Iris Application's Logger is protected with mutex. + // Defaults to true on *os.File and *bytes.Buffer, otherwise false. LockWriter bool // If not empty then each one of them is called on `Close` method. @@ -82,7 +82,8 @@ type AccessLog struct { // // Defaults to false. Async bool - // If not empty then it overrides the Application's configuration's TimeFormat field. + // The time format for current time on log print. + // Defaults to the Iris Application's TimeFormat. TimeFormat string // Force minify request and response contents. BodyMinify bool @@ -103,20 +104,24 @@ type AccessLog struct { } // New returns a new AccessLog value with the default values. -// Writes to the Application's logger. Output be modified through its `SetOutput` method. +// Writes to the "w". Output be further modified through its `Set/AddOutput` methods. // 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, - LockWriter: false, +func New(w io.Writer) *AccessLog { + ac := &AccessLog{ BodyMinify: true, RequestBody: true, ResponseBody: true, - TimeFormat: "2006-01-02 15:04:05", } + + if w == nil { + w = os.Stdout + } + ac.SetOutput(w) + + return ac } // File returns a new AccessLog value with the given "path" @@ -133,18 +138,20 @@ func File(path string) *AccessLog { panic(err) } - ac := New() - ac.SetOutput(f) - return ac + return New(f) } // Write writes to the log destination. // It completes the io.Writer interface. // Safe for concurrent use. func (ac *AccessLog) Write(p []byte) (int, error) { - ac.mu.Lock() + if ac.LockWriter { + ac.mu.Lock() + } n, err := ac.Writer.Write(p) - ac.mu.Unlock() + if ac.LockWriter { + ac.mu.Unlock() + } return n, err } @@ -152,17 +159,28 @@ func (ac *AccessLog) Write(p []byte) (int, error) { // 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 { + if len(writers) == 0 { + return ac + } + + lockWriter := false for _, w := range writers { if closer, ok := w.(io.Closer); ok { ac.Closers = append(ac.Closers, closer) } - } - switch len(writers) { - case 0: - case 1: + if !lockWriter { + switch w.(type) { + case *os.File, *bytes.Buffer: // force lock writer. + lockWriter = true + } + } + } + ac.LockWriter = lockWriter + + if len(writers) == 1 { ac.Writer = writers[0] - default: + } else { ac.Writer = io.MultiWriter(writers...) } @@ -187,6 +205,10 @@ func (ac *AccessLog) AddOutput(writers ...io.Writer) *AccessLog { // Usage: // ac.SetFormatter(&accesslog.JSON{Indent: " "}) func (ac *AccessLog) SetFormatter(f Formatter) *AccessLog { + if ac.Writer == nil { + panic("accesslog: SetFormatter called with nil Writer") + } + f.SetOutput(ac.Writer) // inject the writer here. ac.formatter = f return ac @@ -220,7 +242,7 @@ func (ac *AccessLog) Close() (err error) { // It is the main method of the AccessLog middleware. // // Usage: -// ac := New() or File("access.log") +// ac := New(io.Writer) or File("access.log") // defer ac.Close() // app.UseRouter(ac.Handler) func (ac *AccessLog) Handler(ctx *context.Context) { @@ -375,23 +397,9 @@ func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeForm // key=value key2=value2. requestValues := parseRequestValues(code, params, query, fields) - useLocker := ac.LockWriter - w := ac.Writer - if w == nil { - if ctx != nil { - w = ctx.Application().Logger().Printer - } else { - w = os.Stdout - useLocker = true // force lock. - } - } - - if useLocker { - ac.mu.Lock() - } // 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(w, "%s|%s|%s|%s|%s|%d|%s|%s|\n", + _, err := fmt.Fprintf(ac, "%s|%s|%s|%s|%s|%d|%s|%s|\n", now.Format(timeFormat), latency, method, @@ -401,9 +409,6 @@ func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeForm reqBody, respBody, ) - if useLocker { - ac.mu.Unlock() - } return err } diff --git a/middleware/accesslog/accesslog_test.go b/middleware/accesslog/accesslog_test.go index 59106b0f..7773c152 100644 --- a/middleware/accesslog/accesslog_test.go +++ b/middleware/accesslog/accesslog_test.go @@ -15,11 +15,14 @@ func TestAccessLogPrint_Simple(t *testing.T) { const goroutinesN = 42 w := new(bytes.Buffer) - ac := New() - ac.Writer = w - ac.LockWriter = true + ac := New(w) + ac.TimeFormat = "2006-01-02 15:04:05" ac.Clock = TClock(time.Time{}) + if !ac.LockWriter { // should be true because we register a *bytes.Buffer. + t.Fatalf("expected LockRriter to be true") + } + var ( expected string wg = new(sync.WaitGroup) diff --git a/middleware/accesslog/log.go b/middleware/accesslog/log.go index 68ae442f..8c84338a 100644 --- a/middleware/accesslog/log.go +++ b/middleware/accesslog/log.go @@ -100,7 +100,9 @@ type Formatter interface { // otherwise the log will be printed using the default formatter // and the error will be printed to the Iris Application's error log level. Format(log *Log) error - // SetWriter should inject the accesslog's output. + // SetWriter should inject the accesslog's direct output, + // if this "dest" is used then the Formatter + // should manually control its concurrent use. SetOutput(dest io.Writer) } @@ -133,15 +135,10 @@ func (f *JSON) SetOutput(dest io.Writer) { } // Format prints the logs in JSON format. +// Writes to the destination directly, +// locks on each Format call. func (f *JSON) Format(log *Log) error { 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() @@ -162,7 +159,8 @@ type Template struct { // is response to hold the log result. TmplName string - mu sync.Mutex + dest io.Writer + mu sync.Mutex } // SetOutput creates the default template if missing @@ -176,24 +174,23 @@ func (f *Template) SetOutput(dest io.Writer) { f.Tmpl = template.Must(template.New("").Parse(text)) } + + f.dest = dest } const defaultTmplText = "{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Method}}|{{.Path}}|{{.RequestValuesLine}}|{{.Code}}|{{.Request}}|{{.Response}}|\n" // Format prints the logs in text/template format. func (f *Template) Format(log *Log) error { - var ( - w = log.Logger.Writer - err error - ) + var err error // A template may be executed safely in parallel, although if parallel // executions share a Writer the output may be interleaved. f.mu.Lock() if f.TmplName != "" { - err = f.Tmpl.ExecuteTemplate(w, f.TmplName, log) + err = f.Tmpl.ExecuteTemplate(f.dest, f.TmplName, log) } else { - err = f.Tmpl.Execute(w, log) + err = f.Tmpl.Execute(f.dest, log) } f.mu.Unlock()