From facc94b7258ceba391e1f33cdc0488fcd364eadb Mon Sep 17 00:00:00 2001 From: "Gerasimos (Makis) Maropoulos" Date: Thu, 10 Sep 2020 19:41:30 +0300 Subject: [PATCH] accesslog: improvements --- .../request-logger/accesslog-broker/main.go | 6 +- middleware/accesslog/accesslog.go | 59 +++++---- middleware/accesslog/accesslog_test.go | 124 ++++++++++++++++++ middleware/accesslog/broker.go | 8 +- middleware/accesslog/log.go | 5 + 5 files changed, 170 insertions(+), 32 deletions(-) diff --git a/_examples/logging/request-logger/accesslog-broker/main.go b/_examples/logging/request-logger/accesslog-broker/main.go index 3b2386bf..4ad995a3 100644 --- a/_examples/logging/request-logger/accesslog-broker/main.go +++ b/_examples/logging/request-logger/accesslog-broker/main.go @@ -1,6 +1,8 @@ package main import ( + "os" + "github.com/kataras/iris/v12" "github.com/kataras/iris/v12/middleware/accesslog" "github.com/kataras/iris/v12/middleware/recover" @@ -16,6 +18,8 @@ func main() { */ ac := accesslog.File("./access.log") + ac.AddOutput(os.Stdout) + ac.TimeFormat = "2006-01-02 15:04:05" // ac.KeepMultiLineError = false // set to false to print errors as one line. // Optionally run logging after response has sent: @@ -43,7 +47,7 @@ func main() { } func notFoundHandler(ctx iris.Context) { - ctx.Application().Logger().Infof("Not Found Handler for: %s", ctx.Path()) + // ctx.Application().Logger().Infof("Not Found Handler for: %s", ctx.Path()) suggestPaths := ctx.FindClosest(3) if len(suggestPaths) == 0 { diff --git a/middleware/accesslog/accesslog.go b/middleware/accesslog/accesslog.go index 026648ad..d0263240 100644 --- a/middleware/accesslog/accesslog.go +++ b/middleware/accesslog/accesslog.go @@ -94,6 +94,9 @@ var ( // // Look `New`, `File` package-level functions // and its `Handler` method to learn more. +// +// A new AccessLog middleware MUST +// be created after a `New` function call. type AccessLog struct { mu sync.Mutex // ensures atomic writes. // The destination writer. @@ -163,6 +166,8 @@ type AccessLog struct { // take the field key from the extractor itself. formatter Formatter broker *Broker + + logsPool *sync.Pool } // New returns a new AccessLog value with the default values. @@ -173,12 +178,16 @@ type AccessLog struct { // Example: https://github.com/kataras/iris/tree/master/_examples/logging/request-logger/accesslog func New(w io.Writer) *AccessLog { ac := &AccessLog{ + Clock: clockFunc(time.Now), BytesReceived: true, BytesSent: true, BodyMinify: true, RequestBody: true, ResponseBody: true, KeepMultiLineError: true, + logsPool: &sync.Pool{New: func() interface{} { + return new(Log) + }}, } if w == nil { @@ -515,46 +524,42 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path // Print writes a log manually. // The `Handler` method calls it. func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeFormat string, code int, method, path, reqBody, respBody string, bytesReceived, bytesSent int, params *context.RequestParams, query []memstore.StringEntry, fields []memstore.Entry) (err error) { - var now time.Time - - if ac.Clock != nil { - now = ac.Clock.Now() - } else { - now = time.Now() - } + now := ac.Clock.Now() if hasFormatter, hasBroker := ac.formatter != nil, ac.broker != nil; hasFormatter || hasBroker { - log := &Log{ - Logger: ac, - Now: now, - TimeFormat: timeFormat, - Timestamp: now.Unix(), - Latency: latency, - Method: method, - Path: path, - Code: code, - Query: query, - PathParams: params.Store, - Fields: fields, - BytesReceived: bytesReceived, - BytesSent: bytesSent, - Request: reqBody, - Response: respBody, - Ctx: ctx, // ctx should only be used here, it may be nil on testing. - } + log := ac.logsPool.Get().(*Log) + log.Logger = ac + log.Now = now + log.TimeFormat = timeFormat + log.Timestamp = now.Unix() + log.Latency = latency + log.Method = method + log.Path = path + log.Code = code + log.Query = query + log.PathParams = params.Store + log.Fields = fields + log.BytesReceived = bytesReceived + log.BytesSent = bytesSent + log.Request = reqBody + log.Response = respBody + log.Ctx = ctx var handled bool if hasFormatter { - handled, err = ac.formatter.Format(log) + handled, err = ac.formatter.Format(log) // formatter can alter this, we wait until it's finished. if err != nil { + ac.logsPool.Put(log) return } } if hasBroker { // after Format, it may want to customize the log's fields. - ac.broker.notify(log) + ac.broker.notify(log.Clone()) // a listener cannot edit the log as we use object pooling. } + ac.logsPool.Put(log) // we don't need it anymore. + if handled { return // OK, it's handled, exit now. } diff --git a/middleware/accesslog/accesslog_test.go b/middleware/accesslog/accesslog_test.go index 5e3caf1b..7ff2bb67 100644 --- a/middleware/accesslog/accesslog_test.go +++ b/middleware/accesslog/accesslog_test.go @@ -2,6 +2,11 @@ package accesslog import ( "bytes" + "fmt" + "io" + "io/ioutil" + "net/http" + "net/http/httptest" "sync" "testing" "time" @@ -64,3 +69,122 @@ func TestAccessLogPrint_Simple(t *testing.T) { t.Fatalf("expected printed result to be:\n'%s'\n\nbut got:\n'%s'", expected, got) } } + +func TestAccessLogBroker(t *testing.T) { + w := new(bytes.Buffer) + ac := New(w) + ac.TimeFormat = "2006-01-02 15:04:05" + ac.Clock = TClock(time.Time{}) + broker := ac.Broker() + + closed := make(chan struct{}) + wg := new(sync.WaitGroup) + n := 4 + wg.Add(4) + go func() { + defer wg.Done() + + i := 0 + ln := broker.NewListener() + for { + select { + case <-closed: + broker.CloseListener(ln) + t.Log("Log Listener Closed") + return + case log := <-ln: + lat := log.Latency + t.Log(lat.String()) + wg.Done() + if expected := time.Duration(i) * time.Second; expected != lat { + panic(fmt.Sprintf("expected latency: %s but got: %s", expected, lat)) + } + i++ + time.Sleep(1350 * time.Millisecond) + if i == 2 { + time.Sleep(2 * time.Second) // "random" sleep even more. + } + if log.Latency != lat { + panic("expected logger to wait for notifier before release the log") + } + } + } + }() + + time.Sleep(time.Second) + + printLog := func(lat time.Duration) { + err := ac.Print( + nil, + lat, + "", + 0, + "", + "", + "", + "", + 0, + 0, + &context.RequestParams{}, + nil, + nil, + ) + + if err != nil { + t.Fatal(err) + } + } + + for i := 0; i < n; i++ { + printLog(time.Duration(i) * time.Second) + } + + // wait for all listeners to finish. + wg.Wait() + + // wait for close messages. + wg.Add(1) + close(closed) + wg.Wait() +} + +type noOpFormatter struct{} + +func (*noOpFormatter) SetOutput(io.Writer) {} + +// Format prints the logs in text/template format. +func (*noOpFormatter) Format(*Log) (bool, error) { + return true, nil +} + +// go test -run=^$ -bench=BenchmarkAccessLogAfter -benchmem +func BenchmarkAccessLogAfter(b *testing.B) { + ac := New(ioutil.Discard) + ac.Clock = TClock(time.Time{}) + ac.TimeFormat = "2006-01-02 15:04:05" + ac.BytesReceived = false + ac.BytesSent = false + ac.BodyMinify = false + ac.RequestBody = false + ac.ResponseBody = false + ac.KeepMultiLineError = true + ac.Async = false + ac.SetFormatter(new(noOpFormatter)) // just to create the log structure.) + + ctx := new(context.Context) + req, err := http.NewRequest("GET", "/", nil) + if err != nil { + b.Fatal(err) + } + ctx.ResetRequest(req) + recorder := httptest.NewRecorder() + w := context.AcquireResponseWriter() + w.BeginResponse(recorder) + ctx.ResetResponseWriter(w) + + b.ResetTimer() + for n := 0; n < b.N; n++ { + ac.after(ctx, time.Millisecond, "GET", "/") + } + w.EndResponse() +} diff --git a/middleware/accesslog/broker.go b/middleware/accesslog/broker.go index f559b5b8..f2675bd6 100644 --- a/middleware/accesslog/broker.go +++ b/middleware/accesslog/broker.go @@ -2,7 +2,7 @@ package accesslog // LogChan describes the log channel. // See `Broker` for details. -type LogChan chan *Log +type LogChan chan Log // A Broker holds the active listeners, // incoming logs on its Notifier channel @@ -18,7 +18,7 @@ type Broker struct { newListeners chan LogChan // CloseListener action. - closingListeners chan chan *Log + closingListeners chan LogChan // listeners store. listeners map[LogChan]bool @@ -29,7 +29,7 @@ func newBroker() *Broker { b := &Broker{ Notifier: make(LogChan, 1), newListeners: make(chan LogChan), - closingListeners: make(chan chan *Log), + closingListeners: make(chan LogChan), listeners: make(map[LogChan]bool), } @@ -63,7 +63,7 @@ func (b *Broker) run() { } // notify sends the "log" to all active listeners. -func (b *Broker) notify(log *Log) { +func (b *Broker) notify(log Log) { b.Notifier <- log } diff --git a/middleware/accesslog/log.go b/middleware/accesslog/log.go index d8028a44..5b5a2bda 100644 --- a/middleware/accesslog/log.go +++ b/middleware/accesslog/log.go @@ -57,6 +57,11 @@ type Log struct { Ctx *context.Context `json:"-" yaml:"-" toml:"-"` } +// Clone returns a raw copy value of this Log. +func (l *Log) Clone() Log { + return *l +} + // RequestValuesLine returns a string line which // combines the path parameters, query and custom fields. func (l *Log) RequestValuesLine() string {