JwtPlugin fixes

src/assertion/index.js

@@ -167,7 +167,8 @@ class Assertion {
     }
 
     if (test === false) {
-      logger.warn("failed assertion: %j against value: %j", this.config, value);
+      logger.warn("failed assertion: %j", this.config);
+      logger.debug("failed assertion: %j against value: %j", this.config, value);
     } else {
       logger.debug(
         "passed assertion: %j against value: %j",

src/plugin/jwt/index.js

@@ -130,6 +130,7 @@ class JwtPlugin extends BasePlugin {
 
     let error, error_description;
     const failure_response = function (code = 401) {
+      plugin.server.logger.debug("JwtPlugin: Failure response %j", { error, error_description });
       res.statusCode = code || 401;
 
       if (scheme == "bearer") {
@@ -148,6 +149,7 @@ class JwtPlugin extends BasePlugin {
     };
 
     if (!req.headers[header_name]) {
+      plugin.server.logger.debug("JwtPlugin: Missing '" + header_name + "' header");
       failure_response();
       return res;
     }
@@ -159,6 +161,7 @@ class JwtPlugin extends BasePlugin {
         scheme
       )
     ) {
+      plugin.server.logger.debug("JwtPlugin: Auth scheme mismatch");
       failure_response();
       return res;
     }
@@ -172,41 +175,41 @@ class JwtPlugin extends BasePlugin {
       creds.token = req.headers[header_name];
     }
 
-    const config = plugin.config.config;
+    const jwtConfig = plugin.config.config;
 
     // configure jwks secret automatically when oidc is enabled
-    if (plugin.config.oidc.enabled && !config.secret) {
+    if (plugin.config.oidc.enabled && !jwtConfig.secret) {
       const issuer = await plugin.get_issuer();
-      config.secret = issuer.metadata.jwks_uri;
+      jwtConfig.secret = issuer.metadata.jwks_uri;
     }
 
     function getKey(header, callback) {
       if (
-        config.secret.startsWith("http://") ||
-        config.secret.startsWith("https://")
+        jwtConfig.secret.startsWith("http://") ||
+        jwtConfig.secret.startsWith("https://")
       ) {
         /**
          * cache the client in memory to inherit the jwks caching from the upstream lib/client
          * https://github.com/auth0/node-jwks-rsa#caching
          */
         const jwksClientOptionHash = plugin.server.utils.md5(
-          JSON.stringify(config.secret)
+          JSON.stringify(jwtConfig.secret)
         );
         const cache_key = "jwt:jwks:clients:" + jwksClientOptionHash;
         let client = cache.get(cache_key);
         if (client === undefined) {
           plugin.server.logger.debug(
             "creating jwks client for URI %s",
-            config.secret
+            jwtConfig.secret
           );
           client = jwksClient({
-            jwksUri: config.secret,
+            jwksUri: jwtConfig.secret,
           });
           cache.set(cache_key, client, CLIENT_CACHE_DURATION);
         } else {
           plugin.server.logger.debug(
             "using cached jwks client for URI %s",
-            config.secret
+            jwtConfig.secret
           );
         }
 
@@ -219,17 +222,21 @@ class JwtPlugin extends BasePlugin {
           }
         });
       } else {
-        callback(null, config.secret);
+        callback(null, jwtConfig.secret);
       }
     }
 
     try {
+      plugin.server.logger.debug("JwtPlugin: Validating token using jwt options: %j", jwtConfig.options);
       const token = await new Promise((resolve, reject) => {
-        jwt.verify(creds.token, getKey, config.options, (err, decoded) => {
+        jwt.verify(creds.token, getKey, jwtConfig.options, (err, decoded) => {
           if (err) {
+            plugin.server.logger.debug("JwtPlugin: Validating token FAIL", err);
             reject(err);
+          } else {
+            plugin.server.logger.debug("JwtPlugin: Validating token SUCCESS");
+            resolve(decoded);
           }
-          resolve(decoded);
         });
       });
 
@@ -240,13 +247,17 @@ class JwtPlugin extends BasePlugin {
         JSON.stringify(plugin.config) + ":" + creds.token
       );
 
+      plugin.server.logger.debug("JwtPlugin: Running token assertions");
       const valid = await plugin.assertions(creds.token, token, session_id);
       if (valid !== true) {
         error = "invalid_user";
         error_description = "user did not pass assertions";
+        plugin.server.logger.debug("JwtPlugin: Token assertions FAIL");
 
         failure_response(403);
         return res;
+      } else {
+        plugin.server.logger.debug("JwtPlugin: Token assertions SUCCESS");
       }
 
       // introspection
@@ -261,10 +272,14 @@ class JwtPlugin extends BasePlugin {
         if (valid !== true) {
           error = "invalid_token";
           error_description = "token failed introspection";
+          plugin.server.logger.debug("JwtPlugin: Token introspection FAILED");
 
           failure_response();
           return res;
         }
+        plugin.server.logger.debug("JwtPlugin: Token introspection SUCCESS");
+      } else {
+        plugin.server.logger.debug("JwtPlugin: Token introspection SKIPPED");
       }
 
       // userinfo
@@ -336,15 +351,36 @@ class JwtPlugin extends BasePlugin {
     const plugin = this;
     let isValid = true;
 
+    // Run id_token assertions
     if (plugin.config.assertions && plugin.config.assertions.id_token) {
       isValid = await Assertion.assertSet(
         token_decoded,
         plugin.config.assertions.id_token
       );
 
       if (!isValid) {
+        plugin.server.logger.debug("JwtPlugin: id_token assertions FAILED")
+        return false;
+      }
+      plugin.server.logger.debug("JwtPlugin: id_token assertions PASSED")
+    } else {
+      plugin.server.logger.debug("JwtPlugin: id_token assertions SKIPPED")
+    }
+
+    // Run access_token assertions
+    if (plugin.config.assertions && plugin.config.assertions.access_token) {
+      isValid = await Assertion.assertSet(
+        token_decoded,
+        plugin.config.assertions.access_token
+      );
+
+      if (!isValid) {
+        plugin.server.logger.debug("JwtPlugin: access_token assertions FAILED")
         return false;
       }
+      plugin.server.logger.debug("JwtPlugin: access_token assertions PASSED")
+    } else {
+      plugin.server.logger.debug("JwtPlugin: access_token assertions SKIPPED")
     }
 
     return true;

src/plugin/oauth/index.js

@@ -2075,61 +2075,62 @@ class BaseOauthPlugin extends BasePlugin {
      */
     if (
       pluginStrategy == PLUGIN_STRATEGY_OIDC &&
-      plugin.config.assertions.aud &&
-      idToken.aud != plugin.config.client.client_id
+      plugin.config.assertions.aud
     ) {
-      return false;
+      if (idToken.aud != plugin.config.client.client_id) {
+        plugin.server.logger.debug("aud does not match client_id");
+        return false;
+      }
+    } else {
+      plugin.server.logger.debug("Assertions: SKIPPED aud")
     }
 
     /**
      * access token is expired and refresh tokens are disabled
      */
-    if (
-      plugin.config.assertions.exp &&
-      tokenset_is_expired(tokenSet) &&
-      !(
-        plugin.config.features.refresh_access_token &&
-        tokenset_can_refresh(tokenSet)
-      )
-    ) {
-      plugin.server.logger.verbose(
-        "tokenSet is expired and refresh tokens disabled"
-      );
-      return false;
-    }
+    if (plugin.config.assertions.exp) {
+      const is_expired = tokenset_is_expired(tokenSet)
 
-    /**
-     * both access and refresh tokens are expired and refresh is enabled
-     */
-    if (
-      plugin.config.assertions.exp &&
-      tokenset_is_expired(tokenSet) &&
-      plugin.config.features.refresh_access_token &&
-      !tokenset_can_refresh(tokenSet)
-    ) {
-      plugin.server.logger.verbose(
-        "tokenSet expired and refresh no longer available"
-      );
-      return false;
+      if (is_expired) {
+        plugin.server.logger.debug("tokenSet is expired");
+
+        if (!plugin.config.features.refresh_access_token) {
+          plugin.server.logger.debug("refresh tokens disabled");
+          return false
+        }
+
+        if (!tokenset_can_refresh(tokenSet)) {
+          plugin.server.logger.debug("refresh no longer available");
+          return false
+        }
+
+        plugin.server.logger.debug("refresh token available");
+      }
+      plugin.server.logger.debug("Assertions: PASSED exp");
+    } else {
+      plugin.server.logger.debug("Assertions: SKIPPED exp")
     }
 
-    if (
-      pluginStrategy == PLUGIN_STRATEGY_OIDC &&
-      plugin.config.assertions.nbf &&
-      tokenset_is_premature(tokenSet)
-    ) {
-      plugin.server.logger.verbose("tokenSet is premature");
-      return false;
+
+    if (plugin.config.assertions.nbf) {
+      if (tokenset_is_premature(tokenSet)) {
+        plugin.server.logger.debug("tokenSet is premature");
+        return false
+      }
+      plugin.server.logger.debug("Assertions: PASSED nbf")
+    } else {
+      plugin.server.logger.debug("Assertions: SKIPPED nbf")
     }
 
-    if (
-      pluginStrategy == PLUGIN_STRATEGY_OIDC &&
-      plugin.config.assertions.iss
-    ) {
+
+    if (plugin.config.assertions.iss) {
       if (!tokenset_issuer_match(tokenSet, issuer.issuer)) {
-        plugin.server.logger.verbose("tokenSet has a mismatch issuer");
+        plugin.server.logger.debug("tokenSet has a mismatch issuer");
         return false;
       }
+      plugin.server.logger.debug("Assertions: PASSED iss")
+    } else {
+      plugin.server.logger.debug("Assertions: SKIPPED iss")
     }
 
     if (
@@ -2153,9 +2154,9 @@ class BaseOauthPlugin extends BasePlugin {
         response = await client.introspect(tokenSet.access_token);
       }
 
-      plugin.server.logger.verbose("token introspect details %j", response);
+      plugin.server.logger.debug("token introspect details %j", response);
       if (response.active === false) {
-        plugin.server.logger.verbose("token no longer active!!!");
+        plugin.server.logger.debug("token no longer active!!!");
         return false;
       }
 
@@ -2166,32 +2167,48 @@ class BaseOauthPlugin extends BasePlugin {
       ) {
         await plugin.set_introspection_cache(session_id, response);
       }
+      plugin.server.logger.debug("Assertions: PASSED introspect_access_token")
+    } else {
+      plugin.server.logger.debug("Assertions: SKIPPED introspect_access_token")
     }
 
-    if (
-      pluginStrategy == PLUGIN_STRATEGY_OIDC &&
-      plugin.config.assertions.id_token
-    ) {
-      let idToken;
-      idToken = jwt.decode(tokenSet.id_token);
-      let idTokenValid = await plugin.id_token_assertions(idToken);
+
+    if (plugin.config.assertions.id_token) {
+      if (!tokenSet.id_token) {
+        plugin.server.logger.debug("Missing id_token")
+        return false
+      }
+
+      const idToken = jwt.decode(tokenSet.id_token);
+      const idTokenValid = await plugin.id_token_assertions(idToken);
       if (!idTokenValid) {
+        plugin.server.logger.debug("Invalid id_token")
         return false;
       }
+      plugin.server.logger.debug("Assertions: PASSED id_token")
+    } else {
+      plugin.server.logger.debug("Assertions: SKIPPED id_token")
     }
 
-    if (
-      pluginStrategy == PLUGIN_STRATEGY_OIDC &&
-      plugin.config.assertions.access_token
-    ) {
-      let accessToken;
-      accessToken = jwt.decode(tokenSet.access_token);
-      let accessTokenValid = await plugin.access_token_assertions(accessToken);
+
+    if (plugin.config.assertions.access_token) {
+      if (!tokenSet.access_token) {
+        plugin.server.logger.debug("Missing access_token")
+        return false
+      }
+
+      const accessToken = jwt.decode(tokenSet.access_token);
+      const accessTokenValid = await plugin.access_token_assertions(accessToken);
       if (!accessTokenValid) {
+        plugin.server.logger.debug("Invalid access_token")
         return false;
       }
+      plugin.server.logger.debug("Assertions: PASSED access_token")
+    } else {
+      plugin.server.logger.debug("Assertions: SKIPPED access_token")
     }
 
+    plugin.server.logger.debug("Assertions: PASSED")
     return true;
   }
 
@@ -2334,7 +2351,7 @@ class OauthPlugin extends BaseOauthPlugin {
     const client = await plugin.get_client();
     const response_type = "code";
 
-    return client.oauthCallback(
+    return client.callback(
       authorization_redirect_uri,
       parentReqInfo.parsedQuery,
       {

src/server.js

@@ -385,7 +385,8 @@ verifyHandler = async (req, res, options = {}) => {
           }
 
           lastPluginResponse = pluginResponse;
-          externalAuthServer.logger.debug("plugin response %j", pluginResponse);
+          externalAuthServer.logger.debug("plugin response: " + pluginResponse.statusCode);
+          externalAuthServer.logger.silly("plugin response %j", pluginResponse);
 
           if (fallbackPlugin !== null) {
             if (i == fallbackPlugin) {

src/utils.js

@@ -188,7 +188,7 @@ function get_parent_request_uri(req) {
     originalRequestURI = originalRequestURI.replace(/^(.+?)\/*?$/, "$1"); // remove all trailing slashes
     originalRequestURI += req.headers["x-forwarded-uri"];
   } else {
-    originalRequestURI += req.headers["x-forwarded-uri"];
+    originalRequestURI += req.headers["x-forwarded-uri"] || '';
   }
 
   //x-forwarded-port