Merge branch '18941-arv-prefetch' refs #18941

Arvados-DCO-1.1-Signed-off-by: Peter Amstutz <peter.amstutz@curii.com>

diff --git a/lib/controller/handler_test.go b/lib/controller/handler_test.go
index 817cff79609dab91b7743f2869950974c8796082..5e467cb0588607d3deaa06c1d92326ed18f8f09c 100644 (file)
--- a/lib/controller/handler_test.go
+++ b/lib/controller/handler_test.go
@@ -5,9 +5,11 @@
 package controller
 
 import (
+       "bytes"
        "context"
        "crypto/tls"
        "encoding/json"
+       "io"
        "io/ioutil"
        "net/http"
        "net/http/httptest"
@@ -36,13 +38,15 @@ var _ = check.Suite(&HandlerSuite{})
 type HandlerSuite struct {
        cluster *arvados.Cluster
        handler *Handler
+       logbuf  *bytes.Buffer
        ctx     context.Context
        cancel  context.CancelFunc
 }
 
 func (s *HandlerSuite) SetUpTest(c *check.C) {
+       s.logbuf = &bytes.Buffer{}
        s.ctx, s.cancel = context.WithCancel(context.Background())
-       s.ctx = ctxlog.Context(s.ctx, ctxlog.New(os.Stderr, "json", "debug"))
+       s.ctx = ctxlog.Context(s.ctx, ctxlog.New(io.MultiWriter(os.Stderr, s.logbuf), "json", "debug"))
        s.cluster = &arvados.Cluster{
                ClusterID:  "zzzzz",
                PostgreSQL: integrationTestCluster().PostgreSQL,
@@ -317,6 +321,16 @@ func (s *HandlerSuite) TestValidateRemoteToken(c *check.C) {
        }
 }
 
+func (s *HandlerSuite) TestLogTokenUUID(c *check.C) {
+       req := httptest.NewRequest("GET", "https://0.0.0.0/arvados/v1/users/current", nil)
+       req.Header.Set("Authorization", "Bearer "+arvadostest.ActiveTokenV2)
+       req = req.WithContext(s.ctx)
+       resp := httptest.NewRecorder()
+       httpserver.LogRequests(s.handler).ServeHTTP(resp, req)
+       c.Check(resp.Code, check.Equals, http.StatusOK)
+       c.Check(s.logbuf.String(), check.Matches, `(?ms).*"tokenUUIDs":\["`+strings.Split(arvadostest.ActiveTokenV2, "/")[1]+`"\].*`)
+}
+
 func (s *HandlerSuite) TestCreateAPIToken(c *check.C) {
        req := httptest.NewRequest("GET", "/arvados/v1/users/current", nil)
        auth, err := s.handler.createAPItoken(req, arvadostest.ActiveUserUUID, nil)

diff --git a/lib/controller/router/router.go b/lib/controller/router/router.go
index 2cfcc4fc28287c8ee44166277ecaffe23d42e293..05bdb4754f0a860ac552867d42bf6e30af9eb4d6 100644 (file)
--- a/lib/controller/router/router.go
+++ b/lib/controller/router/router.go
@@ -588,6 +588,23 @@ 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 {
+                               end := t
+                               if len(t) > 5 {
+                                       end = t[len(t)-5:]
+                               }
+                               tokenUUIDs = append(tokenUUIDs, "v1 token ending in "+end)
+                       }
+               }
+               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..5a46635e9102365bbfd01c9c9c120bd8e23a7026 100644 (file)
--- a/sdk/go/httpserver/logger.go
+++ b/sdk/go/httpserver/logger.go
@@ -9,6 +9,7 @@ import (
        "context"
        "net"
        "net/http"
+       "sync"
        "time"
 
        "git.arvados.org/arvados.git/sdk/go/ctxlog"
@@ -21,7 +22,9 @@ type contextKey struct {
 }
 
 var (
-       requestTimeContextKey = contextKey{"requestTime"}
+       requestTimeContextKey       = contextKey{"requestTime"}
+       responseLogFieldsContextKey = contextKey{"responseLogFields"}
+       mutexContextKey             = contextKey{"mutex"}
 )
 
 type hijacker interface {
@@ -64,6 +67,19 @@ func HandlerWithDeadline(timeout time.Duration, next http.Handler) http.Handler
        })
 }
 
+func SetResponseLogFields(ctx context.Context, fields logrus.Fields) {
+       m, _ := ctx.Value(&mutexContextKey).(*sync.Mutex)
+       c, _ := ctx.Value(&responseLogFieldsContextKey).(logrus.Fields)
+       if m == nil || c == nil {
+               return
+       }
+       m.Lock()
+       defer m.Unlock()
+       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 +97,8 @@ 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 = context.WithValue(ctx, &mutexContextKey, &sync.Mutex{})
                ctx = ctxlog.Context(ctx, lgr)
                req = req.WithContext(ctx)
 
@@ -124,6 +142,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