Add TROUBLESHOOTING and update debug logging

README.md

@@ -12,6 +12,7 @@ Express JS middleware implementing sign on for Express web apps using OpenID Con
 - [Install](#install)
 - [Getting Started](#getting-started)
 - [Contributing](#contributing)
+- [Troubleshooting](./TROUBLESHOOTING.md)
 - [Support + Feedback](#support--feedback)
 - [Vulnerability Reporting](#vulnerability-reporting)
 - [What is Auth0](#what-is-auth0)

TROUBLESHOOTING.md

@@ -0,0 +1,25 @@
+# Troubleshooting
+
+If you're running into problems there are 2 sources of logs you can check to get more information about what's going on:
+
+## 1. Debug logs
+
+Add the `DEBUG` environment variable and filter the messages by `express-openid-connect`.
+
+```shell script
+$ DEBUG=express-openid-connect:* node index.js
+```
+
+On Windows, use the corresponding command.
+
+```shell script
+> set DEBUG=express-openid-connect:* & node index.js
+```
+
+For more information about `debug`, see [debug](https://github.com/visionmedia/debug)
+
+## 2. Auth0 tenant logs
+
+If you're an Auth0 customer, you can check out what's happening on the Authorization Server using your [Auth0 tenant logs](https://manage.auth0.com/#/logs).
+
+Visit [View Log Data in the Dashboard](https://auth0.com/docs/logs/guides/view-log-data-dashboard) for more information.

lib/appSession.js

@@ -9,7 +9,7 @@ const onHeaders = require('on-headers');
 const cookie = require('cookie');
 const COOKIES = require('./cookies');
 const { encryption: deriveKey } = require('./hkdf');
-const debug = require('./debug');
+const debug = require('./debug')('appSession');
 
 const epoch = () => (Date.now() / 1000) | 0;
 const CHUNK_BYTE_SIZE = 4000;
@@ -97,12 +97,19 @@ module.exports = (config) => {
     // session was deleted or is empty, this matches all session cookies (chunked or unchunked)
     // and clears them, essentially cleaning up what we've set in the past that is now trash
     if (!req[sessionName] || !Object.keys(req[sessionName]).length) {
+      debug(
+        'session was deleted or is empty, clearing all matching session cookies'
+      );
       for (const cookieName of Object.keys(req[COOKIES])) {
         if (cookieName.match(`^${sessionName}(?:\\.\\d)?$`)) {
           res.clearCookie(cookieName, { domain: cookieOptions.domain });
         }
       }
     } else {
+      debug(
+        'found session, creating signed session cookie(s) with name %o(.i)',
+        sessionName
+      );
       const value = encrypt(JSON.stringify(req[sessionName]), {
         iat,
         uat,
@@ -111,6 +118,7 @@ module.exports = (config) => {
 
       const chunkCount = Math.ceil(value.length / CHUNK_BYTE_SIZE);
       if (chunkCount > 1) {
+        debug('cookie size greater than %d, chunking', CHUNK_BYTE_SIZE);
         for (let i = 0; i < chunkCount; i++) {
           const chunkValue = value.slice(
             i * CHUNK_BYTE_SIZE,
@@ -127,12 +135,13 @@ module.exports = (config) => {
 
   return (req, res, next) => {
     if (req.hasOwnProperty(sessionName)) {
-      debug.trace(
-        `request object (req) already has ${sessionName} property, this is indicative of a middleware setup problem`
+      debug(
+        'request object (req) already has %o property, this is indicative of a middleware setup problem',
+        sessionName
       );
       return next(
         new Error(
-          `req[${sessionName}] is already set, do you run this middleware twice?`
+          `req[${sessionName}] is already set, did you run this middleware twice?`
         )
       );
     }
@@ -147,15 +156,14 @@ module.exports = (config) => {
     try {
       if (req[COOKIES].hasOwnProperty(sessionName)) {
         // get JWE from unchunked session cookie
-        debug.trace(`reading session from ${sessionName} cookie`);
+        debug('reading session from %s cookie', sessionName);
         existingSessionValue = req[COOKIES][sessionName];
       } else if (req[COOKIES].hasOwnProperty(`${sessionName}.0`)) {
         // get JWE from chunked session cookie
         // iterate all cookie names
         // match and filter for the ones that match sessionName.<number>
         // sort by chunk index
         // concat
-        debug.trace('reading session chunks');
         existingSessionValue = Object.entries(req[COOKIES])
           .map(([cookie, value]) => {
             const match = cookie.match(`^${sessionName}\\.(\\d+)$`);
@@ -168,9 +176,7 @@ module.exports = (config) => {
             return parseInt(a, 10) - parseInt(b, 10);
           })
           .map(([i, chunk]) => {
-            debug.trace(
-              `reading session chunk from ${sessionName}.${i} cookie`
-            );
+            debug('reading session chunk from %s.%d cookie', sessionName, i);
             return chunk;
           })
           .join('');
@@ -205,14 +211,14 @@ module.exports = (config) => {
       }
     } catch (err) {
       if (err instanceof AssertionError) {
-        debug.trace('existing session was rejected because', err.message);
+        debug('existing session was rejected because', err.message);
       } else if (err instanceof JOSEError) {
-        debug.trace(
+        debug(
           'existing session was rejected because it could not be decrypted',
           err
         );
       } else {
-        debug.trace('unexpected error handling session', err);
+        debug('unexpected error handling session', err);
       }
     }
 

lib/client.js

@@ -3,7 +3,7 @@ const memoize = require('p-memoize');
 const url = require('url');
 const urlJoin = require('url-join');
 const pkg = require('../package.json');
-const debug = require('./debug');
+const debug = require('./debug')('client');
 
 const telemetryHeader = {
   name: 'express-oidc',
@@ -35,11 +35,8 @@ async function get(config) {
     options.timeout = 5000;
     return options;
   };
-  const applyHttpOptionsCustom = (entity) => {
-    entity[custom.http_options] = config.httpOptions
-      ? (...args) => config.httpOptions(defaultHttpOptions(...args))
-      : defaultHttpOptions;
-  };
+  const applyHttpOptionsCustom = (entity) =>
+    (entity[custom.http_options] = defaultHttpOptions);
 
   applyHttpOptionsCustom(Issuer);
   const issuer = await getIssuer(config.issuerBaseURL);
@@ -51,9 +48,10 @@ async function get(config) {
     ? issuer.id_token_signing_alg_values_supported
     : [];
   if (!issuerTokenAlgs.includes(config.idTokenSigningAlg)) {
-    debug.warn(
-      `ID token algorithm "${config.idTokenSigningAlg}" is not supported by the issuer. ` +
-        `Supported ID token algorithms are: "${issuerTokenAlgs.join('", "')}".`
+    debug(
+      'ID token algorithm %o is not supported by the issuer. Supported ID token algorithms are: %o.',
+      config.idTokenSigningAlg,
+      issuerTokenAlgs
     );
   }
 
@@ -65,9 +63,11 @@ async function get(config) {
     : [];
   issuerRespTypes.map(sortSpaceDelimitedString);
   if (!issuerRespTypes.includes(configRespType)) {
-    debug.warn(
-      `Response type "${configRespType}" is not supported by the issuer. ` +
-        `Supported response types are: "${issuerRespTypes.join('", "')}".`
+    debug(
+      'Response type %o is not supported by the issuer. ' +
+        'Supported response types are: %o.',
+      configRespType,
+      issuerRespTypes
     );
   }
 
@@ -76,9 +76,11 @@ async function get(config) {
     ? issuer.response_modes_supported
     : [];
   if (configRespMode && !issuerRespModes.includes(configRespMode)) {
-    debug.warn(
-      `Response mode "${configRespMode}" is not supported by the issuer. ` +
-        `Supported response modes are "${issuerRespModes.join('", "')}".`
+    debug(
+      'Response mode %o is not supported by the issuer. ' +
+        'Supported response modes are %o.',
+      configRespMode,
+      issuerRespModes
     );
   }
 
@@ -106,7 +108,7 @@ async function get(config) {
         },
       });
     } else {
-      debug.warn('The issuer does not support RP-Initiated Logout.');
+      debug('the issuer does not support RP-Initiated Logout');
     }
   }
 

lib/context.js

@@ -5,7 +5,7 @@ const { TokenSet } = require('openid-client');
 const clone = require('clone');
 const { strict: assert } = require('assert');
 
-const debug = require('./debug');
+const debug = require('./debug')('context');
 const { get: getClient } = require('./client');
 const { encodeState } = require('../lib/hooks/getLoginState');
 const weakRef = require('./weakCache');
@@ -136,10 +136,10 @@ class ResponseContext {
     let returnTo = config.baseURL;
     if (options.returnTo) {
       returnTo = options.returnTo;
-      debug.trace('req.oidc.login() called with returnTo:', returnTo);
+      debug('req.oidc.login() called with returnTo: %s', returnTo);
     } else if (req.method === 'GET' && req.originalUrl) {
       returnTo = req.originalUrl;
-      debug.trace('req.oidc.login() without returnTo, using:', returnTo);
+      debug('req.oidc.login() without returnTo, using: %s', returnTo);
     }
 
     options = {
@@ -170,7 +170,7 @@ class ResponseContext {
 
     const usePKCE = options.authorizationParams.response_type.includes('code');
     if (usePKCE) {
-      debug.trace(
+      debug(
         'response_type includes code, the authorization request will use PKCE'
       );
       stateValue.code_verifier = transient.generateCodeVerifier();
@@ -210,6 +210,7 @@ class ResponseContext {
       }
 
       const authorizationUrl = client.authorizationUrl(authParams);
+      debug('redirecting to %s', authorizationUrl);
       res.redirect(authorizationUrl);
     } catch (err) {
       next(err);
@@ -222,19 +223,22 @@ class ResponseContext {
     const client = await getClient(config);
 
     let returnURL = params.returnTo || config.routes.postLogoutRedirectUri;
+    debug('req.oidc.logout() with return url: %s', returnURL);
 
     if (url.parse(returnURL).host === null) {
       returnURL = urlJoin(config.baseURL, returnURL);
     }
 
     if (!req.oidc.isAuthenticated()) {
+      debug('end-user already logged out, redirecting to %s', returnURL);
       return res.redirect(returnURL);
     }
 
     const { idToken: id_token_hint } = req.oidc;
     req[config.session.name] = undefined;
 
     if (!config.idpLogout) {
+      debug('performing a local only logout, redirecting to %s', returnURL);
       return res.redirect(returnURL);
     }
 
@@ -247,6 +251,7 @@ class ResponseContext {
       return next(err);
     }
 
+    debug('logging out of identity provider, redirecting to %s', returnURL);
     res.redirect(returnURL);
   }
 }

lib/debug.js

@@ -1,13 +1,2 @@
-const Debug = require('debug');
-
-const levels = ['trace', 'debug', 'info', 'warn', 'error'];
-const debug = {};
-
-for (const level of levels) {
-  Object.defineProperty(debug, level, {
-    value: new Debug(`express-openid-connect:${level}`),
-    enumerable: true,
-  });
-}
-
-module.exports = debug;
+module.exports = (name) =>
+  require('debug')('express-openid-connect').extend(name);

lib/hooks/getLoginState.js

@@ -1,4 +1,5 @@
 const base64url = require('base64url');
+const debug = require('../debug')('getLoginState');
 
 /**
  * Generate the state value for use during login transactions. It is used to store the intended
@@ -11,7 +12,9 @@ const base64url = require('base64url');
  * @return {object}
  */
 function defaultState(req, options) {
-  return { returnTo: options.returnTo || req.originalUrl };
+  const state = { returnTo: options.returnTo || req.originalUrl };
+  debug('adding default state %O', state);
+  return state;
 }
 
 /**

middleware/auth.js

@@ -2,7 +2,7 @@ const express = require('express');
 const cb = require('cb');
 const createError = require('http-errors');
 
-const debug = require('../lib/debug');
+const debug = require('../lib/debug')('auth');
 const { get: getConfig } = require('../lib/config');
 const { get: getClient } = require('../lib/client');
 const { requiresAuth } = require('./requiresAuth');
@@ -24,10 +24,7 @@ const enforceLeadingSlash = (path) => {
  */
 module.exports = function (params) {
   const config = getConfig(params);
-  debug.trace(
-    'configuration object processed, resulting configuration:',
-    config
-  );
+  debug('configuration object processed, resulting configuration: %O', config);
   const router = new express.Router();
   const transient = new TransientCookieHandler(config);
 
@@ -43,21 +40,21 @@ module.exports = function (params) {
   // Login route, configurable with routes.login
   if (config.routes.login) {
     const path = enforceLeadingSlash(config.routes.login);
-    debug.trace(`adding GET ${path} route`);
+    debug('adding GET %s route', path);
     router.get(path, express.urlencoded({ extended: false }), (req, res) =>
       res.oidc.login({ returnTo: config.baseURL })
     );
   } else {
-    debug.trace('login handling route not applied');
+    debug('login handling route not applied');
   }
 
   // Logout route, configurable with routes.logout
   if (config.routes.logout) {
     const path = enforceLeadingSlash(config.routes.logout);
-    debug.trace(`adding GET ${path} route`);
+    debug('adding GET %s route', path);
     router.get(path, (req, res) => res.oidc.logout());
   } else {
-    debug.trace('logout handling route not applied');
+    debug('logout handling route not applied');
   }
 
   // Callback route, configured with routes.callback.
@@ -66,7 +63,7 @@ module.exports = function (params) {
     const path = enforceLeadingSlash(config.routes.callback);
     const callbackStack = [
       (req, res, next) => {
-        debug.trace(`${req.method} ${path} called`);
+        debug('%s %s called', req.method, path);
         next();
       },
       async (req, res, next) => {
@@ -127,9 +124,9 @@ module.exports = function (params) {
       (req, res) => res.redirect(req.openidState.returnTo || config.baseURL),
     ];
 
-    debug.trace(`adding GET ${path} route`);
+    debug('adding GET %s route', path);
     router.get(path, ...callbackStack);
-    debug.trace(`adding POST ${path} route`);
+    debug('adding POST %s route', path);
     router.post(
       path,
       express.urlencoded({ extended: false }),
@@ -138,12 +135,12 @@ module.exports = function (params) {
   }
 
   if (config.authRequired) {
-    debug.trace(
+    debug(
       'authentication is required for all routes this middleware is applied to'
     );
     router.use(requiresAuth());
   } else {
-    debug.trace(
+    debug(
       'authentication is not required for any of the routes this middleware is applied to ' +
         'see and apply `requiresAuth` middlewares to your protected resources'
     );