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

internal/middleware/requestid.go

@@ -0,0 +1,111 @@
+/*
+   GoToSocial
+   Copyright (C) 2021-2023 GoToSocial Authors admin@gotosocial.org
+
+   This program is free software: you can redistribute it and/or modify
+   it under the terms of the GNU Affero General Public License as published by
+   the Free Software Foundation, either version 3 of the License, or
+   (at your option) any later version.
+
+   This program is distributed in the hope that it will be useful,
+   but WITHOUT ANY WARRANTY; without even the implied warranty of
+   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+   GNU Affero General Public License for more details.
+
+   You should have received a copy of the GNU Affero General Public License
+   along with this program.  If not, see <http://www.gnu.org/licenses/>.
+*/
+
+package middleware
+
+import (
+	"bufio"
+	"context"
+	"crypto/rand"
+	"encoding/base32"
+	"encoding/binary"
+	"io"
+	"sync"
+	"time"
+
+	"codeberg.org/gruf/go-kv"
+	"github.com/gin-gonic/gin"
+	"github.com/superseriousbusiness/gotosocial/internal/log"
+)
+
+type ctxType string
+
+var (
+	// ridCtxKey is the key underwhich we store request IDs in a context.
+	ridCtxKey ctxType = "id"
+
+	// crand provides buffered reads of random input.
+	crand = bufio.NewReader(rand.Reader)
+	mrand sync.Mutex
+
+	// base32enc is a base 32 encoding based on a human-readable character set (no padding).
+	base32enc = base32.NewEncoding("0123456789abcdefghjkmnpqrstvwxyz").WithPadding(-1)
+)
+
+// generateID generates a new ID string.
+func generateID() string {
+	// 0:8  = timestamp
+	// 8:12 = entropy
+	//
+	// inspired by ULID.
+	b := make([]byte, 12)
+
+	// Get current time in milliseconds.
+	ms := uint64(time.Now().UnixMilli())
+
+	// Store binary time data in byte buffer.
+	binary.LittleEndian.PutUint64(b[0:8], ms)
+
+	mrand.Lock()
+	// Read random bits into buffer end.
+	_, _ = io.ReadFull(crand, b[8:12])
+	mrand.Unlock()
+
+	// Encode the binary time+entropy ID.
+	return base32enc.EncodeToString(b)
+}
+
+// RequestID fetches the stored request ID from context.
+func RequestID(ctx context.Context) string {
+	id, _ := ctx.Value(ridCtxKey).(string)
+	return id
+}
+
+// AddRequestID returns a gin middleware which adds a unique ID to each request (both response header and context).
+func AddRequestID(header string) gin.HandlerFunc {
+	log.Hook(func(ctx context.Context, kvs []kv.Field) []kv.Field {
+		if id, _ := ctx.Value(ridCtxKey).(string); id != "" {
+			// Add stored request ID to log entry fields.
+			return append(kvs, kv.Field{K: "requestID", V: id})
+		}
+		return kvs
+	})
+
+	return func(c *gin.Context) {
+		// Look for existing ID.
+		id := c.GetHeader(header)
+
+		if id == "" {
+			// Generate new ID.
+			//
+			// 0:8  = timestamp
+			// 8:12 = entropy
+			id = generateID()
+			// Set the request ID in the req header in case we pass the request along
+			// to another service
+			c.Request.Header.Set(header, id)
+		}
+
+		// Store request ID in new request ctx and set new gin request obj.
+		ctx := context.WithValue(c.Request.Context(), ridCtxKey, id)
+		c.Request = c.Request.WithContext(ctx)
+
+		// Set the request ID in the rsp header.
+		c.Writer.Header().Set(header, id)
+	}
+}

internal/middleware/session.go

