[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

12 files changed, 58 insertions, 130 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)
 }