accesslog: improvements

_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 {

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
+	now := ac.Clock.Now()
-
-	if ac.Clock != nil {
-		now = ac.Clock.Now()
-	} else {
-		now = time.Now()
-	}
 
 	if hasFormatter, hasBroker := ac.formatter != nil, ac.broker != nil; hasFormatter || hasBroker {
-		log := &Log{
+		log := ac.logsPool.Get().(*Log)
-			Logger:        ac,
+		log.Logger = ac
-			Now:           now,
+		log.Now = now
-			TimeFormat:    timeFormat,
+		log.TimeFormat = timeFormat
-			Timestamp:     now.Unix(),
+		log.Timestamp = now.Unix()
-			Latency:       latency,
+		log.Latency = latency
-			Method:        method,
+		log.Method = method
-			Path:          path,
+		log.Path = path
-			Code:          code,
+		log.Code = code
-			Query:         query,
+		log.Query = query
-			PathParams:    params.Store,
+		log.PathParams = params.Store
-			Fields:        fields,
+		log.Fields = fields
-			BytesReceived: bytesReceived,
+		log.BytesReceived = bytesReceived
-			BytesSent:     bytesSent,
+		log.BytesSent = bytesSent
-			Request:       reqBody,
+		log.Request = reqBody
-			Response:      respBody,
+		log.Response = respBody
-			Ctx:           ctx, // ctx should only be used here, it may be nil on testing.
+		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.
 		}

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

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
 }
 

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 {