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 2cfcc4fc28287c8ee44166277ecaffe23d42e293..e42d9a555b5993e00e2a7ce3eff29ab174ab0b44 100644 (file)
--- 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 7eb7f0f03d57b571e314f8d87ca6714cf7d6563f..437429611cb1ee1d0a5db75be353865863985bb6 100644 (file)
--- 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