16343: Add debug logs in token checking code.

Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tom@tomclegg.ca>

diff --git a/lib/controller/federation.go b/lib/controller/federation.go
index 674183dcc1d8b9f2d96e5f9b5bded909dad23f26..c0d127284ce35a21d5618814dd2792984809f5f2 100644 (file)
--- a/lib/controller/federation.go
+++ b/lib/controller/federation.go
@@ -19,6 +19,7 @@ import (
 
        "git.arvados.org/arvados.git/sdk/go/arvados"
        "git.arvados.org/arvados.git/sdk/go/auth"
+       "git.arvados.org/arvados.git/sdk/go/ctxlog"
        "github.com/jmcvetta/randutil"
 )
 
@@ -153,6 +154,7 @@ func (h *Handler) validateAPItoken(req *http.Request, token string) (*CurrentUse
        user := CurrentUser{Authorization: arvados.APIClientAuthorization{APIToken: token}}
        db, err := h.db(req)
        if err != nil {
+               ctxlog.FromContext(req.Context()).WithError(err).Debugf("validateAPItoken(%s): database error", token)
                return nil, false, err
        }
 
@@ -166,18 +168,23 @@ func (h *Handler) validateAPItoken(req *http.Request, token string) (*CurrentUse
        var scopes string
        err = db.QueryRowContext(req.Context(), `SELECT api_client_authorizations.uuid, api_client_authorizations.scopes, users.uuid FROM api_client_authorizations JOIN users on api_client_authorizations.user_id=users.id WHERE api_token=$1 AND (expires_at IS NULL OR expires_at > current_timestamp) LIMIT 1`, token).Scan(&user.Authorization.UUID, &scopes, &user.UUID)
        if err == sql.ErrNoRows {
+               ctxlog.FromContext(req.Context()).Debugf("validateAPItoken(%s): not found in database", token)
                return nil, false, nil
        } else if err != nil {
+               ctxlog.FromContext(req.Context()).WithError(err).Debugf("validateAPItoken(%s): database error", token)
                return nil, false, err
        }
        if uuid != "" && user.Authorization.UUID != uuid {
                // secret part matches, but UUID doesn't -- somewhat surprising
+               ctxlog.FromContext(req.Context()).Debugf("validateAPItoken(%s): secret part found, but with different UUID: %s", token, user.Authorization.UUID)
                return nil, false, nil
        }
        err = json.Unmarshal([]byte(scopes), &user.Authorization.Scopes)
        if err != nil {
+               ctxlog.FromContext(req.Context()).WithError(err).Debugf("validateAPItoken(%s): error parsing scopes from db", token)
                return nil, false, err
        }
+       ctxlog.FromContext(req.Context()).Debugf("validateAPItoken(%s): ok", token)
        return &user, true, nil
 }
 

diff --git a/services/api/app/models/api_client_authorization.rb b/services/api/app/models/api_client_authorization.rb
index 77fc0a45afb32ff7ea93595a4b97ff66cd128f63..503dfc50dd78e3b30cb2ce9660d5d91fdb49223b 100644 (file)
--- a/services/api/app/models/api_client_authorization.rb
+++ b/services/api/app/models/api_client_authorization.rb
@@ -164,6 +164,9 @@ class ApiClientAuthorization < ArvadosModel
          (secret == auth.api_token ||
           secret == OpenSSL::HMAC.hexdigest('sha1', auth.api_token, remote))
         # found it
+        if token_uuid[0..4] != Rails.configuration.ClusterID
+          Rails.logger.debug "found cached remote token #{token_uuid} with secret #{secret} in local db"
+        end
         return auth
       end
 
@@ -274,6 +277,7 @@ class ApiClientAuthorization < ArvadosModel
                                 api_token: secret,
                                 api_client_id: 0,
                                 expires_at: Time.now + Rails.configuration.Login.RemoteTokenRefresh)
+        Rails.logger.debug "cached remote token #{token_uuid} with secret #{secret} in local db"
       end
       return auth
     else