From b58af27719bbb48a0bb33539bf82a9789c9d9083 Mon Sep 17 00:00:00 2001 From: Timo Hocker <35867059+TimoHocker@users.noreply.github.com> Date: Wed, 5 Jan 2022 12:32:04 +0100 Subject: [PATCH] add debug logging --- lib/AuthHandler.ts | 29 +++++++++++++++++++++++++++-- lib/Authority.ts | 16 ++++++++++++++++ lib/Blacklist.ts | 15 ++++++++++++++- lib/Gateway.ts | 40 ++++++++++++++++++++++++++++++++++++---- lib/KeyStore.ts | 32 ++++++++++++++++++++++++++++---- lib/debug.ts | 9 +++++++++ package.json | 6 ++++-- yarn.lock | 19 +++++++++++++++++++ 8 files changed, 153 insertions(+), 13 deletions(-) create mode 100644 lib/debug.ts diff --git a/lib/AuthHandler.ts b/lib/AuthHandler.ts index 055464b..92eeca4 100644 --- a/lib/AuthHandler.ts +++ b/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 { + 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, leave_open = false ): Promise { + 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,10 +208,13 @@ 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' })); + } } } @@ -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 diff --git a/lib/Authority.ts b/lib/Authority.ts index 2bd5a2a..059cc81 100644 --- a/lib/Authority.ts +++ b/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 { + 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 }; } } diff --git a/lib/Blacklist.ts b/lib/Blacklist.ts index 6ca0ff0..98a6351 100644 --- a/lib/Blacklist.ts +++ b/lib/Blacklist.ts @@ -5,6 +5,10 @@ * Created by Timo Hocker , 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); } } diff --git a/lib/Gateway.ts b/lib/Gateway.ts index b544011..33c2a59 100644 --- a/lib/Gateway.ts +++ b/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 = (/(?\w+) (?.*)/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; 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; 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 { - 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); } } diff --git a/lib/KeyStore.ts b/lib/KeyStore.ts index 635fb20..de5fa1d 100644 --- a/lib/KeyStore.ts +++ b/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; 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,11 +77,15 @@ 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]; + } } } @@ -85,6 +94,12 @@ class KeyStore { valid_for: number, instance?: string ): Promise { + 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 = {}; } diff --git a/lib/debug.ts b/lib/debug.ts new file mode 100644 index 0000000..f780624 --- /dev/null +++ b/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 }; diff --git a/package.json b/package.json index fe30be7..9afec1c 100644 --- a/package.json +++ b/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" diff --git a/yarn.lock b/yarn.lock index 03f5d56..e8cc652 100644 --- a/yarn.lock +++ b/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"