[feature] Add a request ID and include it in logs (#1476)

This adds a lightweight form of tracing to GTS. Each incoming request is
assigned a Request ID which we then pass on and log in all our log
lines. Any function that gets called downstream from an HTTP handler
should now emit a requestID=value pair whenever it logs something.

Co-authored-by: kim <grufwub@gmail.com>

15 files changed, 114 insertions, 101 deletions

diff --git a/internal/federation/authenticate.go b/internal/federation/authenticate.go
index 157a1830b..a966bb26a 100644
--- a/internal/federation/authenticate.go
+++ b/internal/federation/authenticate.go
@@ -124,7 +124,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 	if vi == nil {
 		err := errors.New("http request wasn't signed or http signature was invalid")
 		errWithCode := gtserror.NewErrorUnauthorized(err, err.Error())
-		log.Debug(errWithCode)
+		log.Debug(ctx, errWithCode)
 		return nil, errWithCode
 	}
 
@@ -132,7 +132,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 	if !ok {
 		err := errors.New("http request wasn't signed or http signature was invalid")
 		errWithCode := gtserror.NewErrorUnauthorized(err, err.Error())
-		log.Debug(errWithCode)
+		log.Debug(ctx, errWithCode)
 		return nil, errWithCode
 	}
 
@@ -141,7 +141,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 	if si == nil {
 		err := errors.New("http request wasn't signed or http signature was invalid")
 		errWithCode := gtserror.NewErrorUnauthorized(err, err.Error())
-		log.Debug(errWithCode)
+		log.Debug(ctx, errWithCode)
 		return nil, errWithCode
 	}
 
@@ -149,7 +149,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 	if !ok {
 		err := errors.New("http request wasn't signed or http signature was invalid")
 		errWithCode := gtserror.NewErrorUnauthorized(err, err.Error())
-		log.Debug(errWithCode)
+		log.Debug(ctx, errWithCode)
 		return nil, errWithCode
 	}
 
@@ -157,7 +157,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 	requestingPublicKeyID, err := url.Parse(verifier.KeyId())
 	if err != nil {
 		errWithCode := gtserror.NewErrorBadRequest(err, fmt.Sprintf("couldn't parse public key URL %s", verifier.KeyId()))
-		log.Debug(errWithCode)
+		log.Debug(ctx, errWithCode)
 		return nil, errWithCode
 	}
 
@@ -170,12 +170,12 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 	if host := config.GetHost(); strings.EqualFold(requestingHost, host) {
 		// LOCAL ACCOUNT REQUEST
 		// the request is coming from INSIDE THE HOUSE so skip the remote dereferencing
-		log.Tracef("proceeding without dereference for local public key %s", requestingPublicKeyID)
+		log.Tracef(ctx, "proceeding without dereference for local public key %s", requestingPublicKeyID)
 
 		requestingLocalAccount, err = f.db.GetAccountByPubkeyID(ctx, requestingPublicKeyID.String())
 		if err != nil {
 			errWithCode := gtserror.NewErrorInternalError(fmt.Errorf("couldn't get account with public key uri %s from the database: %s", requestingPublicKeyID.String(), err))
-			log.Debug(errWithCode)
+			log.Debug(ctx, errWithCode)
 			return nil, errWithCode
 		}
 
@@ -184,18 +184,18 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 		pkOwnerURI, err = url.Parse(requestingLocalAccount.URI)
 		if err != nil {
 			errWithCode := gtserror.NewErrorBadRequest(err, fmt.Sprintf("couldn't parse public key owner URL %s", requestingLocalAccount.URI))
-			log.Debug(errWithCode)
+			log.Debug(ctx, errWithCode)
 			return nil, errWithCode
 		}
 	} else if requestingRemoteAccount, err = f.db.GetAccountByPubkeyID(ctx, requestingPublicKeyID.String()); err == nil {
 		// REMOTE ACCOUNT REQUEST WITH KEY CACHED LOCALLY
 		// this is a remote account and we already have the public key for it so use that
-		log.Tracef("proceeding without dereference for cached public key %s", requestingPublicKeyID)
+		log.Tracef(ctx, "proceeding without dereference for cached public key %s", requestingPublicKeyID)
 		publicKey = requestingRemoteAccount.PublicKey
 		pkOwnerURI, err = url.Parse(requestingRemoteAccount.URI)
 		if err != nil {
 			errWithCode := gtserror.NewErrorBadRequest(err, fmt.Sprintf("couldn't parse public key owner URL %s", requestingRemoteAccount.URI))
-			log.Debug(errWithCode)
+			log.Debug(ctx, errWithCode)
 			return nil, errWithCode
 		}
 	} else {
@@ -205,21 +205,21 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 		gone, err := f.CheckGone(ctx, requestingPublicKeyID)
 		if err != nil {
 			errWithCode := gtserror.NewErrorInternalError(fmt.Errorf("error checking for tombstone for %s: %s", requestingPublicKeyID, err))
-			log.Debug(errWithCode)
+			log.Debug(ctx, errWithCode)
 			return nil, errWithCode
 		}
 
 		if gone {
 			errWithCode := gtserror.NewErrorGone(fmt.Errorf("account with public key %s is gone", requestingPublicKeyID))
-			log.Debug(errWithCode)
+			log.Debug(ctx, errWithCode)
 			return nil, errWithCode
 		}
 
-		log.Tracef("proceeding with dereference for uncached public key %s", requestingPublicKeyID)
+		log.Tracef(ctx, "proceeding with dereference for uncached public key %s", requestingPublicKeyID)
 		trans, err := f.transportController.NewTransportForUsername(transport.WithFastfail(ctx), requestedUsername)
 		if err != nil {
 			errWithCode := gtserror.NewErrorInternalError(fmt.Errorf("error creating transport for %s: %s", requestedUsername, err))
-			log.Debug(errWithCode)
+			log.Debug(ctx, errWithCode)
 			return nil, errWithCode
 		}
 
@@ -231,16 +231,16 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 				// we should add a tombstone to our database so that we can avoid trying to deref it in future
 				if err := f.HandleGone(ctx, requestingPublicKeyID); err != nil {
 					errWithCode := gtserror.NewErrorInternalError(fmt.Errorf("error marking account with public key %s as gone: %s", requestingPublicKeyID, err))
-					log.Debug(errWithCode)
+					log.Debug(ctx, errWithCode)
 					return nil, errWithCode
 				}
 				errWithCode := gtserror.NewErrorGone(fmt.Errorf("account with public key %s is gone", requestingPublicKeyID))
-				log.Debug(errWithCode)
+				log.Debug(ctx, errWithCode)
 				return nil, errWithCode
 			}
 
 			errWithCode := gtserror.NewErrorUnauthorized(fmt.Errorf("error dereferencing public key %s: %s", requestingPublicKeyID, err))
-			log.Debug(errWithCode)
+			log.Debug(ctx, errWithCode)
 			return nil, errWithCode
 		}
 
