From 20364a656a7f5c45592bbf2901b733cf7cd3f584 Mon Sep 17 00:00:00 2001 From: Sarat Chandra Date: Thu, 30 Jun 2022 14:18:37 +0530 Subject: [PATCH] feat: Add field logger to avoid locking. Also use a byte buffer pool instead of holding the buffer. --- examples/main.go | 2 +- field_logger.go | 25 ++++++++++ log.go | 119 ++++++++++++++++++++++++++--------------------- 3 files changed, 92 insertions(+), 54 deletions(-) create mode 100644 field_logger.go diff --git a/examples/main.go b/examples/main.go index 9901335..f3e5ec1 100644 --- a/examples/main.go +++ b/examples/main.go @@ -34,7 +34,7 @@ func main() { logger.SetTimestampFormat(time.RFC3339Nano) // Create a logger and add fields which will be logged in every line. - requestLogger := logger.WithFields(logf.Fields{"request_id": "3MG91VKP", "ip": "1.1.1.1", "method": "GET"}) + requestLogger := logger.WithFields(logf.Fields{"request_id": "3MG91VKP", "ip": "1.1.1.1", "method": "method=GET"}) requestLogger.Info("request success") requestLogger.Warn("this isn't supposed to happen") diff --git a/field_logger.go b/field_logger.go new file mode 100644 index 0000000..81c5a63 --- /dev/null +++ b/field_logger.go @@ -0,0 +1,25 @@ +package logf + +type FieldLogger struct { + fields Fields + logger *Logger +} + +func (l *FieldLogger) Debug(msg string) { + l.logger.handleLog(msg, DebugLevel, l.fields) +} + +// Info emits a info log line. +func (l *FieldLogger) Info(msg string) { + l.logger.handleLog(msg, InfoLevel, l.fields) +} + +// Warn emits a warning log line. +func (l *FieldLogger) Warn(msg string) { + l.logger.handleLog(msg, WarnLevel, l.fields) +} + +// Error emits an error log line. +func (l *FieldLogger) Error(msg string) { + l.logger.handleLog(msg, ErrorLevel, l.fields) +} diff --git a/log.go b/log.go index 0318d6c..1ed724b 100644 --- a/log.go +++ b/log.go @@ -10,20 +10,20 @@ import ( "strconv" "sync" "time" + "unicode/utf8" ) // Logger is the interface for all log operations // related to emitting logs. type Logger struct { - mu sync.Mutex // Atomic writes. - out io.Writer // Output destination. - bufW *bytes.Buffer // Buffer to accumulate before writing to output. - level Level // Verbosity of logs. - tsFormat string // Timestamp format. - enableColor bool // Colored output. - enableCaller bool // Print caller information. - callerSkipFrameCount int // Number of frames to skip when detecting caller - fields Fields // Arbitrary map of KV pair to log. + mu sync.Mutex // Atomic writes. + out io.Writer // Output destination. + bufW sync.Pool // Buffer pool to accumulate before writing to output. + level Level // Verbosity of logs. + tsFormat string // Timestamp format. + enableColor bool // Colored output. + enableCaller bool // Print caller information. + callerSkipFrameCount int // Number of frames to skip when detecting caller } // Opts represents various properties @@ -77,14 +77,15 @@ var colorLvlMap = [...]string{ func New() *Logger { // Initialise logger with sane defaults. return &Logger{ - out: os.Stderr, - bufW: bytes.NewBuffer([]byte{}), + out: os.Stderr, + bufW: sync.Pool{New: func() any { + return bytes.NewBuffer([]byte{}) + }}, level: InfoLevel, tsFormat: time.RFC3339, enableColor: false, enableCaller: false, callerSkipFrameCount: 0, - fields: make(Fields, 0), } } @@ -145,50 +146,44 @@ func (l *Logger) SetCallerFrame(caller bool, depth int) { // Debug emits a debug log line. func (l *Logger) Debug(msg string) { - l.handleLog(msg, DebugLevel) + l.handleLog(msg, DebugLevel, nil) } // Info emits a info log line. func (l *Logger) Info(msg string) { - l.handleLog(msg, InfoLevel) + l.handleLog(msg, InfoLevel, nil) } // Warn emits a warning log line. func (l *Logger) Warn(msg string) { - l.handleLog(msg, WarnLevel) + l.handleLog(msg, WarnLevel, nil) } // Error emits an error log line. func (l *Logger) Error(msg string) { - l.handleLog(msg, ErrorLevel) + l.handleLog(msg, ErrorLevel, nil) } // Fatal emits a fatal level log line. // It aborts the current program with an exit code of 1. func (l *Logger) Fatal(msg string) { - l.handleLog(msg, FatalLevel) + l.handleLog(msg, FatalLevel, nil) os.Exit(1) } // WithFields returns a new entry with `fields` set. -func (l *Logger) WithFields(fields Fields) *Logger { - if fields == nil { - fields = make(Fields, 0) +func (l *Logger) WithFields(fields Fields) *FieldLogger { + fl := &FieldLogger{ + fields: fields, + logger: l, } - - l.mu.Lock() - defer l.mu.Unlock() - - // Set the fields in logger. - l.fields = fields - - return l + return fl } // WithError returns a Logger with the "error" key set to `err`. -func (l *Logger) WithError(err error) *Logger { +func (l *Logger) WithError(err error) *FieldLogger { if err == nil { - return l + return &FieldLogger{logger: l} } return l.WithFields(Fields{ @@ -198,62 +193,76 @@ func (l *Logger) WithError(err error) *Logger { // handleLog emits the log after filtering log level // and applying formatting of the fields. -func (l *Logger) handleLog(msg string, lvl Level) { - now := time.Now().Format(l.tsFormat) - // Lock the map to prevet concurrent access to fields map. - l.mu.Lock() - defer l.mu.Unlock() - +func (l *Logger) handleLog(msg string, lvl Level, fields Fields) { // Discard the log if the verbosity is higher. // For eg, if the lvl is `3` (error), but the incoming message is `0` (debug), skip it. if lvl < l.level { return } + now := time.Now().Format(l.tsFormat) + + // Get a buffer from the pool. + bufW := l.bufW.Get().(*bytes.Buffer) + defer l.bufW.Put(bufW) + // Write fixed keys to the buffer before writing user provided ones. - l.writeToBuf("timestamp", now, lvl, l.enableColor, true) - l.writeToBuf("level", lvl, lvl, l.enableColor, true) - l.writeToBuf("message", msg, lvl, l.enableColor, true) + writeToBuf(bufW, "timestamp", now, lvl, l.enableColor, true) + writeToBuf(bufW, "level", lvl, lvl, l.enableColor, true) + writeToBuf(bufW, "message", msg, lvl, l.enableColor, true) if l.enableCaller { - l.writeToBuf("caller", caller(l.callerSkipFrameCount), lvl, l.enableColor, true) + writeToBuf(bufW, "caller", caller(l.callerSkipFrameCount), lvl, l.enableColor, true) } // Format the line as logfmt. - var count int // count is find out if this is the last key in while itering l.fields. - for k, v := range l.fields { + var count int // count is find out if this is the last key in while itering fields. + for k, v := range fields { space := false - if count != len(l.fields)-1 { + if count != len(fields)-1 { space = true } - l.writeToBuf(k, v, lvl, l.enableColor, space) + writeToBuf(bufW, k, v, lvl, l.enableColor, space) count++ } - l.bufW.WriteString("\n") + bufW.WriteString("\n") - _, err := io.Copy(l.out, l.bufW) + l.mu.Lock() + _, err := io.Copy(l.out, bufW) if err != nil { // Should ideally never happen. stdlog.Printf("error logging: %v", err) } + l.mu.Unlock() - l.bufW.Reset() + bufW.Reset() } // writeToBuf takes key, value and additional options to write to the buffer in logfmt. -func (l *Logger) writeToBuf(key string, val any, lvl Level, color, space bool) { +func writeToBuf(bufW *bytes.Buffer, key string, val any, lvl Level, color, space bool) { if color { - l.bufW.WriteString(getColoredKey(key, lvl)) + escapeAndWriteString(bufW, getColoredKey(key, lvl)) } else { - l.bufW.WriteString(key) + escapeAndWriteString(bufW, key) } - l.bufW.WriteString("=") - l.bufW.WriteString(getString(val)) + bufW.WriteByte('=') + escapeAndWriteString(bufW, getString(val)) if space { - l.bufW.WriteByte(' ') + bufW.WriteByte(' ') } } +func escapeAndWriteString(bufW *bytes.Buffer, s string) { + idx := bytes.IndexFunc([]byte(s), checkEscapingRune) + if idx != -1 { + bufW.WriteByte('"') + bufW.WriteString(s) + bufW.WriteByte('"') + return + } + bufW.WriteString(s) +} + // getColoredKey returns a color formatter key based on the log level. func getColoredKey(k string, lvl Level) string { return colorLvlMap[lvl] + k + reset @@ -292,3 +301,7 @@ func getString(val any) string { return fmt.Sprintf("%v", val) } } + +func checkEscapingRune(r rune) bool { + return r == '=' || r == '"' || r == utf8.RuneError +}