From 8effc77788a201efe87636c94e16436da26b5199 Mon Sep 17 00:00:00 2001 From: kim <89579420+NyaaaWhatsUpDoc@users.noreply.github.com> Date: Tue, 17 Sep 2024 19:35:47 +0000 Subject: [PATCH] [chore] improved federatingdb logging in cases of unknown iri / types (#3313) * improved federatingdb logging in cases of unknown iri / types, add new log methods * whoops; forgot to wrap log argument in serialize{} ! * use debug instead of warn level * switch last entry to Debug --- internal/federation/federatingdb/accept.go | 26 +++--- internal/federation/federatingdb/announce.go | 11 +-- internal/federation/federatingdb/create.go | 17 +--- internal/federation/federatingdb/delete.go | 6 +- internal/federation/federatingdb/exists.go | 8 -- internal/federation/federatingdb/get.go | 5 +- internal/federation/federatingdb/move.go | 11 +-- internal/federation/federatingdb/owns.go | 17 ++-- internal/federation/federatingdb/reject.go | 25 +++--- internal/federation/federatingdb/undo.go | 23 ++--- internal/federation/federatingdb/update.go | 13 +-- internal/federation/federatingdb/util.go | 26 +++--- internal/log/log.go | 93 ++++++++++++++++++-- 13 files changed, 146 insertions(+), 135 deletions(-) diff --git a/internal/federation/federatingdb/accept.go b/internal/federation/federatingdb/accept.go index 571e62aed..0592e6b9b 100644 --- a/internal/federation/federatingdb/accept.go +++ b/internal/federation/federatingdb/accept.go @@ -22,7 +22,6 @@ import ( "errors" "net/url" - "codeberg.org/gruf/go-logger/v2/level" "github.com/superseriousbusiness/activity/streams/vocab" "github.com/superseriousbusiness/gotosocial/internal/ap" "github.com/superseriousbusiness/gotosocial/internal/db" @@ -46,15 +45,7 @@ func (f *federatingDB) GetAccept( } func (f *federatingDB) Accept(ctx context.Context, accept vocab.ActivityStreamsAccept) error { - if log.Level() >= level.DEBUG { - i, err := marshalItem(accept) - if err != nil { - return err - } - l := log.WithContext(ctx). - WithField("accept", i) - l.Debug("entering Accept") - } + log.DebugKV(ctx, "accept", serialize{accept}) activityContext := getActivityContext(ctx) if activityContext.internal { @@ -81,10 +72,9 @@ func (f *federatingDB) Accept(ctx context.Context, accept vocab.ActivityStreamsA // handling the ones we know how to handle. for _, object := range ap.ExtractObjects(accept) { if asType := object.GetType(); asType != nil { - // Check and handle any - // vocab.Type objects. - // nolint:gocritic - switch asType.GetTypeName() { + + // Check and handle any vocab.Type objects. + switch name := asType.GetTypeName(); name { // ACCEPT FOLLOW case ap.ActivityFollow: @@ -96,6 +86,10 @@ func (f *federatingDB) Accept(ctx context.Context, accept vocab.ActivityStreamsA ); err != nil { return err } + + // UNHANDLED + default: + log.Debugf(ctx, "unhandled object type: %s", name) } } else if object.IsIRI() { @@ -137,6 +131,10 @@ func (f *federatingDB) Accept(ctx context.Context, accept vocab.ActivityStreamsA ); err != nil { return err } + + // UNHANDLED + default: + log.Debugf(ctx, "unhandled iri type: %s", objIRI) } } } diff --git a/internal/federation/federatingdb/announce.go b/internal/federation/federatingdb/announce.go index 3a3b91236..efd977700 100644 --- a/internal/federation/federatingdb/announce.go +++ b/internal/federation/federatingdb/announce.go @@ -22,7 +22,6 @@ import ( "net/url" "slices" - "codeberg.org/gruf/go-logger/v2/level" "github.com/superseriousbusiness/activity/streams/vocab" "github.com/superseriousbusiness/gotosocial/internal/ap" "github.com/superseriousbusiness/gotosocial/internal/gtserror" @@ -31,15 +30,7 @@ import ( ) func (f *federatingDB) Announce(ctx context.Context, announce vocab.ActivityStreamsAnnounce) error { - if log.Level() >= level.DEBUG { - i, err := marshalItem(announce) - if err != nil { - return err - } - l := log.WithContext(ctx). - WithField("announce", i) - l.Debug("entering Announce") - } + log.DebugKV(ctx, "announce", serialize{announce}) activityContext := getActivityContext(ctx) if activityContext.internal { diff --git a/internal/federation/federatingdb/create.go b/internal/federation/federatingdb/create.go index 44f3cd98c..2a780ed7c 100644 --- a/internal/federation/federatingdb/create.go +++ b/internal/federation/federatingdb/create.go @@ -22,7 +22,6 @@ import ( "errors" "fmt" - "codeberg.org/gruf/go-logger/v2/level" "github.com/miekg/dns" "github.com/superseriousbusiness/activity/streams/vocab" "github.com/superseriousbusiness/gotosocial/internal/ap" @@ -48,17 +47,7 @@ import ( // Under certain conditions and network activities, Create may be called // multiple times for the same ActivityStreams object. func (f *federatingDB) Create(ctx context.Context, asType vocab.Type) error { - if log.Level() >= level.TRACE { - i, err := marshalItem(asType) - if err != nil { - return err - } - - log. - WithContext(ctx). - WithField("create", i). - Trace("entering Create") - } + log.DebugKV(ctx, "create", serialize{asType}) activityContext := getActivityContext(ctx) if activityContext.internal { @@ -74,7 +63,7 @@ func (f *federatingDB) Create(ctx context.Context, asType vocab.Type) error { return nil } - switch asType.GetTypeName() { + switch name := asType.GetTypeName(); name { case ap.ActivityBlock: // BLOCK SOMETHING return f.activityBlock(ctx, asType, receivingAcct, requestingAcct) @@ -90,6 +79,8 @@ func (f *federatingDB) Create(ctx context.Context, asType vocab.Type) error { case ap.ActivityFlag: // FLAG / REPORT SOMETHING return f.activityFlag(ctx, asType, receivingAcct, requestingAcct) + default: + log.Debugf(ctx, "unhandled object type: %s", name) } return nil diff --git a/internal/federation/federatingdb/delete.go b/internal/federation/federatingdb/delete.go index 931320940..c628bd2d1 100644 --- a/internal/federation/federatingdb/delete.go +++ b/internal/federation/federatingdb/delete.go @@ -37,6 +37,8 @@ import ( // // The library makes this call only after acquiring a lock first. func (f *federatingDB) Delete(ctx context.Context, id *url.URL) error { + log.DebugKV(ctx, "id", id) + activityContext := getActivityContext(ctx) if activityContext.internal { return nil // Already processed. @@ -81,9 +83,7 @@ func (f *federatingDB) Delete(ctx context.Context, id *url.URL) error { return nil } - // Log at debug level, as lots of these could indicate federation - // issues between remote and this instance, or help with debugging. - log.Debugf(ctx, "received delete for unknown target: %s", uriStr) + log.Debugf(ctx, "unknown iri: %s", uriStr) return nil } diff --git a/internal/federation/federatingdb/exists.go b/internal/federation/federatingdb/exists.go index 43ebd566a..abac9960e 100644 --- a/internal/federation/federatingdb/exists.go +++ b/internal/federation/federatingdb/exists.go @@ -20,9 +20,6 @@ package federatingdb import ( "context" "net/url" - - "codeberg.org/gruf/go-kv" - "github.com/superseriousbusiness/gotosocial/internal/log" ) // Exists returns true if the database has an entry for the specified @@ -32,10 +29,5 @@ import ( // // Implementation note: this just straight up isn't implemented, and doesn't *really* need to be either. func (f *federatingDB) Exists(ctx context.Context, id *url.URL) (exists bool, err error) { - l := log.WithContext(ctx). - WithFields(kv.Fields{ - {"id", id}, - }...) - l.Debug("entering Exists") return false, nil } diff --git a/internal/federation/federatingdb/get.go b/internal/federation/federatingdb/get.go index 5dcebb877..8ba10a4f9 100644 --- a/internal/federation/federatingdb/get.go +++ b/internal/federation/federatingdb/get.go @@ -22,7 +22,6 @@ import ( "fmt" "net/url" - "codeberg.org/gruf/go-kv" "github.com/superseriousbusiness/activity/streams/vocab" "github.com/superseriousbusiness/gotosocial/internal/log" "github.com/superseriousbusiness/gotosocial/internal/uris" @@ -32,9 +31,7 @@ import ( // // The library makes this call only after acquiring a lock first. func (f *federatingDB) Get(ctx context.Context, id *url.URL) (value vocab.Type, err error) { - l := log.WithContext(ctx). - WithFields(kv.Fields{{"id", id}}...) - l.Debug("entering Get") + log.DebugKV(ctx, "id", id) switch { diff --git a/internal/federation/federatingdb/move.go b/internal/federation/federatingdb/move.go index 681a9cff2..6ae299e30 100644 --- a/internal/federation/federatingdb/move.go +++ b/internal/federation/federatingdb/move.go @@ -27,7 +27,6 @@ import ( "errors" "fmt" - "codeberg.org/gruf/go-logger/v2/level" "github.com/superseriousbusiness/activity/streams/vocab" "github.com/superseriousbusiness/gotosocial/internal/ap" "github.com/superseriousbusiness/gotosocial/internal/gtserror" @@ -37,15 +36,7 @@ import ( ) func (f *federatingDB) Move(ctx context.Context, move vocab.ActivityStreamsMove) error { - if log.Level() >= level.DEBUG { - i, err := marshalItem(move) - if err != nil { - return err - } - l := log.WithContext(ctx). - WithField("move", i) - l.Debug("entering Move") - } + log.DebugKV(ctx, "move", serialize{move}) activityContext := getActivityContext(ctx) if activityContext.internal { diff --git a/internal/federation/federatingdb/owns.go b/internal/federation/federatingdb/owns.go index cc3bb7d5d..3da41dd61 100644 --- a/internal/federation/federatingdb/owns.go +++ b/internal/federation/federatingdb/owns.go @@ -23,7 +23,6 @@ import ( "fmt" "net/url" - "codeberg.org/gruf/go-kv" "github.com/superseriousbusiness/gotosocial/internal/config" "github.com/superseriousbusiness/gotosocial/internal/db" "github.com/superseriousbusiness/gotosocial/internal/gtscontext" @@ -36,15 +35,11 @@ import ( // the database has an entry for the IRI. // The library makes this call only after acquiring a lock first. func (f *federatingDB) Owns(ctx context.Context, id *url.URL) (bool, error) { - l := log.WithContext(ctx). - WithFields(kv.Fields{ - {"id", id}, - }...) - l.Debug("entering Owns") + log.DebugKV(ctx, "id", id) // if the id host isn't this instance host, we don't own this IRI if host := config.GetHost(); id.Host != host { - l.Tracef("we DO NOT own activity because the host is %s not %s", id.Host, host) + log.Tracef(ctx, "we DO NOT own activity because the host is %s not %s", id.Host, host) return false, nil } @@ -85,7 +80,7 @@ func (f *federatingDB) Owns(ctx context.Context, id *url.URL) (bool, error) { // an actual error happened return false, fmt.Errorf("database error fetching account with username %s: %s", username, err) } - l.Debugf("we own url %s", id.String()) + log.Debugf(ctx, "we own url %s", id) return true, nil } @@ -102,7 +97,7 @@ func (f *federatingDB) Owns(ctx context.Context, id *url.URL) (bool, error) { // an actual error happened return false, fmt.Errorf("database error fetching account with username %s: %s", username, err) } - l.Debugf("we own url %s", id.String()) + log.Debugf(ctx, "we own url %s", id) return true, nil } @@ -119,7 +114,7 @@ func (f *federatingDB) Owns(ctx context.Context, id *url.URL) (bool, error) { // an actual error happened return false, fmt.Errorf("database error fetching account with username %s: %s", username, err) } - l.Debugf("we own url %s", id.String()) + log.Debugf(ctx, "we own url %s", id) return true, nil } @@ -148,7 +143,7 @@ func (f *federatingDB) Owns(ctx context.Context, id *url.URL) (bool, error) { // an actual error happened return false, fmt.Errorf("database error fetching block with id %s: %s", blockID, err) } - l.Debugf("we own url %s", id.String()) + log.Debugf(ctx, "we own url %s", id) return true, nil } diff --git a/internal/federation/federatingdb/reject.go b/internal/federation/federatingdb/reject.go index 404e19c4c..498dfa8e9 100644 --- a/internal/federation/federatingdb/reject.go +++ b/internal/federation/federatingdb/reject.go @@ -22,7 +22,6 @@ import ( "errors" "time" - "codeberg.org/gruf/go-logger/v2/level" "github.com/superseriousbusiness/activity/streams/vocab" "github.com/superseriousbusiness/gotosocial/internal/ap" "github.com/superseriousbusiness/gotosocial/internal/db" @@ -35,15 +34,7 @@ import ( ) func (f *federatingDB) Reject(ctx context.Context, reject vocab.ActivityStreamsReject) error { - if log.Level() >= level.DEBUG { - i, err := marshalItem(reject) - if err != nil { - return err - } - l := log.WithContext(ctx). - WithField("reject", i) - l.Debug("entering Reject") - } + log.DebugKV(ctx, "reject", serialize{reject}) activityContext := getActivityContext(ctx) if activityContext.internal { @@ -62,10 +53,8 @@ func (f *federatingDB) Reject(ctx context.Context, reject vocab.ActivityStreamsR for _, object := range ap.ExtractObjects(reject) { if asType := object.GetType(); asType != nil { - // Check and handle any - // vocab.Type objects. - // nolint:gocritic - switch asType.GetTypeName() { + // Check and handle any vocab.Type objects. + switch name := asType.GetTypeName(); name { // REJECT FOLLOW case ap.ActivityFollow: @@ -77,6 +66,10 @@ func (f *federatingDB) Reject(ctx context.Context, reject vocab.ActivityStreamsR ); err != nil { return err } + + // UNHANDLED + default: + log.Debugf(ctx, "unhandled object type: %s", name) } } else if object.IsIRI() { @@ -118,6 +111,10 @@ func (f *federatingDB) Reject(ctx context.Context, reject vocab.ActivityStreamsR ); err != nil { return err } + + // UNHANDLED + default: + log.Debugf(ctx, "unhandled iri type: %s", objIRI) } } } diff --git a/internal/federation/federatingdb/undo.go b/internal/federation/federatingdb/undo.go index 71e248aac..b3e0a2825 100644 --- a/internal/federation/federatingdb/undo.go +++ b/internal/federation/federatingdb/undo.go @@ -22,7 +22,6 @@ import ( "errors" "fmt" - "codeberg.org/gruf/go-logger/v2/level" "github.com/superseriousbusiness/activity/streams/vocab" "github.com/superseriousbusiness/gotosocial/internal/ap" "github.com/superseriousbusiness/gotosocial/internal/db" @@ -33,15 +32,7 @@ import ( ) func (f *federatingDB) Undo(ctx context.Context, undo vocab.ActivityStreamsUndo) error { - if log.Level() >= level.DEBUG { - i, err := marshalItem(undo) - if err != nil { - return err - } - l := log.WithContext(ctx). - WithField("undo", i) - l.Debug("entering Undo") - } + log.DebugKV(ctx, "undo", serialize{undo}) activityContext := getActivityContext(ctx) if activityContext.internal { @@ -59,9 +50,8 @@ func (f *federatingDB) Undo(ctx context.Context, undo vocab.ActivityStreamsUndo) continue } - // Check and handle any - // vocab.Type objects. - switch asType.GetTypeName() { + // Check and handle any vocab.Type objects. + switch name := asType.GetTypeName(); name { // UNDO FOLLOW case ap.ActivityFollow: @@ -99,10 +89,9 @@ func (f *federatingDB) Undo(ctx context.Context, undo vocab.ActivityStreamsUndo) return err } - // UNDO ANNOUNCE - case ap.ActivityAnnounce: - // TODO: actually handle this! - log.Warn(ctx, "skipped undo announce") + // UNHANDLED + default: + log.Debugf(ctx, "unhandled object type: %s", name) } } diff --git a/internal/federation/federatingdb/update.go b/internal/federation/federatingdb/update.go index 16ecf3443..a2a9777d1 100644 --- a/internal/federation/federatingdb/update.go +++ b/internal/federation/federatingdb/update.go @@ -21,7 +21,6 @@ import ( "context" "errors" - "codeberg.org/gruf/go-logger/v2/level" "github.com/superseriousbusiness/activity/streams/vocab" "github.com/superseriousbusiness/gotosocial/internal/ap" "github.com/superseriousbusiness/gotosocial/internal/config" @@ -42,16 +41,7 @@ import ( // // The library makes this call only after acquiring a lock first. func (f *federatingDB) Update(ctx context.Context, asType vocab.Type) error { - l := log.WithContext(ctx) - - if log.Level() >= level.DEBUG { - i, err := marshalItem(asType) - if err != nil { - return err - } - l = l.WithField("update", i) - l.Debug("entering Update") - } + log.DebugKV(ctx, "update", serialize{asType}) activityContext := getActivityContext(ctx) if activityContext.internal { @@ -69,6 +59,7 @@ func (f *federatingDB) Update(ctx context.Context, asType vocab.Type) error { return f.updateStatusable(ctx, receivingAcct, requestingAcct, statusable) } + log.Debugf(ctx, "unhandled object type: %T", asType) return nil } diff --git a/internal/federation/federatingdb/util.go b/internal/federation/federatingdb/util.go index 43d811914..6660bd06a 100644 --- a/internal/federation/federatingdb/util.go +++ b/internal/federation/federatingdb/util.go @@ -23,7 +23,7 @@ import ( "fmt" "net/url" - "codeberg.org/gruf/go-logger/v2/level" + "codeberg.org/gruf/go-byteutil" "github.com/superseriousbusiness/activity/streams" "github.com/superseriousbusiness/activity/streams/vocab" "github.com/superseriousbusiness/gotosocial/internal/ap" @@ -91,15 +91,7 @@ func sameActor(actor1 vocab.ActivityStreamsActorProperty, actor2 vocab.ActivityS // The go-fed library will handle setting the 'id' property on the // activity or object provided with the value returned. func (f *federatingDB) NewID(ctx context.Context, t vocab.Type) (idURL *url.URL, err error) { - if log.Level() >= level.DEBUG { - i, err := marshalItem(t) - if err != nil { - return nil, err - } - l := log.WithContext(ctx). - WithField("newID", i) - l.Debug("entering NewID") - } + log.DebugKV(ctx, "newID", serialize{t}) // Most of our types set an ID already // by this point, return this if found. @@ -268,16 +260,20 @@ func getActivityContext(ctx context.Context) activityContext { } } -func marshalItem(item vocab.Type) (string, error) { - m, err := ap.Serialize(item) +// serialize wraps a vocab.Type to provide +// lazy-serialization along with error output. +type serialize struct{ item vocab.Type } + +func (s serialize) String() string { + m, err := ap.Serialize(s.item) if err != nil { - return "", err + return "!(error serializing item: " + err.Error() + ")" } b, err := json.Marshal(m) if err != nil { - return "", err + return "!(error json marshaling item: " + err.Error() + ")" } - return string(b), nil + return byteutil.B2S(b) } diff --git a/internal/log/log.go b/internal/log/log.go index 15c917757..c90a8167f 100644 --- a/internal/log/log.go +++ b/internal/log/log.go @@ -22,6 +22,7 @@ import ( "fmt" "log/syslog" "os" + "slices" "strings" "syscall" "time" @@ -102,6 +103,14 @@ func Tracef(ctx context.Context, s string, a ...interface{}) { logf(ctx, 3, level.TRACE, nil, s, a...) } +func TraceKV(ctx context.Context, key string, value interface{}) { + logf(ctx, 3, level.TRACE, []kv.Field{{K: key, V: value}}, "") +} + +func TraceKVs(ctx context.Context, kvs ...kv.Field) { + logf(ctx, 3, level.TRACE, kvs, "") +} + func Debug(ctx context.Context, a ...interface{}) { logf(ctx, 3, level.DEBUG, nil, args(len(a)), a...) } @@ -110,6 +119,14 @@ func Debugf(ctx context.Context, s string, a ...interface{}) { logf(ctx, 3, level.DEBUG, nil, s, a...) } +func DebugKV(ctx context.Context, key string, value interface{}) { + logf(ctx, 3, level.DEBUG, []kv.Field{{K: key, V: value}}, "") +} + +func DebugKVs(ctx context.Context, kvs ...kv.Field) { + logf(ctx, 3, level.DEBUG, kvs, "") +} + func Info(ctx context.Context, a ...interface{}) { logf(ctx, 3, level.INFO, nil, args(len(a)), a...) } @@ -118,6 +135,14 @@ func Infof(ctx context.Context, s string, a ...interface{}) { logf(ctx, 3, level.INFO, nil, s, a...) } +func InfoKV(ctx context.Context, key string, value interface{}) { + logf(ctx, 3, level.INFO, []kv.Field{{K: key, V: value}}, "") +} + +func InfoKVs(ctx context.Context, kvs ...kv.Field) { + logf(ctx, 3, level.INFO, kvs, "") +} + func Warn(ctx context.Context, a ...interface{}) { logf(ctx, 3, level.WARN, nil, args(len(a)), a...) } @@ -126,6 +151,14 @@ func Warnf(ctx context.Context, s string, a ...interface{}) { logf(ctx, 3, level.WARN, nil, s, a...) } +func WarnKV(ctx context.Context, key string, value interface{}) { + logf(ctx, 3, level.WARN, []kv.Field{{K: key, V: value}}, "") +} + +func WarnKVs(ctx context.Context, kvs ...kv.Field) { + logf(ctx, 3, level.WARN, kvs, "") +} + func Error(ctx context.Context, a ...interface{}) { logf(ctx, 3, level.ERROR, nil, args(len(a)), a...) } @@ -134,6 +167,14 @@ func Errorf(ctx context.Context, s string, a ...interface{}) { logf(ctx, 3, level.ERROR, nil, s, a...) } +func ErrorKV(ctx context.Context, key string, value interface{}) { + logf(ctx, 3, level.ERROR, []kv.Field{{K: key, V: value}}, "") +} + +func ErrorKVs(ctx context.Context, kvs ...kv.Field) { + logf(ctx, 3, level.WARN, kvs, "") +} + func Fatal(ctx context.Context, a ...interface{}) { defer syscall.Exit(1) logf(ctx, 3, level.FATAL, nil, args(len(a)), a...) @@ -144,6 +185,14 @@ func Fatalf(ctx context.Context, s string, a ...interface{}) { logf(ctx, 3, level.FATAL, nil, s, a...) } +func FatalKV(ctx context.Context, key string, value interface{}) { + logf(ctx, 3, level.FATAL, []kv.Field{{K: key, V: value}}, "") +} + +func FatalKVs(ctx context.Context, kvs ...kv.Field) { + logf(ctx, 3, level.FATAL, kvs, "") +} + func Panic(ctx context.Context, a ...interface{}) { defer panic(fmt.Sprint(a...)) logf(ctx, 3, level.PANIC, nil, args(len(a)), a...) @@ -154,6 +203,14 @@ func Panicf(ctx context.Context, s string, a ...interface{}) { logf(ctx, 3, level.PANIC, nil, s, a...) } +func PanicKV(ctx context.Context, key string, value interface{}) { + logf(ctx, 3, level.PANIC, []kv.Field{{K: key, V: value}}, "") +} + +func PanicKVs(ctx context.Context, kvs ...kv.Field) { + logf(ctx, 3, level.PANIC, kvs, "") +} + // Log will log formatted args as 'msg' field to the log at given level. func Log(ctx context.Context, lvl level.LEVEL, a ...interface{}) { logf(ctx, 3, lvl, nil, args(len(a)), a...) @@ -164,16 +221,36 @@ func Logf(ctx context.Context, lvl level.LEVEL, s string, a ...interface{}) { logf(ctx, 3, lvl, nil, s, a...) } +// LogKV will log the one key-value field to the log at given level. +func LogKV(ctx context.Context, lvl level.LEVEL, key string, value interface{}) { //nolint:revive + logf(ctx, 3, level.DEBUG, []kv.Field{{K: key, V: value}}, "") +} + +// LogKVs will log key-value fields to the log at given level. +func LogKVs(ctx context.Context, lvl level.LEVEL, kvs ...kv.Field) { //nolint:revive + logf(ctx, 3, lvl, kvs, "") +} + // Print will log formatted args to the stdout log output. func Print(a ...interface{}) { printf(3, nil, args(len(a)), a...) } -// Print will log format string to the stdout log output. +// Printf will log format string to the stdout log output. func Printf(s string, a ...interface{}) { printf(3, nil, s, a...) } +// PrintKVs will log the one key-value field to the stdout log output. +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. +func PrintKVs(kvs ...kv.Field) { + printf(3, kvs, "") +} + func printf(depth int, fields []kv.Field, s string, a ...interface{}) { // Acquire buffer buf := getBuf() @@ -249,10 +326,16 @@ func logf(ctx context.Context, depth int, lvl level.LEVEL, fields []kv.Field, s } } - // Append formatted fields with msg - kv.Fields(append(fields, kv.Field{ - K: "msg", V: fmt.Sprintf(s, a...), - })).AppendFormat(buf, false) + if s != "" { + // Append message to log fields. + fields = slices.Grow(fields, 1) + fields = append(fields, kv.Field{ + K: "msg", V: fmt.Sprintf(s, a...), + }) + } + + // Append formatted fields to log buffer. + kv.Fields(fields).AppendFormat(buf, false) if buf.B[len(buf.B)-1] != '\n' { // Append a final newline