@@ -248,7 +248,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 		requestingPublicKey, err := getPublicKeyFromResponse(ctx, b, requestingPublicKeyID)
 		if err != nil {
 			errWithCode := gtserror.NewErrorUnauthorized(fmt.Errorf("error parsing public key %s: %s", requestingPublicKeyID, err))
-			log.Debug(errWithCode)
+			log.Debug(ctx, errWithCode)
 			return nil, errWithCode
 		}
 
@@ -256,7 +256,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 		pkPemProp := requestingPublicKey.GetW3IDSecurityV1PublicKeyPem()
 		if pkPemProp == nil || !pkPemProp.IsXMLSchemaString() {
 			errWithCode := gtserror.NewErrorUnauthorized(errors.New("publicKeyPem property is not provided or it is not embedded as a value"))
-			log.Debug(errWithCode)
+			log.Debug(ctx, errWithCode)
 			return nil, errWithCode
 		}
 
@@ -265,14 +265,14 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 		block, _ := pem.Decode([]byte(pubKeyPem))
 		if block == nil || block.Type != "PUBLIC KEY" {
 			errWithCode := gtserror.NewErrorUnauthorized(errors.New("could not decode publicKeyPem to PUBLIC KEY pem block type"))
-			log.Debug(errWithCode)
+			log.Debug(ctx, errWithCode)
 			return nil, errWithCode
 		}
 
 		publicKey, err = x509.ParsePKIXPublicKey(block.Bytes)
 		if err != nil {
 			errWithCode := gtserror.NewErrorUnauthorized(fmt.Errorf("could not parse public key %s from block bytes: %s", requestingPublicKeyID, err))
-			log.Debug(errWithCode)
+			log.Debug(ctx, errWithCode)
 			return nil, errWithCode
 		}
 
@@ -280,7 +280,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 		pkOwnerProp := requestingPublicKey.GetW3IDSecurityV1Owner()
 		if pkOwnerProp == nil || !pkOwnerProp.IsIRI() {
 			errWithCode := gtserror.NewErrorUnauthorized(errors.New("publicKeyOwner property is not provided or it is not embedded as a value"))
-			log.Debug(errWithCode)
+			log.Debug(ctx, errWithCode)
 			return nil, errWithCode
 		}
 		pkOwnerURI = pkOwnerProp.GetIRI()
