From 9fcfe61410252060e6e96546b0598015cacd8a58 Mon Sep 17 00:00:00 2001 From: kim <89579420+NyaaaWhatsUpDoc@users.noreply.github.com> Date: Sat, 1 Oct 2022 16:36:08 +0100 Subject: [PATCH] [chore] small logging cleanup (#869) * handle more syslogging levels, use singular time format variable, add entry .New() function * pass in calldepth to lower log functions to ensure correctly set * update truncate length in syslog test --- internal/log/entry.go | 36 +++++++------- internal/log/log.go | 96 +++++++++++++++++++++---------------- internal/log/syslog_test.go | 4 +- 3 files changed, 75 insertions(+), 61 deletions(-) diff --git a/internal/log/entry.go b/internal/log/entry.go index 2e6f62e96..2ebac531c 100644 --- a/internal/log/entry.go +++ b/internal/log/entry.go @@ -41,77 +41,77 @@ func (e Entry) WithFields(fields ...kv.Field) Entry { } func (e Entry) Trace(a ...interface{}) { - logf(level.TRACE, e.fields, args(len(a)), a...) + logf(3, level.TRACE, e.fields, args(len(a)), a...) } func (e Entry) Tracef(s string, a ...interface{}) { - logf(level.TRACE, e.fields, s, a...) + logf(3, level.TRACE, e.fields, s, a...) } func (e Entry) Debug(a ...interface{}) { - logf(level.DEBUG, e.fields, args(len(a)), a...) + logf(3, level.DEBUG, e.fields, args(len(a)), a...) } func (e Entry) Debugf(s string, a ...interface{}) { - logf(level.DEBUG, e.fields, s, a...) + logf(3, level.DEBUG, e.fields, s, a...) } func (e Entry) Info(a ...interface{}) { - logf(level.INFO, e.fields, args(len(a)), a...) + logf(3, level.INFO, e.fields, args(len(a)), a...) } func (e Entry) Infof(s string, a ...interface{}) { - logf(level.INFO, e.fields, s, a...) + logf(3, level.INFO, e.fields, s, a...) } func (e Entry) Warn(a ...interface{}) { - logf(level.WARN, e.fields, args(len(a)), a...) + logf(3, level.WARN, e.fields, args(len(a)), a...) } func (e Entry) Warnf(s string, a ...interface{}) { - logf(level.WARN, e.fields, s, a...) + logf(3, level.WARN, e.fields, s, a...) } func (e Entry) Error(a ...interface{}) { - logf(level.ERROR, e.fields, args(len(a)), a...) + logf(3, level.ERROR, e.fields, args(len(a)), a...) } func (e Entry) Errorf(s string, a ...interface{}) { - logf(level.ERROR, e.fields, s, a...) + logf(3, level.ERROR, e.fields, s, a...) } func (e Entry) Fatal(a ...interface{}) { defer syscall.Exit(1) - logf(level.FATAL, e.fields, args(len(a)), a...) + logf(3, level.FATAL, e.fields, args(len(a)), a...) } func (e Entry) Fatalf(s string, a ...interface{}) { defer syscall.Exit(1) - logf(level.FATAL, e.fields, s, a...) + logf(3, level.FATAL, e.fields, s, a...) } func (e Entry) Panic(a ...interface{}) { defer panic(fmt.Sprint(a...)) - logf(level.PANIC, e.fields, args(len(a)), a...) + logf(3, level.PANIC, e.fields, args(len(a)), a...) } func (e Entry) Panicf(s string, a ...interface{}) { defer panic(fmt.Sprintf(s, a...)) - logf(level.PANIC, e.fields, s, a...) + logf(3, level.PANIC, e.fields, s, a...) } func (e Entry) Log(lvl level.LEVEL, a ...interface{}) { - logf(lvl, e.fields, args(len(a)), a...) + logf(3, lvl, e.fields, args(len(a)), a...) } func (e Entry) Logf(lvl level.LEVEL, s string, a ...interface{}) { - logf(lvl, e.fields, s, a...) + logf(3, lvl, e.fields, s, a...) } func (e Entry) Print(a ...interface{}) { - printf(e.fields, args(len(a)), a...) + printf(3, e.fields, args(len(a)), a...) } func (e Entry) Printf(s string, a ...interface{}) { - printf(e.fields, s, a...) + printf(3, e.fields, s, a...) } diff --git a/internal/log/log.go b/internal/log/log.go index a9c7340ed..7ee43c900 100644 --- a/internal/log/log.go +++ b/internal/log/log.go @@ -24,17 +24,17 @@ import ( "log/syslog" "os" "strings" + "sync/atomic" "syscall" "time" - "codeberg.org/gruf/go-atomics" "codeberg.org/gruf/go-kv" "codeberg.org/gruf/go-logger/v2/level" ) var ( // loglvl is the currently set logging level. - loglvl atomics.Uint32 + loglvl atomic.Uint32 // lvlstrs is the lookup table of log levels to strings. lvlstrs = level.Default() @@ -45,6 +45,9 @@ var ( // Syslog output, only set if enabled. sysout *syslog.Writer + + // timefmt is the logging time format used. + timefmt = "02/01/2006 15:04:05.000" ) // Level returns the currently set log level. @@ -57,6 +60,11 @@ func SetLevel(lvl level.LEVEL) { loglvl.Store(uint32(lvl)) } +// New starts a new log entry. +func New() Entry { + return Entry{} +} + func WithField(key string, value interface{}) Entry { return Entry{fields: []kv.Field{{K: key, V: value}}} } @@ -66,98 +74,97 @@ func WithFields(fields ...kv.Field) Entry { } func Trace(a ...interface{}) { - logf(level.TRACE, nil, args(len(a)), a...) + logf(3, level.TRACE, nil, args(len(a)), a...) } func Tracef(s string, a ...interface{}) { - logf(level.TRACE, nil, s, a...) + logf(3, level.TRACE, nil, s, a...) } func Debug(a ...interface{}) { - logf(level.DEBUG, nil, args(len(a)), a...) + logf(3, level.DEBUG, nil, args(len(a)), a...) } func Debugf(s string, a ...interface{}) { - logf(level.DEBUG, nil, s, a...) + logf(3, level.DEBUG, nil, s, a...) } func Info(a ...interface{}) { - logf(level.INFO, nil, args(len(a)), a...) + logf(3, level.INFO, nil, args(len(a)), a...) } func Infof(s string, a ...interface{}) { - logf(level.INFO, nil, s, a...) + logf(3, level.INFO, nil, s, a...) } func Warn(a ...interface{}) { - logf(level.WARN, nil, args(len(a)), a...) + logf(3, level.WARN, nil, args(len(a)), a...) } func Warnf(s string, a ...interface{}) { - logf(level.WARN, nil, s, a...) + logf(3, level.WARN, nil, s, a...) } func Error(a ...interface{}) { - logf(level.ERROR, nil, args(len(a)), a...) + logf(3, level.ERROR, nil, args(len(a)), a...) } func Errorf(s string, a ...interface{}) { - logf(level.ERROR, nil, s, a...) + logf(3, level.ERROR, nil, s, a...) } func Fatal(a ...interface{}) { defer syscall.Exit(1) - logf(level.FATAL, nil, args(len(a)), a...) + logf(3, level.FATAL, nil, args(len(a)), a...) } func Fatalf(s string, a ...interface{}) { defer syscall.Exit(1) - logf(level.FATAL, nil, s, a...) + logf(3, level.FATAL, nil, s, a...) } func Panic(a ...interface{}) { defer panic(fmt.Sprint(a...)) - logf(level.PANIC, nil, args(len(a)), a...) + logf(3, level.PANIC, nil, args(len(a)), a...) } func Panicf(s string, a ...interface{}) { defer panic(fmt.Sprintf(s, a...)) - logf(level.PANIC, nil, s, a...) + logf(3, level.PANIC, nil, s, a...) } // Log will log formatted args as 'msg' field to the log at given level. func Log(lvl level.LEVEL, a ...interface{}) { - logf(lvl, nil, args(len(a)), a...) + logf(3, lvl, nil, args(len(a)), a...) } // Logf will log format string as 'msg' field to the log at given level. func Logf(lvl level.LEVEL, s string, a ...interface{}) { - logf(lvl, nil, s, a...) + logf(3, lvl, nil, s, a...) } // Print will log formatted args to the stdout log output. func Print(a ...interface{}) { - printf(nil, args(len(a)), a...) + printf(3, nil, args(len(a)), a...) } // Print will log format string to the stdout log output. func Printf(s string, a ...interface{}) { - printf(nil, s, a...) + printf(3, nil, s, a...) } -func printf(fields []kv.Field, s string, a ...interface{}) { +func printf(depth int, fields []kv.Field, s string, a ...interface{}) { // Acquire buffer buf := getBuf() // Append formatted timestamp - now := time.Now().Format("02/01/2006 15:04:05.000") buf.B = append(buf.B, `timestamp="`...) - buf.B = append(buf.B, now...) + buf.B = time.Now().AppendFormat(buf.B, timefmt) buf.B = append(buf.B, `" `...) // Append formatted caller func buf.B = append(buf.B, `func=`...) - buf.B = append(buf.B, Caller(4)...) + buf.B = append(buf.B, Caller(depth+1)...) buf.B = append(buf.B, ' ') if len(fields) > 0 { @@ -169,15 +176,22 @@ func printf(fields []kv.Field, s string, a ...interface{}) { // Append formatted args fmt.Fprintf(buf, s, a...) - // Append a final newline - buf.B = append(buf.B, '\n') + if buf.B[len(buf.B)-1] != '\n' { + // Append a final newline + buf.B = append(buf.B, '\n') + } + + if sysout != nil { + // Write log entry to syslog + logsys(level.INFO, buf.String()) + } // Write to log and release _, _ = stdout.Write(buf.B) putBuf(buf) } -func logf(lvl level.LEVEL, fields []kv.Field, s string, a ...interface{}) { +func logf(depth int, lvl level.LEVEL, fields []kv.Field, s string, a ...interface{}) { var out io.Writer // Check if enabled. @@ -197,14 +211,13 @@ func logf(lvl level.LEVEL, fields []kv.Field, s string, a ...interface{}) { buf := getBuf() // Append formatted timestamp - now := time.Now().Format("02/01/2006 15:04:05.000") buf.B = append(buf.B, `timestamp="`...) - buf.B = append(buf.B, now...) + buf.B = time.Now().AppendFormat(buf.B, timefmt) buf.B = append(buf.B, `" `...) // Append formatted caller func buf.B = append(buf.B, `func=`...) - buf.B = append(buf.B, Caller(4)...) + buf.B = append(buf.B, Caller(depth+1)...) buf.B = append(buf.B, ' ') // Append formatted level string @@ -214,11 +227,13 @@ func logf(lvl level.LEVEL, fields []kv.Field, s string, a ...interface{}) { // Append formatted fields with msg kv.Fields(append(fields, kv.Field{ - "msg", fmt.Sprintf(s, a...), + K: "msg", V: fmt.Sprintf(s, a...), })).AppendFormat(buf, false) - // Append a final newline - buf.B = append(buf.B, '\n') + if buf.B[len(buf.B)-1] != '\n' { + // Append a final newline + buf.B = append(buf.B, '\n') + } if sysout != nil { // Write log entry to syslog @@ -231,23 +246,22 @@ func logf(lvl level.LEVEL, fields []kv.Field, s string, a ...interface{}) { } // logsys will log given msg at given severity to the syslog. +// Max length: https://www.rfc-editor.org/rfc/rfc5424.html#section-6.1 func logsys(lvl level.LEVEL, msg string) { - // Truncate message if > 1700 chars - if len(msg) > 1700 { - msg = msg[:1697] + "..." + if max := 2048; len(msg) > max { + // Truncate up to max + msg = msg[:max] } - - // Log at appropriate syslog severity switch lvl { - case level.TRACE: - case level.DEBUG: + case level.TRACE, level.DEBUG: + _ = sysout.Debug(msg) case level.INFO: _ = sysout.Info(msg) case level.WARN: _ = sysout.Warning(msg) case level.ERROR: _ = sysout.Err(msg) - case level.FATAL: + case level.FATAL, level.PANIC: _ = sysout.Crit(msg) } } diff --git a/internal/log/syslog_test.go b/internal/log/syslog_test.go index aafa93419..ad7c6ffbe 100644 --- a/internal/log/syslog_test.go +++ b/internal/log/syslog_test.go @@ -79,7 +79,7 @@ func (suite *SyslogTestSuite) TestSyslogLongMessage() { prefix := fmt.Sprintf(`timestamp="02/01/2006 15:04:05.000" func=%s level=WARN msg="`, funcName) entry := <-suite.syslogChannel - regex := fmt.Sprintf(`timestamp=.* func=.* level=WARN msg="%s\.\.\.`, longMessage[:1700-len(prefix)-3]) + regex := fmt.Sprintf(`timestamp=.* func=.* level=WARN msg="%s`, longMessage[:2048-len(prefix)]) suite.Regexp(regexp.MustCompile(regex), entry["content"]) } @@ -110,7 +110,7 @@ func (suite *SyslogTestSuite) TestSyslogLongMessageUnixgram() { prefix := fmt.Sprintf(`timestamp="02/01/2006 15:04:05.000" func=%s level=WARN msg="`, funcName) entry := <-syslogChannel - regex := fmt.Sprintf(`timestamp=.* func=.* level=WARN msg="%s\.\.\.`, longMessage[:1700-len(prefix)-3]) + regex := fmt.Sprintf(`timestamp=.* func=.* level=WARN msg="%s`, longMessage[:2048-len(prefix)]) suite.Regexp(regexp.MustCompile(regex), entry["content"])