[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

@@ -22,7 +22,6 @@
 	"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)
 			}
 		}
 	}

internal/federation/federatingdb/announce.go

@@ -22,7 +22,6 @@
 	"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 @@
 )
 
 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 {

internal/federation/federatingdb/create.go

@@ -22,7 +22,6 @@
 	"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 @@
 // 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

internal/federation/federatingdb/delete.go

@@ -37,6 +37,8 @@
 //
 // 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
 }
 

internal/federation/federatingdb/exists.go

@@ -20,9 +20,6 @@
 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 @@
 //
 // 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
 }

internal/federation/federatingdb/get.go

@@ -22,7 +22,6 @@
 	"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 @@
 //
 // 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 {
 

internal/federation/federatingdb/move.go

@@ -27,7 +27,6 @@
 	"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 @@
 )
 
 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 {

internal/federation/federatingdb/owns.go

@@ -23,7 +23,6 @@
 	"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 @@
 // 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
 	}
 

internal/federation/federatingdb/reject.go

@@ -22,7 +22,6 @@
 	"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 @@
 )
 
 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)
 			}
 		}
 	}

internal/federation/federatingdb/undo.go

@@ -22,7 +22,6 @@
 	"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 @@
 )
 
 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)
 		}
 	}
 

internal/federation/federatingdb/update.go

@@ -21,7 +21,6 @@
 	"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 @@
 //
 // 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
 }
 

internal/federation/federatingdb/util.go

@@ -23,7 +23,7 @@
 	"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)
 }

internal/log/log.go

@@ -22,6 +22,7 @@
 	"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{
+	if s != "" {
+		// Append message to log fields.
+		fields = slices.Grow(fields, 1)
+		fields = append(fields, kv.Field{
 			K: "msg", V: fmt.Sprintf(s, a...),
-	})).AppendFormat(buf, false)
+		})
+	}
+
+	// Append formatted fields to log buffer.
+	kv.Fields(fields).AppendFormat(buf, false)
 
 	if buf.B[len(buf.B)-1] != '\n' {
 		// Append a final newline