add debug logging

lib/AuthHandler.ts

@@ -8,6 +8,9 @@
 import { IncomingMessage, ServerResponse } from 'http';
 import { to_utf8 } from '@sapphirecode/encoding-helper';
 import auth from './Authority';
+import { debug } from './debug';
+
+const logger = debug ('auth');
 
 interface AccessSettings {
   access_token_expires_in: number
@@ -74,6 +77,7 @@ class AuthRequest {
     this._cookie_name = cookie;
     this._refresh_cookie_name = refresh_cookie;
     this._is_successful = false;
+    logger ('started processing new auth request');
   }
 
   private default_header (set_content = true) {
@@ -92,6 +96,7 @@ class AuthRequest {
     data,
     leave_open
   }: AccessSettings): Promise<AccessResult> {
+    logger ('allowed access');
     this.default_header (typeof redirect_to !== 'string' && !leave_open);
 
     const at = await auth.sign (
@@ -114,6 +119,7 @@ class AuthRequest {
       cookies.push (`${this._cookie_name}=${at.signature}`);
 
     if (include_refresh_token) {
+      logger ('including refresh token');
       if (typeof refresh_token_expires_in !== 'number')
         throw new Error ('no expiry time defined for refresh tokens');
       const rt = await auth.sign (
@@ -130,6 +136,7 @@ class AuthRequest {
     }
 
     if (cookies.length > 0) {
+      logger ('sending %d cookies', cookies.length);
       this.response.setHeader (
         'Set-Cookie',
         cookies
@@ -139,6 +146,7 @@ class AuthRequest {
     this._is_successful = true;
 
     if (typeof redirect_to === 'string') {
+      logger ('redirecting to %s', redirect_to);
       this.response.setHeader ('Location', redirect_to);
       this.response.statusCode = 302;
       if (!leave_open)
@@ -147,6 +155,7 @@ class AuthRequest {
     }
 
     if (!leave_open) {
+      logger ('finishing http request');
       this.response.writeHead (200);
       this.response.end (JSON.stringify (res));
     }
@@ -160,6 +169,7 @@ class AuthRequest {
     data?: Record<string, unknown>,
     leave_open = false
   ): Promise<string> {
+    logger ('allowed part token');
     this.default_header ();
 
     const pt = await auth.sign (
@@ -175,6 +185,7 @@ class AuthRequest {
     };
 
     if (!leave_open) {
+      logger ('finishing http request');
       this.response.writeHead (200);
       this.response.end (JSON.stringify (res));
     }
@@ -184,9 +195,11 @@ class AuthRequest {
   }
 
   public invalid (error_description?: string, leave_open = false): void {
+    logger ('rejecting invalid request');
     this.default_header ();
     this.response.statusCode = 400;
     if (!leave_open) {
+      logger ('finishing http request');
       this.response.end (JSON.stringify ({
         error: 'invalid_request',
         error_description
@@ -195,12 +208,15 @@ class AuthRequest {
   }
 
   public deny (leave_open = false): void {
+    logger ('denied access');
     this.default_header ();
     this.response.statusCode = 401;
-    if (!leave_open)
+    if (!leave_open) {
+      logger ('finishing http request');
       this.response.end (JSON.stringify ({ error: 'invalid_client' }));
     }
   }
+}
 
 type AuthRequestHandler = (req: AuthRequest) => Promise<void> | void;
 
@@ -222,6 +238,7 @@ function process_request (
     return default_handler (request);
 
   if ((/Basic/ui).test (token?.groups?.type as string)) {
+    logger ('found basic login data');
     request.is_basic = true;
 
     let login = token?.groups?.token as string;
@@ -235,6 +252,7 @@ function process_request (
   }
 
   if ((/Bearer/ui).test (token?.groups?.type as string)) {
+    logger ('found bearer login data');
     request.is_bearer = true;
     request.token = token?.groups?.token;
 
@@ -243,6 +261,8 @@ function process_request (
     if (!token_data.valid)
       return default_handler (request);
 
+    logger ('bearer token is valid');
+
     request.token_data = token_data.data;
     request.token_id = token_data.id;
 
@@ -251,6 +271,7 @@ function process_request (
       && typeof options.refresh !== 'undefined'
       && token_data.type === 'refresh_token'
     ) {
+      logger ('found refresh token, emitting new access token');
       request.allow_access (options.refresh);
       return Promise.resolve ();
     }
@@ -262,13 +283,16 @@ function process_request (
       && typeof token_data.next_module !== 'undefined'
       && Object.keys (options.modules)
         .includes (token_data.next_module)
-    )
+    ) {
+      logger ('processing module %s', token_data.next_module);
       return options.modules[token_data.next_module] (request);
+    }
 
     request.invalid ('invalid bearer type');
     return Promise.resolve ();
   }
 
+  logger ('no matching login method, triggering default handler');
   return default_handler (request);
 }
 
@@ -277,6 +301,7 @@ export default function create_auth_handler (
   default_handler: AuthRequestHandler,
   options?: CreateHandlerOptions
 ): AuthHandler {
+  logger ('creating new auth handler');
   if (
     typeof options?.cookie_name !== 'undefined'
     && options.cookie_name === options.refresh_cookie_name

lib/Authority.ts

@@ -12,6 +12,9 @@ import {
 } from '@sapphirecode/crypto-helper';
 import keystore from './KeyStore';
 import blacklist from './Blacklist';
+import { debug } from './debug';
+
+const logger = debug ('authority');
 
 // eslint-disable-next-line no-shadow
 type TokenType = 'access_token' | 'none' | 'part_token' | 'refresh_token'
@@ -39,6 +42,7 @@ interface SignatureOptions
 
 class Authority {
   public verify (key: string): VerificationResult {
+    logger ('verifying token');
     const result: VerificationResult = {
       authorized: false,
       valid:      false,
@@ -59,6 +63,7 @@ class Authority {
     );
 
     if (data === null) {
+      logger ('token invalid');
       result.error = 'invalid signature';
       return result;
     }
@@ -66,7 +71,10 @@ class Authority {
     result.id = data.id;
     result.type = data.type;
 
+    logger ('parsing token %s %s', result.type, result.id);
+
     if (!blacklist.is_valid (data.id)) {
+      logger ('token is blacklisted');
       result.error = 'blacklisted';
       return result;
     }
@@ -76,6 +84,12 @@ class Authority {
     result.next_module = data.next_module;
     result.data = data.obj;
 
+    logger (
+      'valid %s; targeting module %s',
+      result.type,
+      result.next_module
+    );
+
     return result;
   }
 
@@ -84,6 +98,7 @@ class Authority {
     valid_for: number,
     options?: SignatureOptions
   ): Promise<SignatureResult> {
+    logger ('signing new %s', type);
     const time = Date.now ();
     const key = await keystore.get_sign_key (time / 1000, valid_for);
     const attributes = {
@@ -95,6 +110,7 @@ class Authority {
       next_module: options?.next_module
     };
     const signature = sign_object (options?.data, key, attributes);
+    logger ('created token %s', attributes.id);
     return { id: attributes.id, signature };
   }
 }

lib/Blacklist.ts

@@ -5,6 +5,10 @@
  * Created by Timo Hocker <timo@scode.ovh>, December 2020
  */
 
+import { debug } from './debug';
+
+const logger = debug ('blacklist');
+
 interface Signature {
   hash: string;
   iat: number;
@@ -18,6 +22,7 @@ class Blacklist {
   }
 
   public clear (before: number = Number.POSITIVE_INFINITY): void {
+    logger ('clearing blacklist');
     for (let i = this._signatures.length - 1; i >= 0; i--) {
       if (this._signatures[i].iat < before)
         this._signatures.splice (i, 1);
@@ -25,10 +30,12 @@ class Blacklist {
   }
 
   public add_signature (hash: string): void {
+    logger ('blacklisting signature %s', hash);
     this._signatures.push ({ iat: Date.now (), hash });
   }
 
   public remove_signature (hash: string): void {
+    logger ('removing signature from blacklist %s', hash);
     for (let i = this._signatures.length - 1; i >= 0; i--) {
       if (this._signatures[i].hash === hash)
         this._signatures.splice (i, 1);
@@ -36,19 +43,25 @@ class Blacklist {
   }
 
   public is_valid (hash: string): boolean {
+    logger ('checking signature for blacklist entry %s', hash);
     for (const sig of this._signatures) {
-      if (sig.hash === hash)
+      if (sig.hash === hash) {
+        logger ('found matching blacklist entry');
         return false;
       }
+    }
 
+    logger ('signature is not blacklisted');
     return true;
   }
 
   public export_blacklist (): Signature[] {
+    logger ('exporting blacklist');
     return this._signatures;
   }
 
   public import_blacklist (data: Signature[]): void {
+    logger ('importing %d blacklist entries', data.length);
     this._signatures.push (...data);
   }
 }

lib/Gateway.ts

@@ -9,6 +9,9 @@ import { IncomingMessage, ServerResponse } from 'http';
 import { run_regex } from '@sapphirecode/utilities';
 import authority from './Authority';
 import { AuthRequest, AccessSettings } from './AuthHandler';
+import { debug } from './debug';
+
+const logger = debug ('gateway');
 
 type AnyFunc = (...args: unknown[]) => unknown;
 type Gateway = (
@@ -38,6 +41,7 @@ class GatewayClass {
   private _options: GatewayOptions;
 
   public constructor (options: GatewayOptions = {}) {
+    logger ('creating new gateway');
     if (
       typeof options.cookie_name === 'string'
       && options.cookie_name === options.refresh_cookie_name
@@ -48,12 +52,15 @@ class GatewayClass {
   }
 
   public deny (res: ServerResponse): void {
+    logger ('denied http request');
     res.statusCode = 403;
     res.end ();
   }
 
   public redirect (res: ServerResponse): void {
+    logger ('redirecting http request to %s', this._options.redirect_url);
     if (typeof this._options.redirect_url !== 'string') {
+      logger ('no redirect url defined');
       this.deny (res);
       return;
     }
@@ -63,16 +70,19 @@ class GatewayClass {
   }
 
   public get_header_auth (req: IncomingMessage): string | null {
+    logger ('extracting authorization header');
     const auth_header = req.headers.authorization;
     const auth = (/(?<type>\w+) (?<data>.*)/u).exec (auth_header || '');
     if (auth === null)
       return null;
     if (auth.groups?.type !== 'Bearer')
       return null;
+    logger ('found bearer token');
     return auth.groups?.data;
   }
 
   public get_cookie_auth (req: IncomingMessage): AuthCookies {
+    logger ('extracting tokens from cookies');
     const result: AuthCookies = {
       access_cookie:  null,
       refresh_cookie: null
@@ -84,6 +94,7 @@ class GatewayClass {
       cookie_regex,
       req.headers.cookie,
       (res: RegExpMatchArray) => {
+        logger ('parsing cookie %s', res.groups?.name);
         if (res.groups?.name === this._options.cookie_name)
           result.access_cookie = res.groups?.value as string;
         else if (res.groups?.name === this._options.refresh_cookie_name)
@@ -91,22 +102,28 @@ class GatewayClass {
       }
     );
 
+    logger ('parsed cookies: %O', result);
     return result;
   }
 
   public authenticate (req: IncomingMessage): boolean {
+    logger ('authenticating incoming request');
     const cookies = this.get_cookie_auth (req);
     let auth = this.get_header_auth (req);
     if (auth === null)
       auth = cookies.access_cookie;
-    if (auth === null)
+    if (auth === null) {
+      logger ('found no auth token');
       return false;
+    }
 
     const ver = authority.verify (auth);
 
+    logger ('setting connection info');
     const con = req.connection as unknown as Record<string, unknown>;
     con.auth = { token_id: ver.id, token_data: ver.data };
 
+    logger ('token valid: %s', ver.authorized);
     return ver.authorized;
   }
 
@@ -120,12 +137,17 @@ class GatewayClass {
     )
       return false;
 
+    logger ('trying to apply refresh token');
+
     const refresh = this.get_cookie_auth (req).refresh_cookie;
-    if (refresh === null)
+    if (refresh === null) {
+      logger ('could not find refresh token');
       return false;
+    }
 
     const ver = authority.verify (refresh);
     if (ver.type === 'refresh_token' && ver.valid) {
+      logger ('refresh token valid, generating new tokens');
       const auth_request = new AuthRequest (
         req,
         res,
@@ -139,15 +161,18 @@ class GatewayClass {
         leave_open:  true
       });
 
+      logger ('setting connection info');
       const con = req.connection as unknown as Record<string, unknown>;
       con.auth = {
         token_id:   refresh_result.access_token_id,
         token_data: this._options.refresh_settings.data
       };
 
+      logger ('tokens refreshed');
       return true;
     }
 
+    logger ('refresh token invalid');
     return false;
   }
 
@@ -156,10 +181,17 @@ class GatewayClass {
     res: ServerResponse,
     next: AnyFunc
   ): Promise<unknown> {
-    if (this.authenticate (req))
+    logger ('processing incoming http request');
+    if (this.authenticate (req)) {
+      logger ('authentification successful, calling next handler');
       return next ();
-    if (await this.try_refresh (req, res))
+    }
+    if (await this.try_refresh (req, res)) {
+      logger ('refresh successful, calling next handler');
       return next ();
+    }
+
+    logger ('could not verify session, redirecting to auth gateway');
     return this.redirect (res);
   }
 }

lib/KeyStore.ts

@@ -7,6 +7,9 @@
 
 import { generate_keypair, random_hex } from '@sapphirecode/crypto-helper';
 import { to_b58 } from '@sapphirecode/encoding-helper';
+import { debug } from './debug';
+
+const logger = debug ('keystore');
 
 const renew_interval = 3600;
 
@@ -28,6 +31,7 @@ type KeyStoreData = Record<string, KeyPair>;
 type KeyStoreExport = LabelledKey[];
 
 async function create_key (valid_for: number) {
+  logger ('generating new key');
   const time = (new Date)
     .getTime ();
   const pair = await generate_keypair ();
@@ -57,6 +61,7 @@ class KeyStore {
       this.garbage_collect ();
     }, renew_interval);
     this._instance = to_b58 (random_hex (16), 'hex');
+    logger ('created keystore instance %s', this._instance);
   }
 
   private get_index (iat: number, instance = this._instance): string {
@@ -72,19 +77,29 @@ class KeyStore {
       const entry = this._keys[index];
       if (typeof entry.private_key !== 'undefined'
         && entry.private_key.valid_until < time
-      )
+      ) {
+        logger ('deleting expired private key');
         delete entry.private_key;
+      }
 
-      if (entry.public_key.valid_until < time)
+      if (entry.public_key.valid_until < time) {
+        logger ('deleting expired key pair');
         delete this._keys[index];
       }
     }
+  }
 
   public async get_sign_key (
     iat: number,
     valid_for: number,
     instance?: string
   ): Promise<string> {
+    logger (
+      'querying key from %s for timestamp %d, valid for %d',
+      instance,
+      iat,
+      valid_for
+    );
     if (valid_for <= 0)
       throw new Error ('cannot create infinitely valid key');
 
@@ -98,21 +113,27 @@ class KeyStore {
       .getTime () + (valid_for * 1000);
 
     if (typeof this._keys[index] !== 'undefined') {
+      logger ('loading existing key');
       const key = this._keys[index];
-      if (key.public_key.valid_until < valid_until)
-        key.public_key.valid_until = valid_until;
 
       if (typeof key.private_key === 'undefined')
         throw new Error ('cannot access already expired keys');
 
+      if (key.public_key.valid_until < valid_until) {
+        logger ('updating key valid timespan to match new value');
+        key.public_key.valid_until = valid_until;
+      }
+
       return key.private_key?.key as string;
     }
 
+    logger ('key does not exist, creating a new one');
     this._keys[index] = await create_key (valid_for);
     return this._keys[index].private_key?.key as string;
   }
 
   public get_key (iat: number, instance?: string): string {
+    logger ('querying public key from %s for timestamp %d', instance, iat);
     const index = this.get_index (iat, instance);
 
     if (typeof this._keys[index] === 'undefined')
@@ -123,6 +144,7 @@ class KeyStore {
   }
 
   public export_verification_data (): KeyStoreExport {
+    logger ('exporting public keys');
     this.garbage_collect ();
     const out: KeyStoreExport = [];
     for (const index of Object.keys (this._keys))
@@ -132,6 +154,7 @@ class KeyStore {
   }
 
   public import_verification_data (data: KeyStoreExport): void {
+    logger ('importing %d public keys', data.length);
     for (const key of data) {
       if (typeof this._keys[key.index] !== 'undefined')
         throw new Error ('cannot import to the same instance');
@@ -146,6 +169,7 @@ class KeyStore {
   }
 
   public reset_instance (): void {
+    logger ('resetting keystore');
     this._instance = to_b58 (random_hex (16), 'hex');
     this._keys = {};
   }

lib/debug.ts

@@ -0,0 +1,9 @@
+import build_debug from 'debug';
+
+function debug (scope: string): build_debug.Debugger {
+  const namespace = `sapphirecode:auth-server-helper:${scope}`;
+  console.log ('register debugger', namespace);
+  return build_debug (namespace);
+}
+
+export { debug };

package.json

@@ -1,6 +1,6 @@
 {
   "name": "@sapphirecode/auth-server-helper",
-  "version": "2.2.1",
+  "version": "2.2.2",
   "main": "dist/index.js",
   "author": {
     "name": "Timo Hocker",
@@ -17,6 +17,7 @@
     "@sapphirecode/eslint-config-ts": "^1.1.27",
     "@stryker-mutator/core": "^4.3.1",
     "@stryker-mutator/jasmine-runner": "^4.3.1",
+    "@types/debug": "^4.1.7",
     "@types/jasmine": "^3.6.2",
     "@types/node": "^10.0.0",
     "eslint": "^7.14.0",
@@ -46,7 +47,8 @@
   "dependencies": {
     "@sapphirecode/crypto-helper": "^1.3.0",
     "@sapphirecode/encoding-helper": "^1.1.0",
-    "@sapphirecode/utilities": "^1.8.8"
+    "@sapphirecode/utilities": "^1.8.8",
+    "debug": "^4.3.3"
   },
   "engines": {
     "node": ">=10.0.0"

yarn.lock

@@ -503,6 +503,13 @@
   dependencies:
     lodash.flatmap "~4.5.0"
 
+"@types/debug@^4.1.7":
+  version "4.1.7"
+  resolved "https://registry.yarnpkg.com/@types/debug/-/debug-4.1.7.tgz#7cc0ea761509124709b8b2d1090d8f6c17aadb82"
+  integrity sha512-9AonUzyTjXXhEOa0DnqpzZi6VHlqKMswga9EXjpXnnqxwLtdvPPtlO8evrI5D9S6asFRCQ6v+wpiUKbw+vKqyg==
+  dependencies:
+    "@types/ms" "*"
+
 "@types/jasmine@^3.6.2":
   version "3.7.1"
   resolved "https://registry.yarnpkg.com/@types/jasmine/-/jasmine-3.7.1.tgz#35b86511a389673ac1a706c6010b35788a0d998d"
@@ -518,6 +525,11 @@
   resolved "https://registry.yarnpkg.com/@types/json5/-/json5-0.0.29.tgz#ee28707ae94e11d2b827bcbe5270bcea7f3e71ee"
   integrity sha1-7ihweulOEdK4J7y+UnC86n8+ce4=
 
+"@types/ms@*":
+  version "0.7.31"
+  resolved "https://registry.yarnpkg.com/@types/ms/-/ms-0.7.31.tgz#31b7ca6407128a3d2bbc27fe2d21b345397f6197"
+  integrity sha512-iiUgKzV9AuaEkZqkOLDIvlQiL6ltuZd9tGcW3gwpnX8JbuiuhFlEGmmFXEXkN50Cvq7Os88IY2v0dkDqXYWVgA==
+
 "@types/node@^10.0.0":
   version "10.17.59"
   resolved "https://registry.yarnpkg.com/@types/node/-/node-10.17.59.tgz#03f440ccf746a27f7da6e141e6cbae64681dbd2f"
@@ -967,6 +979,13 @@ debug@^4.0.1, debug@^4.1.0, debug@^4.1.1:
   dependencies:
     ms "2.1.2"
 
+debug@^4.3.3:
+  version "4.3.3"
+  resolved "https://registry.yarnpkg.com/debug/-/debug-4.3.3.tgz#04266e0b70a98d4462e6e288e38259213332b664"
+  integrity sha512-/zxw5+vh1Tfv+4Qn7a5nsbcJKPaSvCDhojn6FEl9vupwK2VCSDtEiEtqr8DFtzYFOdz63LBkxec7DYuc2jon6Q==
+  dependencies:
+    ms "2.1.2"
+
 decamelize@^1.2.0:
   version "1.2.0"
   resolved "https://registry.yarnpkg.com/decamelize/-/decamelize-1.2.0.tgz#f6534d15148269b20352e7bee26f501f9a191290"