diff options
Diffstat (limited to 'internal/log')
| -rw-r--r-- | internal/log/caller.go | 28 | ||||
| -rw-r--r-- | internal/log/entry.go | 64 | ||||
| -rw-r--r-- | internal/log/format/format.go | 90 | ||||
| -rw-r--r-- | internal/log/format/format_test.go | 60 | ||||
| -rw-r--r-- | internal/log/format/json.go | 241 | ||||
| -rw-r--r-- | internal/log/format/logfmt.go | 67 | ||||
| -rw-r--r-- | internal/log/init.go | 29 | ||||
| -rw-r--r-- | internal/log/level.go | 28 | ||||
| -rw-r--r-- | internal/log/level/level.go | 45 | ||||
| -rw-r--r-- | internal/log/log.go | 317 | ||||
| -rw-r--r-- | internal/log/pool.go | 18 |
11 files changed, 656 insertions, 331 deletions
diff --git a/internal/log/caller.go b/internal/log/caller.go index 5385b63b5..a67502b41 100644 --- a/internal/log/caller.go +++ b/internal/log/caller.go @@ -19,7 +19,8 @@ package log import ( "runtime" - "strings" + + "codeberg.org/gruf/go-caller" ) // Caller fetches the calling function name, skipping 'depth'. @@ -27,29 +28,6 @@ import ( //go:noinline func Caller(depth int) string { pcs := make([]uintptr, 1) - - // Fetch calling func using depth. _ = runtime.Callers(depth, pcs) - fn := runtime.FuncForPC(pcs[0]) - - if fn == nil { - return "" - } - - // Get func name. - name := fn.Name() - - // Drop all but package and function name, no path. - if idx := strings.LastIndex(name, "/"); idx >= 0 { - name = name[idx+1:] - } - - const params = `[...]` - - // Drop any function generic type parameter markers. - if idx := strings.Index(name, params); idx >= 0 { - name = name[:idx] + name[idx+len(params):] - } - - return name + return caller.Get(pcs[0]) } diff --git a/internal/log/entry.go b/internal/log/entry.go index 48059c3bf..5b18ddf0f 100644 --- a/internal/log/entry.go +++ b/internal/log/entry.go @@ -48,117 +48,85 @@ func (e Entry) WithFields(kvs ...kv.Field) Entry { } // Trace will log formatted args as 'msg' field to the log at TRACE level. -// -//go:noinline func (e Entry) Trace(a ...interface{}) { - logf(e.ctx, 3, TRACE, e.kvs, args(len(a)), a...) + logf(e.ctx, TRACE, e.kvs, "", a...) } // Tracef will log format string as 'msg' field to the log at TRACE level. -// -//go:noinline func (e Entry) Tracef(s string, a ...interface{}) { - logf(e.ctx, 3, TRACE, e.kvs, s, a...) + logf(e.ctx, TRACE, e.kvs, s, a...) } // Debug will log formatted args as 'msg' field to the log at DEBUG level. -// -//go:noinline func (e Entry) Debug(a ...interface{}) { - logf(e.ctx, 3, DEBUG, e.kvs, args(len(a)), a...) + logf(e.ctx, DEBUG, e.kvs, "", a...) } // Debugf will log format string as 'msg' field to the log at DEBUG level. -// -//go:noinline func (e Entry) Debugf(s string, a ...interface{}) { - logf(e.ctx, 3, DEBUG, e.kvs, s, a...) + logf(e.ctx, DEBUG, e.kvs, s, a...) } // Info will log formatted args as 'msg' field to the log at INFO level. -// -//go:noinline func (e Entry) Info(a ...interface{}) { - logf(e.ctx, 3, INFO, e.kvs, args(len(a)), a...) + logf(e.ctx, INFO, e.kvs, "", a...) } // Infof will log format string as 'msg' field to the log at INFO level. -// -//go:noinline func (e Entry) Infof(s string, a ...interface{}) { - logf(e.ctx, 3, INFO, e.kvs, s, a...) + logf(e.ctx, INFO, e.kvs, s, a...) } // Warn will log formatted args as 'msg' field to the log at WARN level. -// -//go:noinline func (e Entry) Warn(a ...interface{}) { - logf(e.ctx, 3, WARN, e.kvs, args(len(a)), a...) + logf(e.ctx, WARN, e.kvs, "", a...) } // Warnf will log format string as 'msg' field to the log at WARN level. -// -//go:noinline func (e Entry) Warnf(s string, a ...interface{}) { - logf(e.ctx, 3, WARN, e.kvs, s, a...) + logf(e.ctx, WARN, e.kvs, s, a...) } // Error will log formatted args as 'msg' field to the log at ERROR level. -// -//go:noinline func (e Entry) Error(a ...interface{}) { - logf(e.ctx, 3, ERROR, e.kvs, args(len(a)), a...) + logf(e.ctx, ERROR, e.kvs, "", a...) } // Errorf will log format string as 'msg' field to the log at ERROR level. -// -//go:noinline func (e Entry) Errorf(s string, a ...interface{}) { - logf(e.ctx, 3, ERROR, e.kvs, s, a...) + logf(e.ctx, ERROR, e.kvs, s, a...) } // Panic will log formatted args as 'msg' field to the log at PANIC level. // This will then call panic causing the application to crash. -// -//go:noinline func (e Entry) Panic(a ...interface{}) { defer panic(fmt.Sprint(a...)) - logf(e.ctx, 3, PANIC, e.kvs, args(len(a)), a...) + logf(e.ctx, PANIC, e.kvs, "", a...) } // Panicf will log format string as 'msg' field to the log at PANIC level. // This will then call panic causing the application to crash. -// -//go:noinline func (e Entry) Panicf(s string, a ...interface{}) { defer panic(fmt.Sprintf(s, a...)) - logf(e.ctx, 3, PANIC, e.kvs, s, a...) + logf(e.ctx, PANIC, e.kvs, s, a...) } // Log will log formatted args as 'msg' field to the log at given level. -// -//go:noinline func (e Entry) Log(lvl LEVEL, a ...interface{}) { - logf(e.ctx, 3, lvl, e.kvs, args(len(a)), a...) + logf(e.ctx, lvl, e.kvs, "", a...) } // Logf will log format string as 'msg' field to the log at given level. -// -//go:noinline func (e Entry) Logf(lvl LEVEL, s string, a ...interface{}) { - logf(e.ctx, 3, lvl, e.kvs, s, a...) + logf(e.ctx, lvl, e.kvs, s, a...) } // Print will log formatted args to the stdout log output. -// -//go:noinline func (e Entry) Print(a ...interface{}) { - printf(3, e.kvs, args(len(a)), a...) + logf(e.ctx, UNSET, e.kvs, "", a...) } // Printf will log format string to the stdout log output. -// -//go:noinline func (e Entry) Printf(s string, a ...interface{}) { - printf(3, e.kvs, s, a...) + logf(e.ctx, UNSET, e.kvs, s, a...) } diff --git a/internal/log/format/format.go b/internal/log/format/format.go new file mode 100644 index 000000000..b7c650906 --- /dev/null +++ b/internal/log/format/format.go @@ -0,0 +1,90 @@ +// GoToSocial +// Copyright (C) GoToSocial Authors admin@gotosocial.org +// SPDX-License-Identifier: AGPL-3.0-or-later +// +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU Affero General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Affero General Public License for more details. +// +// You should have received a copy of the GNU Affero General Public License +// along with this program. If not, see <http://www.gnu.org/licenses/>. + +package format + +import ( + "sync/atomic" + "time" + + "code.superseriousbusiness.org/gotosocial/internal/log/level" + "codeberg.org/gruf/go-byteutil" + "codeberg.org/gruf/go-kv/v2" +) + +var ( + // ensure func signature conformance. + _ FormatFunc = (*Logfmt)(nil).Format + _ FormatFunc = (*JSON)(nil).Format +) + +// FormatFunc defines a function capable of formatting a log entry (args = 1+) to a given buffer (args = 0). +type FormatFunc func(buf *byteutil.Buffer, stamp time.Time, pc uintptr, lvl level.LEVEL, kvs []kv.Field, msg string) //nolint:revive + +type Base struct { + // TimeFormat defines time.Format() layout to + // use when appending a timestamp to log entry. + TimeFormat string + + // stampCache caches recently formatted stamps. + // + // see the following benchmark: + // goos: linux + // goarch: amd64 + // pkg: code.superseriousbusiness.org/gotosocial/internal/log/format + // cpu: AMD Ryzen 7 7840U w/ Radeon 780M Graphics + // BenchmarkStampCache + // BenchmarkStampCache-16 272199975 4.447 ns/op 0 B/op 0 allocs/op + // BenchmarkNoStampCache + // BenchmarkNoStampCache-16 76041058 15.94 ns/op 0 B/op 0 allocs/op + stampCache atomic.Pointer[struct { + stamp time.Time + format string + }] +} + +// AppendFormatStamp will append given timestamp according to TimeFormat, +// caching recently formatted stamp strings to reduce number of Format() calls. +func (b *Base) AppendFormatStamp(buf *byteutil.Buffer, stamp time.Time) { + const precision = time.Millisecond + + // Load cached stamp value. + last := b.stampCache.Load() + + // Round stamp to min precision. + stamp = stamp.Round(precision) + + // If a cached entry exists use this string. + if last != nil && stamp.Equal(last.stamp) { + buf.B = append(buf.B, last.format...) + return + } + + // Else format new and store ASAP, + // i.e. ignoring any CAS result. + format := stamp.Format(b.TimeFormat) + b.stampCache.CompareAndSwap(last, &struct { + stamp time.Time + format string + }{ + stamp: stamp, + format: format, + }) + + // Finally, append new timestamp. + buf.B = append(buf.B, format...) +} diff --git a/internal/log/format/format_test.go b/internal/log/format/format_test.go new file mode 100644 index 000000000..a8d229eb7 --- /dev/null +++ b/internal/log/format/format_test.go @@ -0,0 +1,60 @@ +// GoToSocial +// Copyright (C) GoToSocial Authors admin@gotosocial.org +// SPDX-License-Identifier: AGPL-3.0-or-later +// +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU Affero General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Affero General Public License for more details. +// +// You should have received a copy of the GNU Affero General Public License +// along with this program. If not, see <http://www.gnu.org/licenses/>. + +package format_test + +import ( + "testing" + "time" + + "code.superseriousbusiness.org/gotosocial/internal/log/format" + "codeberg.org/gruf/go-byteutil" +) + +func BenchmarkStampCache(b *testing.B) { + var base format.Base + base.TimeFormat = `02/01/2006 15:04:05.000` + + b.RunParallel(func(pb *testing.PB) { + var buf byteutil.Buffer + buf.B = make([]byte, 0, 1024) + + for pb.Next() { + base.AppendFormatStamp(&buf, time.Now()) + buf.B = buf.B[:0] + } + + buf.B = buf.B[:0] + }) +} + +func BenchmarkNoStampCache(b *testing.B) { + var base format.Base + base.TimeFormat = `02/01/2006 15:04:05.000` + + b.RunParallel(func(pb *testing.PB) { + var buf byteutil.Buffer + buf.B = make([]byte, 0, 1024) + + for pb.Next() { + buf.B = time.Now().AppendFormat(buf.B, base.TimeFormat) + buf.B = buf.B[:0] + } + + buf.B = buf.B[:0] + }) +} diff --git a/internal/log/format/json.go b/internal/log/format/json.go new file mode 100644 index 000000000..49964b5fe --- /dev/null +++ b/internal/log/format/json.go @@ -0,0 +1,241 @@ +// GoToSocial +// Copyright (C) GoToSocial Authors admin@gotosocial.org +// SPDX-License-Identifier: AGPL-3.0-or-later +// +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU Affero General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Affero General Public License for more details. +// +// You should have received a copy of the GNU Affero General Public License +// along with this program. If not, see <http://www.gnu.org/licenses/>. + +package format + +import ( + "encoding/json" + "time" + "unicode/utf8" + + "code.superseriousbusiness.org/gotosocial/internal/log/level" + "codeberg.org/gruf/go-byteutil" + "codeberg.org/gruf/go-caller" + "codeberg.org/gruf/go-kv/v2" +) + +type JSON struct{ Base } + +func (fmt *JSON) Format(buf *byteutil.Buffer, stamp time.Time, pc uintptr, lvl level.LEVEL, kvs []kv.Field, msg string) { + // Prepend opening JSON brace. + buf.B = append(buf.B, `{`...) + + if fmt.TimeFormat != "" { + // Append JSON formatted timestamp string. + buf.B = append(buf.B, `"timestamp":"`...) + fmt.AppendFormatStamp(buf, stamp) + buf.B = append(buf.B, `", `...) + } + + // Append JSON formatted caller func. + buf.B = append(buf.B, `"func":"`...) + buf.B = append(buf.B, caller.Get(pc)...) + buf.B = append(buf.B, `", `...) + + if lvl != level.UNSET { + // Append JSON formatted level string. + buf.B = append(buf.B, `"level":"`...) + buf.B = append(buf.B, lvl.String()...) + buf.B = append(buf.B, `", `...) + } + + // Append JSON formatted fields. + for _, field := range kvs { + appendStringJSON(buf, field.K) + buf.B = append(buf.B, `:`...) + b, _ := json.Marshal(field.V) + buf.B = append(buf.B, b...) + buf.B = append(buf.B, `, `...) + } + + if msg != "" { + // Append JSON formatted msg string. + buf.B = append(buf.B, `"msg":`...) + appendStringJSON(buf, msg) + } else if string(buf.B[len(buf.B)-2:]) == ", " { + // Drop the trailing ", ". + buf.B = buf.B[:len(buf.B)-2] + } + + // Append closing JSON brace. + buf.B = append(buf.B, `}`...) +} + +// appendStringJSON is modified from the encoding/json.appendString() +// function, copied in here such that we can use it for key appending. +func appendStringJSON(buf *byteutil.Buffer, src string) { + const hex = "0123456789abcdef" + buf.B = append(buf.B, '"') + start := 0 + for i := 0; i < len(src); { + if b := src[i]; b < utf8.RuneSelf { + if jsonSafeSet[b] { + i++ + continue + } + buf.B = append(buf.B, src[start:i]...) + switch b { + case '\\', '"': + buf.B = append(buf.B, '\\', b) + case '\b': + buf.B = append(buf.B, '\\', 'b') + case '\f': + buf.B = append(buf.B, '\\', 'f') + case '\n': + buf.B = append(buf.B, '\\', 'n') + case '\r': + buf.B = append(buf.B, '\\', 'r') + case '\t': + buf.B = append(buf.B, '\\', 't') + default: + // This encodes bytes < 0x20 except for \b, \f, \n, \r and \t. + buf.B = append(buf.B, '\\', 'u', '0', '0', hex[b>>4], hex[b&0xF]) + } + i++ + start = i + continue + } + n := len(src) - i + if n > utf8.UTFMax { + n = utf8.UTFMax + } + c, size := utf8.DecodeRuneInString(src[i : i+n]) + if c == utf8.RuneError && size == 1 { + buf.B = append(buf.B, src[start:i]...) + buf.B = append(buf.B, `\ufffd`...) + i += size + start = i + continue + } + // U+2028 is LINE SEPARATOR. + // U+2029 is PARAGRAPH SEPARATOR. + // They are both technically valid characters in JSON strings, + // but don't work in JSONP, which has to be evaluated as JavaScript, + // and can lead to security holes there. It is valid JSON to + // escape them, so we do so unconditionally. + // See https://en.wikipedia.org/wiki/JSON#Safety. + if c == '\u2028' || c == '\u2029' { + buf.B = append(buf.B, src[start:i]...) + buf.B = append(buf.B, '\\', 'u', '2', '0', '2', hex[c&0xF]) + i += size + start = i + continue + } + i += size + } + buf.B = append(buf.B, src[start:]...) + buf.B = append(buf.B, '"') +} + +var jsonSafeSet = [utf8.RuneSelf]bool{ + ' ': true, + '!': true, + '"': false, + '#': true, + '$': true, + '%': true, + '&': true, + '\'': true, + '(': true, + ')': true, + '*': true, + '+': true, + ',': true, + '-': true, + '.': true, + '/': true, + '0': true, + '1': true, + '2': true, + '3': true, + '4': true, + '5': true, + '6': true, + '7': true, + '8': true, + '9': true, + ':': true, + ';': true, + '<': true, + '=': true, + '>': true, + '?': true, + '@': true, + 'A': true, + 'B': true, + 'C': true, + 'D': true, + 'E': true, + 'F': true, + 'G': true, + 'H': true, + 'I': true, + 'J': true, + 'K': true, + 'L': true, + 'M': true, + 'N': true, + 'O': true, + 'P': true, + 'Q': true, + 'R': true, + 'S': true, + 'T': true, + 'U': true, + 'V': true, + 'W': true, + 'X': true, + 'Y': true, + 'Z': true, + '[': true, + '\\': false, + ']': true, + '^': true, + '_': true, + '`': true, + 'a': true, + 'b': true, + 'c': true, + 'd': true, + 'e': true, + 'f': true, + 'g': true, + 'h': true, + 'i': true, + 'j': true, + 'k': true, + 'l': true, + 'm': true, + 'n': true, + 'o': true, + 'p': true, + 'q': true, + 'r': true, + 's': true, + 't': true, + 'u': true, + 'v': true, + 'w': true, + 'x': true, + 'y': true, + 'z': true, + '{': true, + '|': true, + '}': true, + '~': true, + '\u007f': true, +} diff --git a/internal/log/format/logfmt.go b/internal/log/format/logfmt.go new file mode 100644 index 000000000..a774be8c9 --- /dev/null +++ b/internal/log/format/logfmt.go @@ -0,0 +1,67 @@ +// GoToSocial +// Copyright (C) GoToSocial Authors admin@gotosocial.org +// SPDX-License-Identifier: AGPL-3.0-or-later +// +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU Affero General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Affero General Public License for more details. +// +// You should have received a copy of the GNU Affero General Public License +// along with this program. If not, see <http://www.gnu.org/licenses/>. + +package format + +import ( + "time" + + "code.superseriousbusiness.org/gotosocial/internal/log/level" + "codeberg.org/gruf/go-byteutil" + "codeberg.org/gruf/go-caller" + "codeberg.org/gruf/go-kv/v2" + "codeberg.org/gruf/go-kv/v2/format" +) + +var args = format.DefaultArgs() + +type Logfmt struct{ Base } + +func (fmt *Logfmt) Format(buf *byteutil.Buffer, stamp time.Time, pc uintptr, lvl level.LEVEL, kvs []kv.Field, msg string) { + if fmt.TimeFormat != "" { + // Append formatted timestamp string. + buf.B = append(buf.B, `timestamp="`...) + fmt.AppendFormatStamp(buf, stamp) + buf.B = append(buf.B, `" `...) + } + + // Append formatted calling func. + buf.B = append(buf.B, `func=`...) + buf.B = append(buf.B, caller.Get(pc)...) + buf.B = append(buf.B, ' ') + + if lvl != level.UNSET { + // Append formatted level string. + buf.B = append(buf.B, `level=`...) + buf.B = append(buf.B, lvl.String()...) + buf.B = append(buf.B, ' ') + } + + // Append formatted fields. + for _, field := range kvs { + kv.AppendQuoteString(buf, field.K) + buf.B = append(buf.B, '=') + buf.B = format.Global.Append(buf.B, field.V, args) + buf.B = append(buf.B, ' ') + } + + if msg != "" { + // Append formatted msg string. + buf.B = append(buf.B, `msg=`...) + kv.AppendQuoteString(buf, msg) + } +} diff --git a/internal/log/init.go b/internal/log/init.go index 850ae8b5d..3ec3b777c 100644 --- a/internal/log/init.go +++ b/internal/log/init.go @@ -23,7 +23,8 @@ import ( "strings" ) -// ParseLevel will parse the log level from given string and set to appropriate LEVEL. +// ParseLevel will parse the log level from +// given string and set to appropriate LEVEL. func ParseLevel(str string) error { switch strings.ToLower(str) { case "trace": @@ -44,16 +45,22 @@ func ParseLevel(str string) error { return nil } -// EnableSyslog will enabling logging to the syslog at given address. -func EnableSyslog(proto, addr string) error { - // Dial a connection to the syslog daemon - writer, err := syslog.Dial(proto, addr, 0, "gotosocial") - if err != nil { - return err +// ParseFormat will parse the log format from +// given string and set appropriate formatter. +func ParseFormat(str string) error { + switch strings.ToLower(str) { + case "json": + SetJSON(true) + case "", "logfmt": + SetJSON(false) + default: + return fmt.Errorf("unknown log format: %q", str) } - - // Set the syslog writer - sysout = writer - return nil } + +// EnableSyslog will enabling logging to the syslog at given address. +func EnableSyslog(proto, addr string) (err error) { + sysout, err = syslog.Dial(proto, addr, 0, "gotosocial") + return err +} diff --git a/internal/log/level.go b/internal/log/level.go index be45e2964..5776db999 100644 --- a/internal/log/level.go +++ b/internal/log/level.go @@ -17,22 +17,18 @@ package log -// LEVEL defines a level of logging. -type LEVEL uint8 +import ( + "code.superseriousbusiness.org/gotosocial/internal/log/level" +) + +type LEVEL = level.LEVEL -// Default levels of logging. const ( - UNSET LEVEL = 0 - PANIC LEVEL = 1 - ERROR LEVEL = 100 - WARN LEVEL = 150 - INFO LEVEL = 200 - DEBUG LEVEL = 250 - TRACE LEVEL = 254 - ALL LEVEL = ^LEVEL(0) + PANIC = level.PANIC + ERROR = level.ERROR + WARN = level.WARN + INFO = level.INFO + DEBUG = level.DEBUG + TRACE = level.TRACE + UNSET = level.UNSET ) - -// CanLog returns whether an incoming log of 'lvl' can be logged against receiving level. -func (loglvl LEVEL) CanLog(lvl LEVEL) bool { - return loglvl > lvl -} diff --git a/internal/log/level/level.go b/internal/log/level/level.go new file mode 100644 index 000000000..11f2abb6d --- /dev/null +++ b/internal/log/level/level.go @@ -0,0 +1,45 @@ +// GoToSocial +// Copyright (C) GoToSocial Authors admin@gotosocial.org +// SPDX-License-Identifier: AGPL-3.0-or-later +// +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU Affero General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Affero General Public License for more details. +// +// You should have received a copy of the GNU Affero General Public License +// along with this program. If not, see <http://www.gnu.org/licenses/>. + +package level + +// LEVEL defines a level of logging. +type LEVEL uint8 + +// Logging levels. +const ( + PANIC LEVEL = 1 + ERROR LEVEL = 100 + WARN LEVEL = 150 + INFO LEVEL = 200 + DEBUG LEVEL = 250 + TRACE LEVEL = 254 + UNSET LEVEL = ^LEVEL(0) +) + +func (lvl LEVEL) String() string { + return strings[lvl] +} + +var strings = [int(UNSET) + 1]string{ + TRACE: "TRACE", + DEBUG: "DEBUG", + INFO: "INFO", + WARN: "WARN", + ERROR: "ERROR", + PANIC: "PANIC", +} diff --git a/internal/log/log.go b/internal/log/log.go index afb1bcdb8..50236db6e 100644 --- a/internal/log/log.go +++ b/internal/log/log.go @@ -22,35 +22,31 @@ import ( "fmt" "log/syslog" "os" - "strings" + "runtime" "time" + "code.superseriousbusiness.org/gotosocial/internal/log/format" + "code.superseriousbusiness.org/gotosocial/internal/log/level" "code.superseriousbusiness.org/gotosocial/internal/util/xslices" "codeberg.org/gruf/go-kv/v2" ) var ( // loglvl is the currently - // set logging output - loglvl LEVEL - - // lvlstrs is the lookup table - // of all log levels to strings. - lvlstrs = [int(ALL) + 1]string{ - TRACE: "TRACE", - DEBUG: "DEBUG", - INFO: "INFO", - WARN: "WARN", - ERROR: "ERROR", - PANIC: "PANIC", - } + // set logging output. + loglvl = level.UNSET + + // appendFormat stores log + // entry formatting function. + appendFormat = (&format.Logfmt{ + Base: format.Base{TimeFormat: timefmt}, + }).Format // syslog output, only set if enabled. sysout *syslog.Writer - // timefmt is the logging time format used, which includes - // the full field and required quoting - timefmt = `timestamp="02/01/2006 15:04:05.000" ` + // timefmt is the logging time format used. + timefmt = `02/01/2006 15:04:05.000` // ctxhooks allows modifying log content based on context. ctxhooks []func(context.Context, []kv.Field) []kv.Field @@ -61,12 +57,12 @@ func Hook(hook func(ctx context.Context, kvs []kv.Field) []kv.Field) { ctxhooks = append(ctxhooks, hook) } -// Level returns the currently set log +// Level returns the currently set log. func Level() LEVEL { return loglvl } -// SetLevel sets the max logging +// SetLevel sets the max logging. func SetLevel(lvl LEVEL) { loglvl = lvl } @@ -78,11 +74,20 @@ func TimeFormat() string { // SetTimeFormat sets the timestamp format to the given string. func SetTimeFormat(format string) { - if format == "" { - timefmt = format - return + timefmt = format +} + +// SetJSON enables / disables JSON log output formatting. +func SetJSON(enabled bool) { + if enabled { + var fmt format.JSON + fmt.TimeFormat = timefmt + appendFormat = fmt.Format + } else { + var fmt format.Logfmt + fmt.TimeFormat = timefmt + appendFormat = fmt.Format } - timefmt = `timestamp="` + format + `" ` } // New starts a new log entry. @@ -105,282 +110,166 @@ func WithFields(fields ...kv.Field) Entry { return Entry{kvs: fields} } -// Note that most of the below logging -// functions we specifically do NOT allow -// the Go buildchain to inline, to ensure -// expected behaviour in caller fetching. - // Trace will log formatted args as 'msg' field to the log at TRACE level. -// -//go:noinline func Trace(ctx context.Context, a ...interface{}) { - logf(ctx, 3, TRACE, nil, args(len(a)), a...) + logf(ctx, TRACE, nil, "", a...) } // Tracef will log format string as 'msg' field to the log at TRACE level. -// -//go:noinline func Tracef(ctx context.Context, s string, a ...interface{}) { - logf(ctx, 3, TRACE, nil, s, a...) + logf(ctx, TRACE, nil, s, a...) } // TraceKV will log the one key-value field to the log at TRACE level. -// -//go:noinline func TraceKV(ctx context.Context, key string, value interface{}) { - logf(ctx, 3, TRACE, []kv.Field{{K: key, V: value}}, "") + logf(ctx, TRACE, []kv.Field{{K: key, V: value}}, "") } // TraceKVs will log key-value fields to the log at TRACE level. -// -//go:noinline func TraceKVs(ctx context.Context, kvs ...kv.Field) { - logf(ctx, 3, TRACE, kvs, "") + logf(ctx, TRACE, kvs, "") } // Debug will log formatted args as 'msg' field to the log at DEBUG level. -// -//go:noinline func Debug(ctx context.Context, a ...interface{}) { - logf(ctx, 3, DEBUG, nil, args(len(a)), a...) + logf(ctx, DEBUG, nil, "", a...) } // Debugf will log format string as 'msg' field to the log at DEBUG level. -// -//go:noinline func Debugf(ctx context.Context, s string, a ...interface{}) { - logf(ctx, 3, DEBUG, nil, s, a...) + logf(ctx, DEBUG, nil, s, a...) } // DebugKV will log the one key-value field to the log at DEBUG level. -// -//go:noinline func DebugKV(ctx context.Context, key string, value interface{}) { - logf(ctx, 3, DEBUG, []kv.Field{{K: key, V: value}}, "") + logf(ctx, DEBUG, []kv.Field{{K: key, V: value}}, "") } // DebugKVs will log key-value fields to the log at DEBUG level. -// -//go:noinline func DebugKVs(ctx context.Context, kvs ...kv.Field) { - logf(ctx, 3, DEBUG, kvs, "") + logf(ctx, DEBUG, kvs, "") } // Info will log formatted args as 'msg' field to the log at INFO level. -// -//go:noinline func Info(ctx context.Context, a ...interface{}) { - logf(ctx, 3, INFO, nil, args(len(a)), a...) + logf(ctx, INFO, nil, "", a...) } // Infof will log format string as 'msg' field to the log at INFO level. -// -//go:noinline func Infof(ctx context.Context, s string, a ...interface{}) { - logf(ctx, 3, INFO, nil, s, a...) + logf(ctx, INFO, nil, s, a...) } // InfoKV will log the one key-value field to the log at INFO level. -// -//go:noinline func InfoKV(ctx context.Context, key string, value interface{}) { - logf(ctx, 3, INFO, []kv.Field{{K: key, V: value}}, "") + logf(ctx, INFO, []kv.Field{{K: key, V: value}}, "") } // InfoKVs will log key-value fields to the log at INFO level. -// -//go:noinline func InfoKVs(ctx context.Context, kvs ...kv.Field) { - logf(ctx, 3, INFO, kvs, "") + logf(ctx, INFO, kvs, "") } // Warn will log formatted args as 'msg' field to the log at WARN level. -// -//go:noinline func Warn(ctx context.Context, a ...interface{}) { - logf(ctx, 3, WARN, nil, args(len(a)), a...) + logf(ctx, WARN, nil, "", a...) } // Warnf will log format string as 'msg' field to the log at WARN level. -// -//go:noinline func Warnf(ctx context.Context, s string, a ...interface{}) { - logf(ctx, 3, WARN, nil, s, a...) + logf(ctx, WARN, nil, s, a...) } // WarnKV will log the one key-value field to the log at WARN level. -// -//go:noinline func WarnKV(ctx context.Context, key string, value interface{}) { - logf(ctx, 3, WARN, []kv.Field{{K: key, V: value}}, "") + logf(ctx, WARN, []kv.Field{{K: key, V: value}}, "") } // WarnKVs will log key-value fields to the log at WARN level. -// -//go:noinline func WarnKVs(ctx context.Context, kvs ...kv.Field) { - logf(ctx, 3, WARN, kvs, "") + logf(ctx, WARN, kvs, "") } // Error will log formatted args as 'msg' field to the log at ERROR level. -// -//go:noinline func Error(ctx context.Context, a ...interface{}) { - logf(ctx, 3, ERROR, nil, args(len(a)), a...) + logf(ctx, ERROR, nil, "", a...) } // Errorf will log format string as 'msg' field to the log at ERROR level. -// -//go:noinline func Errorf(ctx context.Context, s string, a ...interface{}) { - logf(ctx, 3, ERROR, nil, s, a...) + logf(ctx, ERROR, nil, s, a...) } // ErrorKV will log the one key-value field to the log at ERROR level. -// -//go:noinline func ErrorKV(ctx context.Context, key string, value interface{}) { - logf(ctx, 3, ERROR, []kv.Field{{K: key, V: value}}, "") + logf(ctx, ERROR, []kv.Field{{K: key, V: value}}, "") } // ErrorKVs will log key-value fields to the log at ERROR level. -// -//go:noinline func ErrorKVs(ctx context.Context, kvs ...kv.Field) { - logf(ctx, 3, ERROR, kvs, "") + logf(ctx, ERROR, kvs, "") } // Panic will log formatted args as 'msg' field to the log at PANIC level. // This will then call panic causing the application to crash. -// -//go:noinline func Panic(ctx context.Context, a ...interface{}) { defer panic(fmt.Sprint(a...)) - logf(ctx, 3, PANIC, nil, args(len(a)), a...) + logf(ctx, PANIC, nil, "", a...) } // Panicf will log format string as 'msg' field to the log at PANIC level. // This will then call panic causing the application to crash. -// -//go:noinline func Panicf(ctx context.Context, s string, a ...interface{}) { defer panic(fmt.Sprintf(s, a...)) - logf(ctx, 3, PANIC, nil, s, a...) + logf(ctx, PANIC, nil, s, a...) } // PanicKV will log the one key-value field to the log at PANIC level. // This will then call panic causing the application to crash. -// -//go:noinline func PanicKV(ctx context.Context, key string, value interface{}) { defer panic(kv.Field{K: key, V: value}.String()) - logf(ctx, 3, PANIC, []kv.Field{{K: key, V: value}}, "") + logf(ctx, PANIC, []kv.Field{{K: key, V: value}}, "") } // PanicKVs will log key-value fields to the log at PANIC level. // This will then call panic causing the application to crash. -// -//go:noinline func PanicKVs(ctx context.Context, kvs ...kv.Field) { defer panic(kv.Fields(kvs).String()) - logf(ctx, 3, PANIC, kvs, "") + logf(ctx, PANIC, kvs, "") } // Log will log formatted args as 'msg' field to the log at given level. -// -//go:noinline -func Log(ctx context.Context, lvl LEVEL, a ...interface{}) { - logf(ctx, 3, lvl, nil, args(len(a)), a...) +func Log(ctx context.Context, lvl LEVEL, a ...interface{}) { //nolint:revive + logf(ctx, lvl, nil, "", a...) } // Logf will log format string as 'msg' field to the log at given level. -// -//go:noinline -func Logf(ctx context.Context, lvl LEVEL, s string, a ...interface{}) { - logf(ctx, 3, lvl, nil, s, a...) +func Logf(ctx context.Context, lvl LEVEL, s string, a ...interface{}) { //nolint:revive + logf(ctx, lvl, nil, s, a...) } // LogKV will log the one key-value field to the log at given level. -// -//go:noinline func LogKV(ctx context.Context, lvl LEVEL, key string, value interface{}) { //nolint:revive - logf(ctx, 3, lvl, []kv.Field{{K: key, V: value}}, "") + logf(ctx, lvl, []kv.Field{{K: key, V: value}}, "") } // LogKVs will log key-value fields to the log at given level. -// -//go:noinline func LogKVs(ctx context.Context, lvl LEVEL, kvs ...kv.Field) { //nolint:revive - logf(ctx, 3, lvl, kvs, "") + logf(ctx, lvl, kvs, "") } // Print will log formatted args to the stdout log output. -// -//go:noinline func Print(a ...interface{}) { - printf(3, nil, args(len(a)), a...) + logf(context.Background(), UNSET, nil, "", a...) } // Printf will log format string to the stdout log output. -// -//go:noinline func Printf(s string, a ...interface{}) { - printf(3, nil, s, a...) -} - -// PrintKVs will log the one key-value field to the stdout log output. -// -//go:noinline -func PrintKV(key string, value interface{}) { - printf(3, []kv.Field{{K: key, V: value}}, "") -} - -// PrintKVs will log key-value fields to the stdout log output. -// -//go:noinline -func PrintKVs(kvs ...kv.Field) { - printf(3, kvs, "") -} - -//go:noinline -func printf(depth int, fields []kv.Field, s string, a ...interface{}) { - // Acquire buffer - buf := getBuf() - - // Append formatted timestamp according to `timefmt` - buf.B = time.Now().AppendFormat(buf.B, timefmt) - - // Append formatted caller func - buf.B = append(buf.B, `func=`...) - buf.B = append(buf.B, Caller(depth+1)...) - buf.B = append(buf.B, ' ') - - if len(fields) > 0 { - // Append formatted fields - kv.Fields(fields).AppendFormat(buf, false) - buf.B = append(buf.B, ' ') - } - - // Append formatted args - fmt.Fprintf(buf, s, a...) - - 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(INFO, buf.String()) - } - - // Write to log and release - _, _ = os.Stdout.Write(buf.B) - putBuf(buf) + logf(context.Background(), UNSET, nil, s, a...) } //go:noinline -func logf(ctx context.Context, depth int, lvl LEVEL, fields []kv.Field, s string, a ...interface{}) { +func logf(ctx context.Context, lvl LEVEL, fields []kv.Field, msg string, args ...interface{}) { var out *os.File // Check if enabled. @@ -396,25 +285,20 @@ func logf(ctx context.Context, depth int, lvl LEVEL, fields []kv.Field, s string out = os.Stdout } - // Acquire buffer - buf := getBuf() - - // Append formatted timestamp according to `timefmt` - buf.B = time.Now().AppendFormat(buf.B, timefmt) + // Get log stamp. + now := time.Now() - // Append formatted caller func - buf.B = append(buf.B, `func=`...) - buf.B = append(buf.B, Caller(depth+1)...) - buf.B = append(buf.B, ' ') + // Get caller information. + pcs := make([]uintptr, 1) + _ = runtime.Callers(3, pcs) - // Append formatted level string - buf.B = append(buf.B, `level=`...) - buf.B = append(buf.B, lvlstrs[lvl]...) - buf.B = append(buf.B, ' ') + // Acquire buffer. + buf := getBuf() + defer putBuf(buf) - if ctx != nil && len(ctxhooks) > 0 { - // Ensure fields have space for hooks (+1 for below). - fields = xslices.GrowJust(fields, len(ctxhooks)+1) + if ctx != nil { + // Ensure fields have space for context hooks. + fields = xslices.GrowJust(fields, len(ctxhooks)) // Pass context through hooks. for _, hook := range ctxhooks { @@ -422,18 +306,32 @@ func logf(ctx context.Context, depth int, lvl LEVEL, fields []kv.Field, s string } } - if s != "" { - // Append message (if given) as final log field. - fields = xslices.AppendJust(fields, kv.Field{ - K: "msg", V: fmt.Sprintf(s, a...), - }) + // If no args, use placeholders. + if msg == "" && len(args) > 0 { + const argstr = `%v%v%v%v%v%v%v%v%v%v` + + `%v%v%v%v%v%v%v%v%v%v` + + `%v%v%v%v%v%v%v%v%v%v` + + `%v%v%v%v%v%v%v%v%v%v` + msg = argstr[:2*len(args)] } - // Append formatted fields to log buffer. - kv.Fields(fields).AppendFormat(buf, false) + if msg != "" { + // Format the message string. + msg = fmt.Sprintf(msg, args...) + } + // Append formatted + // entry to buffer. + appendFormat(buf, + now, + pcs[0], + lvl, + fields, + msg, + ) + + // Ensure a final new-line char. if buf.B[len(buf.B)-1] != '\n' { - // Append a final newline buf.B = append(buf.B, '\n') } @@ -442,9 +340,8 @@ func logf(ctx context.Context, depth int, lvl LEVEL, fields []kv.Field, s string logsys(lvl, buf.String()) } - // Write to log and release + // Write to output file. _, _ = out.Write(buf.B) - putBuf(buf) } // logsys will log given msg at given severity to the syslog. @@ -467,27 +364,3 @@ func logsys(lvl LEVEL, msg string) { _ = sysout.Crit(msg) } } - -// args returns an args format string of format '%v' * count. -func args(count int) string { - const args = `%v%v%v%v%v%v%v%v%v%v` + - `%v%v%v%v%v%v%v%v%v%v` + - `%v%v%v%v%v%v%v%v%v%v` + - `%v%v%v%v%v%v%v%v%v%v` - - // Use predetermined args str - if count < len(args) { - return args[:count*2] - } - - // Allocate buffer of needed len - var buf strings.Builder - buf.Grow(count * 2) - - // Manually build an args str - for i := 0; i < count; i++ { - buf.WriteString(`%v`) - } - - return buf.String() -} diff --git a/internal/log/pool.go b/internal/log/pool.go index 3396fa244..1b45ed61f 100644 --- a/internal/log/pool.go +++ b/internal/log/pool.go @@ -23,22 +23,22 @@ import ( "codeberg.org/gruf/go-byteutil" ) -// bufPool provides a memory pool of log buffers. -var bufPool = sync.Pool{ - New: func() any { - return &byteutil.Buffer{ - B: make([]byte, 0, 512), - } - }, -} +// bufPool provides memory +// pool of log buffers. +var bufPool sync.Pool // getBuf acquires a buffer from memory pool. func getBuf() *byteutil.Buffer { buf, _ := bufPool.Get().(*byteutil.Buffer) + if buf == nil { + buf = new(byteutil.Buffer) + buf.B = make([]byte, 0, 512) + } return buf } -// putBuf places (after resetting) buffer back in memory pool, dropping if capacity too large. +// putBuf places (after resetting) buffer back in +// memory pool, dropping if capacity too large. func putBuf(buf *byteutil.Buffer) { if buf.Cap() > int(^uint16(0)) { return // drop large buffer |