@@ -41,7 +41,7 @@ func SessionOptions() sessions.Options {
 	case "strict":
 		samesite = http.SameSiteStrictMode
 	default:
-		log.Warnf("%s set to %s which is not recognized, defaulting to 'lax'", config.AdvancedCookiesSamesiteFlag(), config.GetAdvancedCookiesSamesite())
+		log.Warnf(nil, "%s set to %s which is not recognized, defaulting to 'lax'", config.AdvancedCookiesSamesiteFlag(), config.GetAdvancedCookiesSamesite())
 		samesite = http.SameSiteLaxMode
 	}
 

internal/middleware/signaturecheck.go

@@ -36,13 +36,16 @@ var (
 // In case of an error, the request will be aborted with http code 500 internal server error.
 func SignatureCheck(isURIBlocked func(context.Context, *url.URL) (bool, db.Error)) func(*gin.Context) {
 	return func(c *gin.Context) {
+		// Acquire ctx from gin request.
+		ctx := c.Request.Context()
+
 		// create the verifier from the request, this will error if the request wasn't signed
 		verifier, err := httpsig.NewVerifier(c.Request)
 		if err != nil {
 			// Something went wrong, so we need to return regardless, but only actually
 			// *abort* the request with 401 if a signature was present but malformed
 			if err.Error() != noSignatureError {
-				log.Debugf("http signature was present but invalid: %s", err)
+				log.Debugf(ctx, "http signature was present but invalid: %s", err)
 				c.AbortWithStatus(http.StatusUnauthorized)
 			}
 			return
@@ -54,13 +57,13 @@ func SignatureCheck(isURIBlocked func(context.Context, *url.URL) (bool, db.Error
 		requestingPublicKeyIDString := verifier.KeyId()
 		requestingPublicKeyID, err := url.Parse(requestingPublicKeyIDString)
 		if err != nil {
-			log.Debugf("http signature requesting public key id %s could not be parsed as a url: %s", requestingPublicKeyIDString, err)
+			log.Debugf(ctx, "http signature requesting public key id %s could not be parsed as a url: %s", requestingPublicKeyIDString, err)
 			c.AbortWithStatus(http.StatusUnauthorized)
 			return
 		} else if requestingPublicKeyID == nil {
 			// Key can sometimes be nil, according to url parse function:
 			// 'Trying to parse a hostname and path without a scheme is invalid but may not necessarily return an error, due to parsing ambiguities'
-			log.Debugf("http signature requesting public key id %s was nil after parsing as a url", requestingPublicKeyIDString)
+			log.Debugf(ctx, "http signature requesting public key id %s was nil after parsing as a url", requestingPublicKeyIDString)
 			c.AbortWithStatus(http.StatusUnauthorized)
 			return
 		}
@@ -68,11 +71,11 @@ func SignatureCheck(isURIBlocked func(context.Context, *url.URL) (bool, db.Error
 		// we managed to parse the url!
 		// if the domain is blocked we want to bail as early as possible
 		if blocked, err := isURIBlocked(c.Request.Context(), requestingPublicKeyID); err != nil {
-			log.Errorf("could not tell if domain %s was blocked or not: %s", requestingPublicKeyID.Host, err)
+			log.Errorf(ctx, "could not tell if domain %s was blocked or not: %s", requestingPublicKeyID.Host, err)
 			c.AbortWithStatus(http.StatusInternalServerError)
 			return
 		} else if blocked {
-			log.Infof("domain %s is blocked", requestingPublicKeyID.Host)
+			log.Infof(ctx, "domain %s is blocked", requestingPublicKeyID.Host)
 			c.AbortWithStatus(http.StatusForbidden)
 			return
 		}

internal/middleware/tokencheck.go

@@ -52,6 +52,7 @@ import (
 // Bearer token set (eg., for public instance information and so on).
 func TokenCheck(dbConn db.DB, validateBearerToken func(r *http.Request) (oauth2.TokenInfo, error)) func(*gin.Context) {
 	return func(c *gin.Context) {
+		// Acquire context from gin request.
 		ctx := c.Request.Context()
 
 		if c.Request.Header.Get("Authorization") == "" {
@@ -61,38 +62,38 @@ func TokenCheck(dbConn db.DB, validateBearerToken func(r *http.Request) (oauth2.
 
 		ti, err := validateBearerToken(c.Copy().Request)
 		if err != nil {
-			log.Debugf("token was passed in Authorization header but we could not validate it: %s", err)
+			log.Debugf(ctx, "token was passed in Authorization header but we could not validate it: %s", err)
 			return
 		}
 		c.Set(oauth.SessionAuthorizedToken, ti)
 
 		// check for user-level token
 		if userID := ti.GetUserID(); userID != "" {
-			log.Tracef("authenticated user %s with bearer token, scope is %s", userID, ti.GetScope())
+			log.Tracef(ctx, "authenticated user %s with bearer token, scope is %s", userID, ti.GetScope())
 
 			// fetch user for this token
 			user, err := dbConn.GetUserByID(ctx, userID)
 			if err != nil {
 				if err != db.ErrNoEntries {
-					log.Errorf("database error looking for user with id %s: %s", userID, err)
+					log.Errorf(ctx, "database error looking for user with id %s: %s", userID, err)
 					return
 				}
-				log.Warnf("no user found for userID %s", userID)
+				log.Warnf(ctx, "no user found for userID %s", userID)
 				return
 			}
 
 			if user.ConfirmedAt.IsZero() {
-				log.Warnf("authenticated user %s has never confirmed thier email address", userID)
+				log.Warnf(ctx, "authenticated user %s has never confirmed thier email address", userID)
 				return
 			}
 
 			if !*user.Approved {
-				log.Warnf("authenticated user %s's account was never approved by an admin", userID)
+				log.Warnf(ctx, "authenticated user %s's account was never approved by an admin", userID)
 				return
 			}
 
 			if *user.Disabled {
-				log.Warnf("authenticated user %s's account was disabled'", userID)
+				log.Warnf(ctx, "authenticated user %s's account was disabled'", userID)
 				return
 			}
 
@@ -103,17 +104,17 @@ func TokenCheck(dbConn db.DB, validateBearerToken func(r *http.Request) (oauth2.
 				acct, err := dbConn.GetAccountByID(ctx, user.AccountID)
 				if err != nil {
 					if err != db.ErrNoEntries {
-						log.Errorf("database error looking for account with id %s: %s", user.AccountID, err)
+						log.Errorf(ctx, "database error looking for account with id %s: %s", user.AccountID, err)
 						return
 					}
-					log.Warnf("no account found for userID %s", userID)
+					log.Warnf(ctx, "no account found for userID %s", userID)
 					return
 				}
 				user.Account = acct
 			}
 
 			if !user.Account.SuspendedAt.IsZero() {
-				log.Warnf("authenticated user %s's account (accountId=%s) has been suspended", userID, user.AccountID)
+				log.Warnf(ctx, "authenticated user %s's account (accountId=%s) has been suspended", userID, user.AccountID)
 				return
 			}
 
@@ -122,16 +123,16 @@ func TokenCheck(dbConn db.DB, validateBearerToken func(r *http.Request) (oauth2.
 
 		// check for application token
 		if clientID := ti.GetClientID(); clientID != "" {
-			log.Tracef("authenticated client %s with bearer token, scope is %s", clientID, ti.GetScope())
+			log.Tracef(ctx, "authenticated client %s with bearer token, scope is %s", clientID, ti.GetScope())
 
 			// fetch app for this token
 			app := &gtsmodel.Application{}
 			if err := dbConn.GetWhere(ctx, []db.Where{{Key: "client_id", Value: clientID}}, app); err != nil {
 				if err != db.ErrNoEntries {
-					log.Errorf("database error looking for application with clientID %s: %s", clientID, err)
+					log.Errorf(ctx, "database error looking for application with clientID %s: %s", clientID, err)
 					return
 				}
-				log.Warnf("no app found for client %s", clientID)
+				log.Warnf(ctx, "no app found for client %s", clientID)
 				return
 			}
 			c.Set(oauth.SessionAuthorizedApplication, app)