@@ -289,7 +289,7 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 	// after all that, public key should be defined
 	if publicKey == nil {
 		errWithCode := gtserror.NewErrorInternalError(errors.New("returned public key was empty"))
-		log.Debug(errWithCode)
+		log.Debug(ctx, errWithCode)
 		return nil, errWithCode
 	}
 
@@ -301,16 +301,16 @@ func (f *federator) AuthenticateFederatedRequest(ctx context.Context, requestedU
 	}
 
 	for _, algo := range algos {
-		log.Tracef("trying algo: %s", algo)
+		log.Tracef(ctx, "trying algo: %s", algo)
 		err := verifier.Verify(publicKey, algo)
 		if err == nil {
-			log.Tracef("authentication for %s PASSED with algorithm %s", pkOwnerURI, algo)
+			log.Tracef(ctx, "authentication for %s PASSED with algorithm %s", pkOwnerURI, algo)
 			return pkOwnerURI, nil
 		}
-		log.Tracef("authentication for %s NOT PASSED with algorithm %s: %s", pkOwnerURI, algo, err)
+		log.Tracef(ctx, "authentication for %s NOT PASSED with algorithm %s: %s", pkOwnerURI, algo, err)
 	}
 
 	errWithCode := gtserror.NewErrorUnauthorized(fmt.Errorf("authentication not passed for public key owner %s; signature value was '%s'", pkOwnerURI, signature))
-	log.Debug(errWithCode)
+	log.Debug(ctx, errWithCode)
 	return nil, errWithCode
 }
