[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>

4 files changed, 39 insertions, 36 deletions

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")