[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

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"])