diff --git a/internal/federation/dereferencing/account.go b/internal/federation/dereferencing/account.go
index ed514e493..93e0e3549 100644
--- a/internal/federation/dereferencing/account.go
+++ b/internal/federation/dereferencing/account.go
@@ -77,7 +77,7 @@ func (d *deref) GetAccountByURI(ctx context.Context, requestUser string, uri *ur
 	// Try to update existing account model
 	enriched, err := d.enrichAccount(ctx, requestUser, uri, account, false, block)
 	if err != nil {
-		log.Errorf("error enriching remote account: %v", err)
+		log.Errorf(ctx, "error enriching remote account: %v", err)
 		return account, nil // fall back to returning existing
 	}
 
@@ -114,7 +114,7 @@ func (d *deref) GetAccountByUsernameDomain(ctx context.Context, requestUser stri
 	// Try to update existing account model
 	enriched, err := d.enrichAccount(ctx, requestUser, nil, account, false, block)
 	if err != nil {
-		log.Errorf("GetAccountByUsernameDomain: error enriching account from remote: %v", err)
+		log.Errorf(ctx, "error enriching account from remote: %v", err)
 		return account, nil // fall back to returning unchanged existing account model
 	}
 
@@ -250,7 +250,7 @@ func (d *deref) enrichAccount(ctx context.Context, requestUser string, uri *url.
 				latestAcc.ID,
 			)
 			if err != nil {
-				log.Errorf("error fetching remote avatar for account %s: %v", uri, err)
+				log.Errorf(ctx, "error fetching remote avatar for account %s: %v", uri, err)
 
 				// Keep old avatar for now, we'll try again in $interval.
 				latestAcc.AvatarMediaAttachmentID = account.AvatarMediaAttachmentID
@@ -271,7 +271,7 @@ func (d *deref) enrichAccount(ctx context.Context, requestUser string, uri *url.
 				latestAcc.ID,
 			)
 			if err != nil {
-				log.Errorf("error fetching remote header for account %s: %v", uri, err)
+				log.Errorf(ctx, "error fetching remote header for account %s: %v", uri, err)
 
 				// Keep old header for now, we'll try again in $interval.
 				latestAcc.HeaderMediaAttachmentID = account.HeaderMediaAttachmentID
@@ -283,7 +283,7 @@ func (d *deref) enrichAccount(ctx context.Context, requestUser string, uri *url.
 	// Fetch the latest remote account emoji IDs used in account display name/bio.
 	_, err = d.fetchRemoteAccountEmojis(ctx, latestAcc, requestUser)
 	if err != nil {
-		log.Errorf("error fetching remote emojis for account %s: %v", uri, err)
+		log.Errorf(ctx, "error fetching remote emojis for account %s: %v", uri, err)
 	}
 
 	if account.CreatedAt.IsZero() {
diff --git a/internal/federation/dereferencing/emoji.go b/internal/federation/dereferencing/emoji.go
index 7d8526c73..15d341383 100644
--- a/internal/federation/dereferencing/emoji.go
+++ b/internal/federation/dereferencing/emoji.go
@@ -111,7 +111,7 @@ func (d *deref) populateEmojis(ctx context.Context, rawEmojis []*gtsmodel.Emoji,
 			// have to get it from the database again
 			gotEmoji = e
 		} else if gotEmoji, err = d.db.GetEmojiByShortcodeDomain(ctx, e.Shortcode, e.Domain); err != nil && err != db.ErrNoEntries {
-			log.Errorf("populateEmojis: error checking database for emoji %s: %s", shortcodeDomain, err)
+			log.Errorf(ctx, "error checking database for emoji %s: %s", shortcodeDomain, err)
 			continue
 		}
 
@@ -120,24 +120,24 @@ func (d *deref) populateEmojis(ctx context.Context, rawEmojis []*gtsmodel.Emoji,
 		if gotEmoji != nil {
 			// we had the emoji already, but refresh it if necessary
 			if e.UpdatedAt.Unix() > gotEmoji.ImageUpdatedAt.Unix() {
-				log.Tracef("populateEmojis: emoji %s was updated since we last saw it, will refresh", shortcodeDomain)
+				log.Tracef(ctx, "emoji %s was updated since we last saw it, will refresh", shortcodeDomain)
 				refresh = true
 			}
 
 			if !refresh && (e.URI != gotEmoji.URI) {
-				log.Tracef("populateEmojis: emoji %s changed URI since we last saw it, will refresh", shortcodeDomain)
+				log.Tracef(ctx, "emoji %s changed URI since we last saw it, will refresh", shortcodeDomain)
 				refresh = true
 			}
 
 			if !refresh && (e.ImageRemoteURL != gotEmoji.ImageRemoteURL) {
-				log.Tracef("populateEmojis: emoji %s changed image URL since we last saw it, will refresh", shortcodeDomain)
+				log.Tracef(ctx, "emoji %s changed image URL since we last saw it, will refresh", shortcodeDomain)
 				refresh = true
 			}
 
 			if !refresh {
-				log.Tracef("populateEmojis: emoji %s is up to date, will not refresh", shortcodeDomain)
+				log.Tracef(ctx, "emoji %s is up to date, will not refresh", shortcodeDomain)
 			} else {
-				log.Tracef("populateEmojis: refreshing emoji %s", shortcodeDomain)
+				log.Tracef(ctx, "refreshing emoji %s", shortcodeDomain)
 				emojiID := gotEmoji.ID // use existing ID
 				processingEmoji, err := d.GetRemoteEmoji(ctx, requestingUsername, e.ImageRemoteURL, e.Shortcode, e.Domain, emojiID, e.URI, &media.AdditionalEmojiInfo{
 					Domain:               &e.Domain,
@@ -147,12 +147,12 @@ func (d *deref) populateEmojis(ctx context.Context, rawEmojis []*gtsmodel.Emoji,
 					VisibleInPicker:      gotEmoji.VisibleInPicker,
 				}, refresh)
 				if err != nil {
-					log.Errorf("populateEmojis: couldn't refresh remote emoji %s: %s", shortcodeDomain, err)
+					log.Errorf(ctx, "couldn't refresh remote emoji %s: %s", shortcodeDomain, err)
 					continue
 				}
 
 				if gotEmoji, err = processingEmoji.LoadEmoji(ctx); err != nil {
-					log.Errorf("populateEmojis: couldn't load refreshed remote emoji %s: %s", shortcodeDomain, err)
+					log.Errorf(ctx, "couldn't load refreshed remote emoji %s: %s", shortcodeDomain, err)
 					continue
 				}
 			}
@@ -160,7 +160,7 @@ func (d *deref) populateEmojis(ctx context.Context, rawEmojis []*gtsmodel.Emoji,
 			// it's new! go get it!
 			newEmojiID, err := id.NewRandomULID()
 			if err != nil {
-				log.Errorf("populateEmojis: error generating id for remote emoji %s: %s", shortcodeDomain, err)
+				log.Errorf(ctx, "error generating id for remote emoji %s: %s", shortcodeDomain, err)
 				continue
 			}
 
@@ -172,12 +172,12 @@ func (d *deref) populateEmojis(ctx context.Context, rawEmojis []*gtsmodel.Emoji,
 				VisibleInPicker:      e.VisibleInPicker,
 			}, refresh)
 			if err != nil {
-				log.Errorf("populateEmojis: couldn't get remote emoji %s: %s", shortcodeDomain, err)
+				log.Errorf(ctx, "couldn't get remote emoji %s: %s", shortcodeDomain, err)
 				continue
 			}
 
 			if gotEmoji, err = processingEmoji.LoadEmoji(ctx); err != nil {
-				log.Errorf("populateEmojis: couldn't load remote emoji %s: %s", shortcodeDomain, err)
+				log.Errorf(ctx, "couldn't load remote emoji %s: %s", shortcodeDomain, err)
 				continue
 			}
 		}
diff --git a/internal/federation/dereferencing/status.go b/internal/federation/dereferencing/status.go
index da4639c5d..56545c5e0 100644
--- a/internal/federation/dereferencing/status.go
+++ b/internal/federation/dereferencing/status.go
@@ -318,20 +318,20 @@ func (d *deref) populateStatusMentions(ctx context.Context, status *gtsmodel.Sta
 	for _, m := range status.Mentions {
 		if m.ID != "" {
 			// we've already populated this mention, since it has an ID
-			log.Debug("populateStatusMentions: mention already populated")
+			log.Debug(ctx, "mention already populated")
 			mentionIDs = append(mentionIDs, m.ID)
 			newMentions = append(newMentions, m)
 			continue
 		}
 
 		if m.TargetAccountURI == "" {
-			log.Debug("populateStatusMentions: target URI not set on mention")
+			log.Debug(ctx, "target URI not set on mention")
 			continue
 		}
 
 		targetAccountURI, err := url.Parse(m.TargetAccountURI)
 		if err != nil {
-			log.Debugf("populateStatusMentions: error parsing mentioned account uri %s: %s", m.TargetAccountURI, err)
+			log.Debugf(ctx, "error parsing mentioned account uri %s: %s", m.TargetAccountURI, err)
 			continue
 		}
 
@@ -342,7 +342,7 @@ func (d *deref) populateStatusMentions(ctx context.Context, status *gtsmodel.Sta
 		if a, err := d.db.GetAccountByURI(ctx, targetAccountURI.String()); err != nil {
 			errs = append(errs, err.Error())
 		} else {
-			log.Debugf("populateStatusMentions: got target account %s with id %s through GetAccountByURI", targetAccountURI, a.ID)
+			log.Debugf(ctx, "got target account %s with id %s through GetAccountByURI", targetAccountURI, a.ID)
 			targetAccount = a
 		}
 
@@ -352,13 +352,13 @@ func (d *deref) populateStatusMentions(ctx context.Context, status *gtsmodel.Sta
 			if a, err := d.GetAccountByURI(ctx, requestingUsername, targetAccountURI, false); err != nil {
 				errs = append(errs, err.Error())
 			} else {
-				log.Debugf("populateStatusMentions: got target account %s with id %s through GetRemoteAccount", targetAccountURI, a.ID)
+				log.Debugf(ctx, "got target account %s with id %s through GetRemoteAccount", targetAccountURI, a.ID)
 				targetAccount = a
 			}
 		}
 
 		if targetAccount == nil {
-			log.Debugf("populateStatusMentions: couldn't get target account %s: %s", m.TargetAccountURI, strings.Join(errs, " : "))
+			log.Debugf(ctx, "couldn't get target account %s: %s", m.TargetAccountURI, strings.Join(errs, " : "))
 			continue
 		}
 
@@ -419,13 +419,13 @@ func (d *deref) populateStatusAttachments(ctx context.Context, status *gtsmodel.
 			Blurhash:    &a.Blurhash,
 		})
 		if err != nil {
-			log.Errorf("populateStatusAttachments: couldn't get remote media %s: %s", a.RemoteURL, err)
+			log.Errorf(ctx, "couldn't get remote media %s: %s", a.RemoteURL, err)
 			continue
 		}
 
 		attachment, err := processingMedia.LoadAttachment(ctx)
 		if err != nil {
-			log.Errorf("populateStatusAttachments: couldn't load remote attachment %s: %s", a.RemoteURL, err)
+			log.Errorf(ctx, "couldn't load remote attachment %s: %s", a.RemoteURL, err)
 			continue
 		}
 
diff --git a/internal/federation/dereferencing/thread.go b/internal/federation/dereferencing/thread.go
index e89b2da7a..517d44e7a 100644
--- a/internal/federation/dereferencing/thread.go
+++ b/internal/federation/dereferencing/thread.go
@@ -45,10 +45,11 @@ const maxIter = 1000
 //
 // This does not return error, as for robustness we do not want to error-out on a status because another further up / down has issues.
 func (d *deref) DereferenceThread(ctx context.Context, username string, statusIRI *url.URL, status *gtsmodel.Status, statusable ap.Statusable) {
-	l := log.WithFields(kv.Fields{
-		{"username", username},
-		{"statusIRI", status.URI},
-	}...)
+	l := log.WithContext(ctx).
+		WithFields(kv.Fields{
+			{"username", username},
+			{"statusIRI", status.URI},
+		}...)
 
 	// Log function start
 	l.Trace("beginning")
@@ -72,10 +73,11 @@ func (d *deref) dereferenceStatusAncestors(ctx context.Context, username string,
 	ogIRI := status.URI
 
 	// Start log entry with fields
-	l := log.WithFields(kv.Fields{
-		{"username", username},
-		{"statusIRI", ogIRI},
-	}...)
+	l := log.WithContext(ctx).
+		WithFields(kv.Fields{
+			{"username", username},
+			{"statusIRI", ogIRI},
+		}...)
 
 	// Log function start
 	l.Trace("beginning")
@@ -132,10 +134,11 @@ func (d *deref) dereferenceStatusDescendants(ctx context.Context, username strin
 	ogIRI := statusIRI
 
 	// Start log entry with fields
-	l := log.WithFields(kv.Fields{
-		{"username", username},
-		{"statusIRI", ogIRI},
-	}...)
+	l := log.WithContext(ctx).
+		WithFields(kv.Fields{
+			{"username", username},
+			{"statusIRI", ogIRI},
+		}...)
 
 	// Log function start
 	l.Trace("beginning")
diff --git a/internal/federation/federatingactor.go b/internal/federation/federatingactor.go
index 029149a9b..71e6e8fb6 100644
--- a/internal/federation/federatingactor.go
+++ b/internal/federation/federatingactor.go
@@ -56,7 +56,7 @@ func newFederatingActor(c pub.CommonBehavior, s2s pub.FederatingProtocol, db pub
 // method will guaranteed work for non-custom Actors. For custom actors,
 // care should be used to not call this method if only C2S is supported.
 func (f *federatingActor) Send(c context.Context, outbox *url.URL, t vocab.Type) (pub.Activity, error) {
-	log.Infof("federating actor: send activity %s via outbox %s", t.GetTypeName(), outbox)
+	log.Infof(c, "send activity %s via outbox %s", t.GetTypeName(), outbox)
 	return f.actor.Send(c, outbox, t)
 }
 
diff --git a/internal/federation/federatingdb/create.go b/internal/federation/federatingdb/create.go
index 62784e68d..bf3e7f75d 100644
--- a/internal/federation/federatingdb/create.go
+++ b/internal/federation/federatingdb/create.go
@@ -53,8 +53,9 @@ func (f *federatingDB) Create(ctx context.Context, asType vocab.Type) error {
 		if err != nil {
 			return err
 		}
-		l := log.WithField("create", i)
-		l.Debug("entering Create")
+		l := log.WithContext(ctx).
+			WithField("create", i)
+		l.Trace("entering Create")
 	}
 
 	receivingAccount, requestingAccount := extractFromCtx(ctx)
@@ -164,10 +165,11 @@ func (f *federatingDB) activityCreate(ctx context.Context, asType vocab.Type, re
 
 // createNote handles a Create activity with a Note type.
 func (f *federatingDB) createNote(ctx context.Context, note vocab.ActivityStreamsNote, receivingAccount *gtsmodel.Account, requestingAccount *gtsmodel.Account) error {
-	l := log.WithFields(kv.Fields{
-		{"receivingAccount", receivingAccount.URI},
-		{"requestingAccount", requestingAccount.URI},
-	}...)
+	l := log.WithContext(ctx).
+		WithFields(kv.Fields{
+			{"receivingAccount", receivingAccount.URI},
+			{"requestingAccount", requestingAccount.URI},
+		}...)
 
 	// Check if we have a forward.
 	// In other words, was the note posted to our inbox by at least one actor who actually created the note, or are they just forwarding it?
diff --git a/internal/federation/federatingdb/delete.go b/internal/federation/federatingdb/delete.go
index 22434f63e..a1890b56b 100644
--- a/internal/federation/federatingdb/delete.go
+++ b/internal/federation/federatingdb/delete.go
@@ -35,9 +35,10 @@ import (
 //
 // The library makes this call only after acquiring a lock first.
 func (f *federatingDB) Delete(ctx context.Context, id *url.URL) error {
-	l := log.WithFields(kv.Fields{
-		{"id", id},
-	}...)
+	l := log.WithContext(ctx).
+		WithFields(kv.Fields{
+			{"id", id},
+		}...)
 	l.Debug("entering Delete")
 
 	receivingAccount, requestingAccount := extractFromCtx(ctx)
diff --git a/internal/federation/federatingdb/exists.go b/internal/federation/federatingdb/exists.go
index 51e7399aa..a235770c6 100644
--- a/internal/federation/federatingdb/exists.go
+++ b/internal/federation/federatingdb/exists.go
@@ -32,10 +32,11 @@ import (
 // The library makes this call only after acquiring a lock first.
 //
 // Implementation note: this just straight up isn't implemented, and doesn't *really* need to be either.
-func (f *federatingDB) Exists(c context.Context, id *url.URL) (exists bool, err error) {
-	l := log.WithFields(kv.Fields{
-		{"id", id},
-	}...)
+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/followers.go b/internal/federation/federatingdb/followers.go
index 9a80d5f0b..c47a2b625 100644
--- a/internal/federation/federatingdb/followers.go
+++ b/internal/federation/federatingdb/followers.go
@@ -18,9 +18,10 @@ import (
 //
 // The library makes this call only after acquiring a lock first.
 func (f *federatingDB) Followers(ctx context.Context, actorIRI *url.URL) (followers vocab.ActivityStreamsCollection, err error) {
-	l := log.WithFields(kv.Fields{
-		{"id", actorIRI},
-	}...)
+	l := log.WithContext(ctx).
+		WithFields(kv.Fields{
+			{"id", actorIRI},
+		}...)
 	l.Debug("entering Followers")
 
 	acct, err := f.getAccountForIRI(ctx, actorIRI)
diff --git a/internal/federation/federatingdb/following.go b/internal/federation/federatingdb/following.go
index 2290b72f4..f4f07bb25 100644
--- a/internal/federation/federatingdb/following.go
+++ b/internal/federation/federatingdb/following.go
@@ -36,9 +36,10 @@ import (
 //
 // The library makes this call only after acquiring a lock first.
 func (f *federatingDB) Following(ctx context.Context, actorIRI *url.URL) (following vocab.ActivityStreamsCollection, err error) {
-	l := log.WithFields(kv.Fields{
-		{"id", actorIRI},
-	}...)
+	l := log.WithContext(ctx).
+		WithFields(kv.Fields{
+			{"id", actorIRI},
+		}...)
 	l.Debug("entering Following")
 
 	acct, err := f.getAccountForIRI(ctx, actorIRI)
diff --git a/internal/federation/federatingdb/get.go b/internal/federation/federatingdb/get.go
index a55cb0280..92a79d70f 100644
--- a/internal/federation/federatingdb/get.go
+++ b/internal/federation/federatingdb/get.go
@@ -33,7 +33,8 @@ 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.WithFields(kv.Fields{{"id", id}}...)
+	l := log.WithContext(ctx).
+		WithFields(kv.Fields{{"id", id}}...)
 	l.Debug("entering Get")
 
 	switch {
diff --git a/internal/federation/federatingdb/owns.go b/internal/federation/federatingdb/owns.go
index 070036df7..def0fa518 100644
--- a/internal/federation/federatingdb/owns.go
+++ b/internal/federation/federatingdb/owns.go
@@ -35,9 +35,10 @@ 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.WithFields(kv.Fields{
-		{"id", id},
-	}...)
+	l := log.WithContext(ctx).
+		WithFields(kv.Fields{
+			{"id", id},
+		}...)
 	l.Debug("entering Owns")
 
 	// if the id host isn't this instance host, we don't own this IRI
diff --git a/internal/federation/federatingdb/util.go b/internal/federation/federatingdb/util.go
index b5a9feab1..1eb27dc03 100644
--- a/internal/federation/federatingdb/util.go
+++ b/internal/federation/federatingdb/util.go
@@ -304,7 +304,7 @@ func extractFromCtx(ctx context.Context) (receivingAccount, requestingAccount *g
 		var ok bool
 		receivingAccount, ok = receivingAccountI.(*gtsmodel.Account)
 		if !ok {
-			log.Panicf("extractFromCtx: context entry with key %s could not be asserted to *gtsmodel.Account", ap.ContextReceivingAccount)
+			log.Panicf(ctx, "context entry with key %s could not be asserted to *gtsmodel.Account", ap.ContextReceivingAccount)
 		}
 	}
 
@@ -313,7 +313,7 @@ func extractFromCtx(ctx context.Context) (receivingAccount, requestingAccount *g
 		var ok bool
 		requestingAccount, ok = requestingAcctI.(*gtsmodel.Account)
 		if !ok {
-			log.Panicf("extractFromCtx: context entry with key %s could not be asserted to *gtsmodel.Account", ap.ContextRequestingAccount)
+			log.Panicf(ctx, "context entry with key %s could not be asserted to *gtsmodel.Account", ap.ContextRequestingAccount)
 		}
 	}
 
diff --git a/internal/federation/federatingprotocol.go b/internal/federation/federatingprotocol.go
index d75570dd6..e60f278c7 100644
--- a/internal/federation/federatingprotocol.go
+++ b/internal/federation/federatingprotocol.go
@@ -138,10 +138,11 @@ func (f *federator) PostInboxRequestBodyHook(ctx context.Context, r *http.Reques
 // authenticated must be true and error nil. The request will continue
 // to be processed.
 func (f *federator) AuthenticatePostInbox(ctx context.Context, w http.ResponseWriter, r *http.Request) (context.Context, bool, error) {
-	l := log.WithFields(kv.Fields{
-		{"useragent", r.UserAgent()},
-		{"url", r.URL.String()},
-	}...)
+	l := log.WithContext(ctx).
+		WithFields(kv.Fields{
+			{"useragent", r.UserAgent()},
+			{"url", r.URL.String()},
+		}...)
 	l.Trace("received request to authenticate")
 
 	if !uris.IsInboxPath(r.URL) {
@@ -242,7 +243,7 @@ func (f *federator) AuthenticatePostInbox(ctx context.Context, w http.ResponseWr
 // blocked must be false and error nil. The request will continue
 // to be processed.
 func (f *federator) Blocked(ctx context.Context, actorIRIs []*url.URL) (bool, error) {
-	log.Debugf("entering BLOCKED function with IRI list: %+v", actorIRIs)
+	log.Tracef(ctx, "entering BLOCKED function with IRI list: %+v", actorIRIs)
 
 	// check domain blocks first for the given actor IRIs
 	blocked, err := f.db.AreURIsBlocked(ctx, actorIRIs)
@@ -257,7 +258,7 @@ func (f *federator) Blocked(ctx context.Context, actorIRIs []*url.URL) (bool, er
 	otherInvolvedIRIsI := ctx.Value(ap.ContextOtherInvolvedIRIs)
 	otherInvolvedIRIs, ok := otherInvolvedIRIsI.([]*url.URL)
 	if !ok {
-		log.Error("other involved IRIs not set on request context")
+		log.Error(ctx, "other involved IRIs not set on request context")
 		return false, errors.New("other involved IRIs not set on request context, so couldn't determine blocks")
 	}
 	blocked, err = f.db.AreURIsBlocked(ctx, otherInvolvedIRIs)
@@ -272,13 +273,13 @@ func (f *federator) Blocked(ctx context.Context, actorIRIs []*url.URL) (bool, er
 	receivingAccountI := ctx.Value(ap.ContextReceivingAccount)
 	receivingAccount, ok := receivingAccountI.(*gtsmodel.Account)
 	if !ok {
-		log.Error("receiving account not set on request context")
+		log.Error(ctx, "receiving account not set on request context")
 		return false, errors.New("receiving account not set on request context, so couldn't determine blocks")
 	}
 	requestingAccountI := ctx.Value(ap.ContextRequestingAccount)
 	requestingAccount, ok := requestingAccountI.(*gtsmodel.Account)
 	if !ok {
-		log.Error("requesting account not set on request context")
+		log.Error(ctx, "requesting account not set on request context")
 		return false, errors.New("requesting account not set on request context, so couldn't determine blocks")
 	}
 	// the receiver shouldn't block the sender
@@ -384,10 +385,11 @@ func (f *federator) FederatingCallbacks(ctx context.Context) (wrapped pub.Federa
 // type and extension, so the unhandled ones are passed to
 // DefaultCallback.
 func (f *federator) DefaultCallback(ctx context.Context, activity pub.Activity) error {
-	l := log.WithFields(kv.Fields{
-		{"aptype", activity.GetTypeName()},
-	}...)
-	l.Debugf("received unhandle-able activity type so ignoring it")
+	l := log.WithContext(ctx).
+		WithFields(kv.Fields{
+			{"aptype", activity.GetTypeName()},
+		}...)
+	l.Debug("received unhandle-able activity type so ignoring it")
 	return nil
 }