From: Ward Vandewege <ward@curii.com>
Date: Fri, 25 Mar 2022 11:58:48 +0000 (-0400)
Subject: 18896: controller logs the UUIDs of the tokens used in each request.
X-Git-Tag: 2.4.0~21^2~3
X-Git-Url: https://git.arvados.org/arvados.git/commitdiff_plain/15661585c028bedf752603b37cab07746209c3cc

18896: controller logs the UUIDs of the tokens used in each request.

Arvados-DCO-1.1-Signed-off-by: Ward Vandewege <ward@curii.com>
---

diff --git a/lib/controller/router/router.go b/lib/controller/router/router.go
index 2cfcc4fc28..e42d9a555b 100644
--- a/lib/controller/router/router.go
+++ b/lib/controller/router/router.go
@@ -588,6 +588,19 @@ func (rtr *router) addRoute(endpoint arvados.APIEndpoint, defaultOpts func() int
 			"apiOptsType": fmt.Sprintf("%T", opts),
 			"apiOpts":     opts,
 		}).Debug("exec")
+		// Extract the token UUIDs (or a placeholder for v1 tokens)
+		var tokenUUIDs []string
+		for _, t := range creds.Tokens {
+			if strings.HasPrefix(t, "v2/") {
+				tokenParts := strings.Split(t, "/")
+				if len(tokenParts) >= 3 {
+					tokenUUIDs = append(tokenUUIDs, tokenParts[1])
+				}
+			} else {
+				tokenUUIDs = append(tokenUUIDs, "v1 token ending in "+t[len(t)-5:])
+			}
+		}
+		httpserver.SetResponseLogFields(req.Context(), logrus.Fields{"tokenUUIDs": tokenUUIDs})
 		resp, err := exec(ctx, opts)
 		if err != nil {
 			logger.WithError(err).Debugf("returning error type %T", err)
diff --git a/sdk/go/httpserver/logger.go b/sdk/go/httpserver/logger.go
index 7eb7f0f03d..437429611c 100644
--- a/sdk/go/httpserver/logger.go
+++ b/sdk/go/httpserver/logger.go
@@ -21,7 +21,8 @@ type contextKey struct {
 }
 
 var (
-	requestTimeContextKey = contextKey{"requestTime"}
+	requestTimeContextKey       = contextKey{"requestTime"}
+	responseLogFieldsContextKey = contextKey{"responseLogFields"}
 )
 
 type hijacker interface {
@@ -64,6 +65,15 @@ func HandlerWithDeadline(timeout time.Duration, next http.Handler) http.Handler
 	})
 }
 
+func SetResponseLogFields(ctx context.Context, fields logrus.Fields) {
+	ctxfields := ctx.Value(&responseLogFieldsContextKey)
+	if c, ok := ctxfields.(logrus.Fields); ok {
+		for k, v := range fields {
+			c[k] = v
+		}
+	}
+}
+
 // LogRequests wraps an http.Handler, logging each request and
 // response.
 func LogRequests(h http.Handler) http.Handler {
@@ -81,6 +91,7 @@ func LogRequests(h http.Handler) http.Handler {
 		})
 		ctx := req.Context()
 		ctx = context.WithValue(ctx, &requestTimeContextKey, time.Now())
+		ctx = context.WithValue(ctx, &responseLogFieldsContextKey, logrus.Fields{})
 		ctx = ctxlog.Context(ctx, lgr)
 		req = req.WithContext(ctx)
 
@@ -124,6 +135,9 @@ func logResponse(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
 			"timeWriteBody": stats.Duration(tDone.Sub(writeTime)),
 		})
 	}
+	if responseLogFields, ok := req.Context().Value(&responseLogFieldsContextKey).(logrus.Fields); ok {
+		lgr = lgr.WithFields(responseLogFields)
+	}
 	respCode := w.WroteStatus()
 	if respCode == 0 {
 		respCode = http.StatusOK