From dba226c1c1f03ba482113b822622e0a11319c1bf Mon Sep 17 00:00:00 2001 From: Tigor Hutasuhut Date: Tue, 27 Aug 2024 15:22:42 +0700 Subject: [PATCH] update logging --- .gitignore | 1 + Makefile | 3 + core/zlog/buffer.go | 27 ---- core/zlog/exported.go | 153 +++++++++++++++++++++ core/zlog/notification.go | 18 +++ core/zlog/write_locker.go | 23 ++++ core/zlog/zlog.go | 139 +++++++++++++------ internal/bufferpool/bufferpool.go | 18 +-- log.go | 215 ++++++++++++++++++++++++++++++ 9 files changed, 518 insertions(+), 79 deletions(-) create mode 100644 core/zlog/exported.go create mode 100644 core/zlog/notification.go create mode 100644 core/zlog/write_locker.go create mode 100644 log.go diff --git a/.gitignore b/.gitignore index 5d37cea..d9bb0f5 100644 --- a/.gitignore +++ b/.gitignore @@ -1,2 +1,3 @@ .direnv gen +bin/ diff --git a/Makefile b/Makefile index c6210a2..ee34ecd 100644 --- a/Makefile +++ b/Makefile @@ -1,5 +1,8 @@ .ONESHELL: +build: generate + go build -o ./bin ./cmd/zen + generate: generate-proto generate-proto: diff --git a/core/zlog/buffer.go b/core/zlog/buffer.go index 0f904b0..a602245 100644 --- a/core/zlog/buffer.go +++ b/core/zlog/buffer.go @@ -46,30 +46,3 @@ func (j *jsonHandler) Put() { j.pool.Put(j) } } - -type bufferPool struct { - *sync.Pool -} - -func newBufferPool() *bufferPool { - return &bufferPool{ - &sync.Pool{ - New: func() any { - buf := new(bytes.Buffer) - buf.Grow(1024) - return buf - }, - }, - } -} - -func (bp *bufferPool) Get() *bytes.Buffer { - return bp.Pool.Get().(*bytes.Buffer) -} - -func (bp *bufferPool) Put(buf *bytes.Buffer) { - if buf.Cap() < 1024*1024*4 { - buf.Reset() - bp.Pool.Put(buf) - } -} diff --git a/core/zlog/exported.go b/core/zlog/exported.go new file mode 100644 index 0000000..6b9aab7 --- /dev/null +++ b/core/zlog/exported.go @@ -0,0 +1,153 @@ +package zlog + +import ( + "context" + "fmt" + "log/slog" + "os" + "time" + + "gitlab.bareksa.com/backend/zen/core/zcaller" +) + +var Logger = New(os.Stderr, defaultOpts) + +func Info(ctx context.Context, msg string) { + if !Logger.Enabled(ctx, slog.LevelInfo) { + return + } + + pc := zcaller.Get(3) + t := time.Now() + Log(ctx, msg, pc, t, slog.LevelInfo) +} + +func Infof(ctx context.Context, msg string, args ...any) { + if !Logger.Enabled(ctx, slog.LevelInfo) { + return + } + pc := zcaller.Get(3) + t := time.Now() + msg = fmt.Sprintf(msg, args...) + + Log(ctx, msg, pc, t, slog.LevelInfo) +} + +func Infow(ctx context.Context, msg string, fields ...any) { + if !Logger.Enabled(ctx, slog.LevelInfo) { + return + } + pc := zcaller.Get(3) + t := time.Now() + Log(ctx, msg, pc, t, slog.LevelInfo, fields...) +} + +func Debug(ctx context.Context, msg string) { + if !Logger.Enabled(ctx, slog.LevelDebug) { + return + } + + pc := zcaller.Get(3) + t := time.Now() + Log(ctx, msg, pc, t, slog.LevelDebug) +} + +func Debugf(ctx context.Context, msg string, args ...any) { + if !Logger.Enabled(ctx, slog.LevelDebug) { + return + } + pc := zcaller.Get(3) + t := time.Now() + msg = fmt.Sprintf(msg, args...) + + Log(ctx, msg, pc, t, slog.LevelDebug) +} + +func Debugw(ctx context.Context, msg string, fields ...any) { + if !Logger.Enabled(ctx, slog.LevelDebug) { + return + } + pc := zcaller.Get(3) + t := time.Now() + Log(ctx, msg, pc, t, slog.LevelDebug, fields...) +} + +func Warn(ctx context.Context, msg string) { + if !Logger.Enabled(ctx, slog.LevelWarn) { + return + } + + pc := zcaller.Get(3) + t := time.Now() + Log(ctx, msg, pc, t, slog.LevelWarn) +} + +func Warnf(ctx context.Context, msg string, args ...any) { + if !Logger.Enabled(ctx, slog.LevelWarn) { + return + } + pc := zcaller.Get(3) + t := time.Now() + msg = fmt.Sprintf(msg, args...) + + Log(ctx, msg, pc, t, slog.LevelWarn) +} + +func Warnw(ctx context.Context, msg string, fields ...any) { + if !Logger.Enabled(ctx, slog.LevelWarn) { + return + } + pc := zcaller.Get(3) + t := time.Now() + Log(ctx, msg, pc, t, slog.LevelWarn, fields...) +} + +func Error(ctx context.Context, msg string) { + if !Logger.Enabled(ctx, slog.LevelError) { + return + } + + pc := zcaller.Get(3) + t := time.Now() + Log(ctx, msg, pc, t, slog.LevelError) +} + +func Errorf(ctx context.Context, msg string, args ...any) { + if !Logger.Enabled(ctx, slog.LevelError) { + return + } + pc := zcaller.Get(3) + t := time.Now() + msg = fmt.Sprintf(msg, args...) + + Log(ctx, msg, pc, t, slog.LevelError) +} + +func Errorw(ctx context.Context, msg string, fields ...any) { + if !Logger.Enabled(ctx, slog.LevelError) { + return + } + pc := zcaller.Get(3) + t := time.Now() + Log(ctx, msg, pc, t, slog.LevelError, fields...) +} + +func LogRecord(ctx context.Context, record slog.Record) { + if !Logger.Enabled(ctx, record.Level) { + return + } + Logger.Handle(ctx, record) +} + +func Log(ctx context.Context, msg string, pc uintptr, t time.Time, level slog.Level, fields ...any) { + record := slog.NewRecord(t, level, msg, pc) + record.Add(fields...) + // error is only returned if the output writer fails. + if err := Logger.Handle(ctx, record); err != nil { + slog.ErrorContext(ctx, "failed to log", "error", err) + } +} + +func SetDefault(log *ZLog) { + Logger = log +} diff --git a/core/zlog/notification.go b/core/zlog/notification.go new file mode 100644 index 0000000..505f8b6 --- /dev/null +++ b/core/zlog/notification.go @@ -0,0 +1,18 @@ +package zlog + +import ( + "context" + "log/slog" + + "gitlab.bareksa.com/backend/zen/core/zoptions" +) + +type Notifier interface { + Notify(options ...zoptions.NotifyOption) +} + +type NotificationHandler interface { + NotifyLog(ctx context.Context, record slog.Record) +} + +type notifyHandler struct{} diff --git a/core/zlog/write_locker.go b/core/zlog/write_locker.go new file mode 100644 index 0000000..f905ac6 --- /dev/null +++ b/core/zlog/write_locker.go @@ -0,0 +1,23 @@ +package zlog + +import ( + "io" + "sync" +) + +type WriteLocker interface { + io.Writer + sync.Locker +} + +func WrapLocker(w io.Writer) WriteLocker { + if wl, ok := w.(WriteLocker); ok { + return wl + } + return &writeLocker{Writer: w} +} + +type writeLocker struct { + io.Writer + sync.Mutex +} diff --git a/core/zlog/zlog.go b/core/zlog/zlog.go index e981bbf..83f1628 100644 --- a/core/zlog/zlog.go +++ b/core/zlog/zlog.go @@ -2,48 +2,77 @@ package zlog import ( "context" + "errors" "io" "log/slog" - "sync" + "os" + "testing" "time" "github.com/fatih/color" + "github.com/mattn/go-isatty" "github.com/tidwall/pretty" + "gitlab.bareksa.com/backend/zen/internal/bufferpool" ) -type WriteLocker interface { - io.Writer - sync.Locker -} - -func WrapLocker(w io.Writer) WriteLocker { - if wl, ok := w.(WriteLocker); ok { - return wl - } - return &writeLocker{Writer: w} -} - -type writeLocker struct { - io.Writer - sync.Mutex -} - -type Log struct { - level slog.Level - bufPool *bufferPool +type ZLog struct { + bufPool *bufferpool.Pool jsonPool *jsonHandlerPool withAttrs []slog.Attr withGroup []string - opts *slog.HandlerOptions - pretty bool - color bool + opts *ZLogOptions writer WriteLocker } +type ZLogOptions struct { + // HandlerOptions handles the options for the underlying slog.Handler. + // + // If nil, default options are used. + HandlerOptions *slog.HandlerOptions + // Pretty enables pretty-printing of log messages. + Pretty bool + // Color enables colorized output. + Color bool + // NotificationHandler is a handler that is called when a log message is + // intended to be sent to a notification service. + // + // If nil, no notification is sent. + NotificationHandler NotificationHandler +} + +// New creates a new Logger that writes to w. +// +// if opts is nil, default options are used. +func New(w io.Writer, opts *ZLogOptions) *ZLog { + if w == nil { + panic(errors.New("zlog: New: w is nil")) + } + pretty := isatty.IsTerminal(os.Stderr.Fd()) + if opts == nil { + opts = defaultOpts + } else { + if opts.HandlerOptions == nil { + opts.HandlerOptions = defaultHandlerOptions + } else { + opts.HandlerOptions.ReplaceAttr = wrapPrettyReplaceAttr(pretty, opts.HandlerOptions.ReplaceAttr) + } + } + wl := WrapLocker(w) + + return &ZLog{ + bufPool: bufferpool.New(bufferpool.SharedCap, bufferpool.BufCap), + jsonPool: newJsonHandlerPool(opts.HandlerOptions), + withAttrs: []slog.Attr{}, + withGroup: []string{}, + opts: opts, + writer: wl, + } +} + // Clone clones the Logger, replacing the output writer with w. // // If w is nil, the clone shares the original Logger's output writer. -func (log *Log) Clone(w io.Writer) *Log { +func (log *ZLog) Clone(w io.Writer) *ZLog { var output WriteLocker if w == nil { output = log.writer @@ -54,26 +83,24 @@ func (log *Log) Clone(w io.Writer) *Log { copy(withAttrs, log.withAttrs) withGroup := make([]string, len(log.withGroup)) copy(withGroup, log.withGroup) - return &Log{ - level: log.level, + return &ZLog{ withAttrs: withAttrs, withGroup: withGroup, opts: log.opts, - pretty: log.pretty, - bufPool: newBufferPool(), - jsonPool: newJsonHandlerPool(log.opts), + bufPool: bufferpool.New(bufferpool.SharedCap, bufferpool.BufCap), + jsonPool: newJsonHandlerPool(log.opts.HandlerOptions), writer: output, } } // Enabled implements the slog.Handler interface. -func (lo *Log) Enabled(ctx context.Context, lvl slog.Level) bool { - return lvl >= lo.level +func (lo *ZLog) Enabled(ctx context.Context, lvl slog.Level) bool { + return lvl >= lo.opts.HandlerOptions.Level.Level() } // Handle implements the slog.Handler interface. -func (lo *Log) Handle(ctx context.Context, record slog.Record) error { - if !lo.pretty { +func (lo *ZLog) Handle(ctx context.Context, record slog.Record) error { + if !lo.opts.Pretty { j := lo.jsonPool.Get() defer j.Put() return j.Handle(ctx, record) @@ -92,9 +119,9 @@ func (lo *Log) Handle(ctx context.Context, record slog.Record) error { } buf := lo.bufPool.Get() - defer lo.bufPool.Put(buf) + defer buf.Close() - if record.PC != 0 && lo.opts.AddSource { + if record.PC != 0 && lo.opts.HandlerOptions.AddSource { f := frame{Caller(record.PC).Frame()} levelColor.Fprint(buf, f.ShortFile()) levelColor.Fprint(buf, ":") @@ -127,7 +154,7 @@ func (lo *Log) Handle(ctx context.Context, record slog.Record) error { if jHandler.buf.Len() > 3 { // Skip empty objects like "{}\n" jsonData := jHandler.buf.Bytes() jsonData = pretty.Pretty(jsonData) - if lo.color { + if lo.opts.Color { jsonData = pretty.Color(jsonData, nil) } buf.Write(jsonData) @@ -142,14 +169,14 @@ func (lo *Log) Handle(ctx context.Context, record slog.Record) error { } // WithAttrs implements the slog.Handler interface. -func (lo *Log) WithAttrs(attrs []slog.Attr) slog.Handler { +func (lo *ZLog) WithAttrs(attrs []slog.Attr) slog.Handler { l := lo.Clone(nil) l.withAttrs = append(l.withAttrs, attrs...) return l } // WithGroup implements the slog.Handler interface. -func (lo *Log) WithGroup(name string) slog.Handler { +func (lo *ZLog) WithGroup(name string) slog.Handler { l := lo.Clone(nil) l.withGroup = append(l.withGroup, name) return l @@ -157,11 +184,15 @@ func (lo *Log) WithGroup(name string) slog.Handler { type replaceAttrFunc = func([]string, slog.Attr) slog.Attr -// wrapReplaceAttr disables adding Time, Level, Source, Message -// fields when pretty mode is enabled. -func (lo *Log) wrapReplaceAttr(f replaceAttrFunc) replaceAttrFunc { +func wrapPrettyReplaceAttr(pretty bool, f replaceAttrFunc) replaceAttrFunc { + if f == nil { + f = func(s []string, a slog.Attr) slog.Attr { return a } + } return func(s []string, a slog.Attr) slog.Attr { - if !lo.pretty { + if len(s) > 0 { + return f(s, a) + } + if pretty { return f(s, a) } switch a.Key { @@ -171,3 +202,25 @@ func (lo *Log) wrapReplaceAttr(f replaceAttrFunc) replaceAttrFunc { return f(s, a) } } + +func defaultLevel() slog.Leveler { + if testing.Testing() { + return slog.Level(999) // Disable logging in tests + } + return slog.LevelInfo +} + +var defaultOpts = &ZLogOptions{ + Pretty: isatty.IsTerminal(os.Stderr.Fd()), + Color: isatty.IsTerminal(os.Stderr.Fd()), + HandlerOptions: defaultHandlerOptions, +} + +var defaultHandlerOptions = &slog.HandlerOptions{ + AddSource: true, + Level: defaultLevel(), + ReplaceAttr: wrapPrettyReplaceAttr( + isatty.IsTerminal(os.Stderr.Fd()), + nil, + ), +} diff --git a/internal/bufferpool/bufferpool.go b/internal/bufferpool/bufferpool.go index a4d774f..d953a97 100644 --- a/internal/bufferpool/bufferpool.go +++ b/internal/bufferpool/bufferpool.go @@ -13,7 +13,7 @@ import ( "sync/atomic" ) -type BufferPool struct { +type Pool struct { pool *sync.Pool maxSharedCapacity uint64 currentCapacity atomic.Uint64 @@ -28,7 +28,7 @@ type BufferPool struct { // Close never returns an error. The signature is to implement io.Closer. type Buffer struct { *bytes.Buffer - pool *BufferPool + pool *Pool } // Close puts the buffer back to the pool. @@ -38,13 +38,13 @@ func (buf *Buffer) Close() error { return nil } -func (b *BufferPool) Get() *Buffer { +func (b *Pool) Get() *Buffer { buf := b.pool.Get().(*Buffer) b.currentCapacity.Add(-uint64(buf.Cap())) return buf } -func (b *BufferPool) Put(buf *Buffer) { +func (b *Pool) Put(buf *Buffer) { bufCap := uint64(buf.Cap()) overloaded := b.currentCapacity.Add(bufCap) > b.maxSharedCapacity if buf.Cap() < b.maxBufferCapacity && !overloaded { @@ -55,8 +55,8 @@ func (b *BufferPool) Put(buf *Buffer) { } } -func New(sharedCapacity uint64, bufferCapacity int) *BufferPool { - b := &BufferPool{ +func New(sharedCapacity uint64, bufferCapacity int) *Pool { + b := &Pool{ maxSharedCapacity: sharedCapacity, maxBufferCapacity: bufferCapacity, } @@ -67,11 +67,11 @@ func New(sharedCapacity uint64, bufferCapacity int) *BufferPool { } const ( - sharedCap uint64 = 64 * 1024 * 1024 // 64MB - bufCap int = 8 * 1024 * 1024 // 8MB + SharedCap uint64 = 64 * 1024 * 1024 // 64MB + BufCap int = 8 * 1024 * 1024 // 8MB ) -var pool = New(sharedCap, bufCap) +var pool = New(SharedCap, BufCap) // Get returns a bytes.Buffer from the global pool. func Get() *Buffer { diff --git a/log.go b/log.go new file mode 100644 index 0000000..be94bc7 --- /dev/null +++ b/log.go @@ -0,0 +1,215 @@ +package zen + +import ( + "gitlab.bareksa.com/backend/zen/core/zlog" +) + +var ( + // Info logs a message at level Info. + // Use this method to log basic information like "server is starting". + // + // To log with additional information, use the Infof or Infow methods. + // + // Use Infof to log with a format. + // + // Use Infow to log with additional json fields. + Info = zlog.Info + + // Infof logs a message at level Info with format. + // + // msg and args are passed to fmt.Sprintf. + // + // Use Infow to log with additional json fields. + // + // Use Infow to print structs and maps since they will + // be rendered as json. + // + // Example: + // + // zen.Infof(ctx, "user '%s' logged in", user) + Infof = zlog.Infof + + // Infow logs a message with additional json fields. + // + // Use Infow to render structs and maps as json. + // + // fields is an alternating key-value sequence. + // `key` must be a string type (including not alias), and `value` can be any + // serializeable type. + // + // wrong number of fields or non-string key will cause the misplaced + // value to be paired with `!BADKEY` key. + // + // failing to serialize json value will cause the value to be replaced with + // the string `!ERROR:{reason}`. + // + // If value implements [slog.LogValuer] interface, it will be used as log fields. + // If does not, it will look if it implements [json.Marshaler] interface and + // use it to serialize. + // Then for the last resort, use normal json.Marshal. + // + // Note that primitive values are already optimized and will not use heavy reflection. + // + // Example: + // + // zen.Infow(ctx, "API called without error", + // "method", request.Method, + // "path", request.URL.Path, + // "query", request.URL.Query(), + // "duration", dur, + // ) + Infow = zlog.Infow + + // Debug logs a message at level Debug. + // Use this method to log detailed information for debugging purposes. + // + // To log with additional information, use the Debugf or Debugw methods. + // + // Use [Debugf] to log with a format. + // + // Use [Debugw] to log with additional json fields. + Debug = zlog.Debug + + // Debugf logs a message at level Debug with format. + // + // msg and args are passed to fmt.Sprintf. + // + // Use Debugw to log with additional json fields. + // + // Use Debugw to print structs and maps since they will + // be rendered as json. + // + // Example: + // + // zen.Debugf(ctx, "user '%s' logged in", user) + Debugf = zlog.Debugf + + // Debugw logs a message with additional json fields. + // + // Use Debugw to render structs and maps as json. + // + // fields is an alternating key-value sequence. + // `key` must be a string type (including not alias), and `value` can be any + // serializeable type. + // + // wrong number of fields or non-string key will cause the misplaced + // value to be paired with `!BADKEY` key. + // + // failing to serialize json value will cause the value to be replaced with + // the string `!ERROR:{reason}`. + // + // If value implements [slog.LogValuer] interface, it will be used as log fields. + // If does not, it will look if it implements [json.Marshaler] interface and + // use it to serialize. + // Then for the last resort, use normal json.Marshal. + // + // Example: + // + // zen.Debugw(ctx, "database query", + // "query", query, + // "args", args, + // ) + Debugw = zlog.Debugw + + // Warn logs a message at level Warn. + // Use this method to log warnings. + // + // To log with additional information, use the Warnf or Warnw methods. + // + // Use Warnf to log with a format. + // + // Use Warnw to log with additional json fields. + Warn = zlog.Warn + + // Warnf logs a message at level Warn with format. + // + // msg and args are passed to fmt.Sprintf. + // + // Use Warnw to log with additional json fields. + // + // Use Warnw to print structs and maps since they will + // be rendered as json. + // + // Example: + // + // zen.Warnf(ctx, "user '%s' logged in", user) + Warnf = zlog.Warnf + + // Warnw logs a message with additional json fields. + // + // Use Warnw to render structs and maps as json. + // + // fields is an alternating key-value sequence. + // `key` must be a string type (including not alias), and `value` can be any + // serializeable type. + // + // wrong number of fields or non-string key will cause the misplaced + // value to be paired with `!BADKEY` key. + // + // failing to serialize json value will cause the value to be replaced with + // the string `!ERROR:{reason}`. + // + // If value implements [slog.LogValuer] interface, it will be used as log fields. + // If does not, it will look if it implements [json.Marshaler] interface and + // use it to serialize. + // Then for the last resort, use normal json.Marshal. + Warnw = zlog.Warnw + + // Error logs a message at level Error. + // Use this method to log errors. + // + // To log with additional information, use the Errorf or Errorw methods. + // + // Use Errorf to log with a format. + // + // Use Errorw to log with additional json fields. + Error = zlog.Error + + // Errorf logs a message at level Error with format. + // + // msg and args are passed to fmt.Sprintf. + // + // Use Errorw to log with additional json fields. + // + // Use Errorw to print structs and maps since they will + // be rendered as json. + // + // Example: + // + // zen.Errorf(ctx, "user '%s' logged in", user) + Errorf = zlog.Errorf + + // Errorw logs a message with additional json fields. + // + // Use Errorw to render structs and maps as json. + // + // fields is an alternating key-value sequence. + // `key` must be a string type (including not alias), and `value` can be any + // serializeable type. + // + // wrong number of fields or non-string key will cause the misplaced + // value to be paired with `!BADKEY` key. + // + // failing to serialize json value will cause the value to be replaced with + // the string `!ERROR:{reason}`. + // + // If value implements [slog.LogValuer] interface, it will be used as log fields. + // If does not, it will look if it implements [json.Marshaler] interface and + // use it to serialize. + // Then for the last resort, use normal json.Marshal. + // + // Example: + // + // zlog.Errorw(ctx, "RPC Error", + // "error", err, + // "requeset", request, + // ) + Errorw = zlog.Errorw + + // SetDefaultLogger sets the default logger that is + // used by the package level functions. + // + // SetDefaultLogger is not thread-safe and should be + // called early in the startup phase of the application. + SetDefaultLogger = zlog.SetDefault +)