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

1 files changed, 14 insertions, 12 deletions

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
 }