From d30543221e4e7d0a7e89a1e603f679704dec7939 Mon Sep 17 00:00:00 2001 From: Pl217 Date: Thu, 12 Aug 2021 20:17:44 +0200 Subject: [PATCH] =?UTF-8?q?=E2=9C=A8=20Port=20logging=20from=20v3=20API?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- package.json | 2 + src/logging/log.ts | 228 +++++++++++++++++++++++++++++++++++++++ src/logging/logging.ts | 240 +++++++++++++++++++++++++++++++++++++++++ src/util/index.ts | 3 + yarn.lock | 80 +++++++++++++- 5 files changed, 551 insertions(+), 2 deletions(-) create mode 100644 src/logging/log.ts create mode 100644 src/logging/logging.ts diff --git a/package.json b/package.json index 79f070d2..05300dc1 100644 --- a/package.json +++ b/package.json @@ -12,6 +12,7 @@ "lint": "yarn lint-prettier && yarn lint-eslint" }, "dependencies": { + "bunyan": "^1.0.1", "fp-ts": "^2.6.6", "io-ts": "2.2.9", "knex": "0.21.1", @@ -20,6 +21,7 @@ "pg": "^8.5.1" }, "devDependencies": { + "@types/bunyan": "^1.0.1", "@types/hapi__hapi": "20.0.8", "@types/lodash": "^4.14.170", "@types/node": "^14.0.5", diff --git a/src/logging/log.ts b/src/logging/log.ts new file mode 100644 index 00000000..c3081def --- /dev/null +++ b/src/logging/log.ts @@ -0,0 +1,228 @@ +/* eslint-disable @typescript-eslint/no-explicit-any */ +/** + * Use of `any` in this module is generally deliberate to help with generics + */ +import bunyan = require('bunyan'); +import { format } from 'util'; +import { Config } from '../Context'; + +export interface LogObject { + time: Date; + level: number; + msg: string; + stackTrace?: string; +} + +export type LoggingListener = (log: LogObject) => void; + +const listeners = new Set(); + +export const addLoggingListener = (l: LoggingListener): void => { + listeners.add(l); +}; + +export const removeLoggingListener = (l: LoggingListener): void => { + listeners.delete(l); +}; + +export const loggingListenerStream: bunyan.Stream = { + type: 'raw', + level: 0, + stream: { + write: (obj: LogObject) => { + listeners.forEach((l) => l(obj)); + }, + } as any, +}; + +const printLevel = (obj: LogObject, useColor: boolean): string | undefined => { + if (obj.level >= bunyan.FATAL) { + return (useColor ? '\x1b[0;31;1m' : '') + '[FATAL]'; + } + if (obj.level >= bunyan.ERROR) { + return (useColor ? '\x1b[0;31;1m' : '') + '[ERROR]'; + } + if (obj.level >= bunyan.WARN) { + return (useColor ? '\x1b[0;33;1m' : '') + '[WARN]'; + } + if (obj.level >= bunyan.INFO) { + return (useColor ? '\x1b[0;36;1m' : '') + '[INFO]'; + } + if (obj.level >= bunyan.DEBUG) { + return '[DEBUG]'; + } + if (obj.level >= bunyan.TRACE) { + return '[TRACE]'; + } +}; + +export const printLog = (obj: LogObject, useColor: boolean): void => { + process.stdout.write( + // Make Dim + (useColor ? '\x1b[2m' : '') + + // Time + '[' + + obj.time.getHours() + + ':' + + obj.time.getMinutes() + + ':' + + obj.time.getSeconds() + + ':' + + obj.time.getMilliseconds() + + '] ' + + printLevel(obj, useColor) + + ' ' + + // Reset colors + (useColor ? '\x1b[0m' : '') + + obj.msg + + '\n' + ); + if (obj.stackTrace) { + process.stdout.write( + obj.stackTrace + .split('\n') + .map((s) => ` ${s}`) + .join('\n') + ); + } +}; + +export const getLog = (config: Config): bunyan => { + interface LoggingConfig { + writeToFile: bunyan.LogLevel | false; + writeToStdout: + | { + level: bunyan.LogLevel; + color: boolean; + } + | false; + } + + const LOGGING_MODES = ['live', 'devServer', 'jenkinsScript', 'test'] as const; + + type LoggingMode = typeof LOGGING_MODES[number]; + + const isLoggingMode = (mode: string): mode is LoggingMode => + LOGGING_MODES.indexOf(mode as LoggingMode) > -1; + + const LOGGING_CONFIG_LIVE: LoggingConfig = { + writeToFile: 'warn', + writeToStdout: false, + }; + + /** + * Standard logging configurations + */ + const LOGGING_CONFIGS: { [key in LoggingMode]: LoggingConfig } = { + live: LOGGING_CONFIG_LIVE, + devServer: { + writeToFile: false, + writeToStdout: { + level: 'debug', + color: true, + }, + }, + jenkinsScript: { + // Use same file config level as live server + writeToFile: LOGGING_CONFIG_LIVE.writeToFile, + writeToStdout: { + level: 'debug', + color: false, + }, + }, + test: { + // Console can be independently activated for each test via lib/logging + writeToFile: false, + writeToStdout: false, + }, + }; + + const getLoggingConfig = () => { + if (config.logging.mode) { + if (isLoggingMode(config.logging.mode)) { + return LOGGING_CONFIGS[config.logging.mode]; + } + + console.error('Unrecognized logging mode:', config.logging.mode); + } + // TODO: + // once all jenkins scripts have been updated to use the LOG_MODE env var, + // this should be updated to use devServer instead of jenkinsScript, + // and when all local scripts have been updated, this can be removed. + if (config.name === 'dockerdev') { + return LOGGING_CONFIGS.devServer; + } + + return LOGGING_CONFIGS.live; + }; + + const logConfig: LoggingConfig = getLoggingConfig(); + + // Overwrite color settings if specified + if (config.logging.color !== undefined && logConfig.writeToStdout) { + logConfig.writeToStdout.color = config.logging.color; + } + + if (process.env.JEST_WORKER_ID === undefined) { + console.log('Logging mode set to:', logConfig); + } + + const streams: bunyan.Stream[] = [loggingListenerStream]; + + if (logConfig.writeToFile) { + streams.push({ + level: logConfig.writeToFile, + path: '/var/log/hpc_service.log', + }); + } + + if (logConfig.writeToStdout) { + const shouldUseColor = logConfig.writeToStdout.color; + streams.push({ + type: 'raw', + level: logConfig.writeToStdout.level, + stream: { + write: (obj: LogObject) => printLog(obj, shouldUseColor), + } as any, + }); + } + + const log = bunyan.createLogger({ + name: config.name || '', + serializers: { + req: bunyan.stdSerializers.req, + }, + streams: streams, + }); + + // Overwrite default console log behaviour to output to bunyan using json + console.log = (...args: any[]) => { + log.info({ data: 'console.log' }, format(args[0], ...args.slice(1))); + }; + console.info = (...args: any[]) => { + log.info({ data: 'console.info' }, format(args[0], ...args.slice(1))); + }; + console.warn = (...args: any[]) => { + log.warn({ data: 'console.warn' }, format(args[0], ...args.slice(1))); + }; + console.error = (...args: any[]) => { + log.error({ data: 'console.error' }, format(args[0], ...args.slice(1))); + }; + console.debug = (...args: any[]) => { + log.debug({ data: 'console.debug' }, format(args[0], ...args.slice(1))); + }; + + // Handle uncaught rejections by logging an error + process.on('unhandledRejection', (reason, promise) => { + log.error( + { + data: 'unhandledRejection', + promise: format(promise), + reason: format(reason), + }, + `Unhandled Rejection: ${reason}` + ); + }); + + return log; +}; diff --git a/src/logging/logging.ts b/src/logging/logging.ts new file mode 100644 index 00000000..de893695 --- /dev/null +++ b/src/logging/logging.ts @@ -0,0 +1,240 @@ +import merge = require('lodash/merge'); +import { format } from 'util'; +import { getLoggedInParticipant } from '../auth'; +import Context, { Config } from '../Context'; +import { getLog } from './log'; + +type LoggerDataValue = + | { [id: string]: LoggerDataValue } + | LoggerDataValue[] + | number + | string + | null + | undefined + | boolean; + +export type LoggerTimingData = { + /** + * True iff the timing is past a point where we should begin to worry + */ + beyondWarningThreshold?: boolean; + /** + * UNIX timestamps / deltas in milliseconds + */ + values?: { + [id: string]: number; + }; + /** + * Human-readable information + */ + info?: { + [id: string]: string; + }; +}; + +export type LoggerData = { + [id: string]: LoggerDataValue; + /** + * Areate a stub logger context for when an actual / accurate context is not + * available. Usually used as a default value in a parameter for a function + * when we want to ensure compatibility with callers that have not yet been + * converted to typescript. + * + * TODO: remove this when all logging contexts have been added + */ + orphan?: boolean; + /** + * A JSON dump of the permissions that a user needed to have to perform the + * requested action that was denied. + */ + requiredPermissions?: string; + /** + * Timing information related to this log entry + */ + timing?: LoggerTimingData; + /** + * Information to present when a cache miss happened + */ + cacheMiss?: { + namespace: string; + fingerprint: string; + fingerprintSha: string; + oldestAllowedTime: string; + cachedTime: string; + }; + /** + * Set to true when a log message is indicative of a potential security issue. + */ + isPotentialSecurityIssue?: true; + /** + * Optional string used to identify the area of the codebase producing a log + */ + namespace?: string; + /** A list of identifiers for entities in the database relevant to the error */ + entities?: string[]; +}; + +/** + * For when we want to write to stdout directly, + * regardless of the logging environment. + * (e.g. for commands) + */ +export const stdoutWrite = (message: string): boolean => + process.stdout.write(message + '\n'); + +type LogMethod = ( + message: string, + opts?: { + data?: LoggerData; + error?: Error; + } +) => void; + +export type LogContextHandler = ( + level: 'debug' | 'info' | 'warn' | 'error', + message: string, + opts?: { + data?: LoggerData; + error?: Error; + } +) => void; + +/** + * Encapsulate all the context that should be captured and output alongside + * any log messages. + * + * contexts can be extended when there is additional context that needs to be + * included. For example, when an HTTP request is initialized, + * the raw request information may be captured in the context, + * and that context can then be passed down to callee functions. + * When a sub-task is running (e.g some data modifications), the context can be + * extended with the information of the sub-task, and used when logging actions + * related to the subtask. + */ +export class LogContext { + private readonly parent: LogContext | null; + private readonly data: LoggerData; + private readonly config: Config; + private readonly listener?: LogContextHandler; + + constructor( + parent: LogContext | null, + data: LoggerData, + config: Config, + listener?: LogContextHandler + ) { + this.parent = parent; + this.data = data; + this.config = config; + this.listener = listener; + } + + public extend = ( + data: LoggerData, + config: Config, + listener?: LogContextHandler + ): LogContext => new LogContext(this, data, config, listener); + + public log: LogContextHandler = (level, message, opts) => { + // Recursively merge context + const data = merge( + {}, + this.data, + opts?.data || {}, + opts?.error + ? { + stackTrace: opts.error.stack || format(opts.error), + } + : {} + ); + if (this.parent) { + this.parent.log(level, message, { data }); + } else { + getLog(this.config)[level](data, message); + } + if (this.listener) { + this.listener(level, message, opts); + } + }; + + public error: LogMethod = (message, opts) => this.log('error', message, opts); + + public warn: LogMethod = (message, opts) => this.log('warn', message, opts); + + public info: LogMethod = (message, opts) => this.log('info', message, opts); + + public debug: LogMethod = (message, opts) => this.log('debug', message, opts); + + /** + * Retreive a particular bit of context from either the current context or + * a parent's context (this is for use in more descriptive log messages) + */ + public getContext = ( + f: (data: LoggerData) => LoggerDataValue + ): LoggerDataValue => { + const s = f(this.data); + if (!s && this.parent) { + return this.parent.getContext(f); + } + return s; + }; +} + +export const createRootContext = ( + data: LoggerData, + config: Config +): LogContext => new LogContext(null, data, config); + +/** + * TODO: remove this when all logging contexts have been added + */ +export const createOrphanedContext = (config: Config): LogContext => + createRootContext( + { + orphan: true, + }, + config + ); + +/** + * Create a fresh context for when a new process has started (usually by CLI) + */ +export const createRootContextFromProcess = (config: Config): LogContext => + createRootContext( + { + hpc: { + process: { + argv: process.argv, + }, + }, + }, + config + ); + +/** + * Create a fresh context for an HTTP request + */ +export const createRootContextFromRequest = async ( + context: Context +): Promise => { + const user = await getLoggedInParticipant(context); + + const path = + typeof context.request.path === 'string' + ? context.request.path + : context.request.path?.(); + + return createRootContext( + { + hpc: { + req: { + method: context.request.method, + path, + userId: user?.id, + userEmail: user?.email, + }, + }, + }, + context.config + ); +}; diff --git a/src/util/index.ts b/src/util/index.ts index d9585109..35fa0d97 100644 --- a/src/util/index.ts +++ b/src/util/index.ts @@ -1,3 +1,6 @@ +export const isDefined = (v: T | null | undefined): v is T => + v !== null && v !== undefined; + export const getOrCreate = (map: Map, k: K, val: () => V): V => { let v = map.get(k); diff --git a/yarn.lock b/yarn.lock index 226ee3ee..5f4e99ac 100644 --- a/yarn.lock +++ b/yarn.lock @@ -168,7 +168,7 @@ resolved "https://registry.yarnpkg.com/@sideway/pinpoint/-/pinpoint-2.0.0.tgz#cff8ffadc372ad29fd3f78277aeb29e632cc70df" integrity sha512-RNiOoTPkptFtSVzQevY/yWtZwf/RxyVnPy/OcA9HBM3MlGDnBEYL5B41H0MTn0Uec8Hi+2qUtTfG2WWZBmMejQ== -"@types/bunyan@*": +"@types/bunyan@*", "@types/bunyan@^1.0.1": version "1.8.7" resolved "https://registry.yarnpkg.com/@types/bunyan/-/bunyan-1.8.7.tgz#63cc65b5ecff6217d1509409a575e7b991f80831" integrity sha512-jaNt6xX5poSmXuDAkQrSqx2zkR66OrdRDuVnU8ldvn3k/Ci/7Sf5nooKspQWimDnw337Bzt/yirqSThTjvrHkg== @@ -533,6 +533,16 @@ buffer-writer@2.0.0: resolved "https://registry.yarnpkg.com/buffer-writer/-/buffer-writer-2.0.0.tgz#ce7eb81a38f7829db09c873f2fbb792c0c98ec04" integrity sha512-a7ZpuTZU1TRtnwyCNW3I5dc0wWNC3VR9S++Ewyk2HHZdrO3CQJqSpd+95Us590V6AL7JqUAH2IwZ/398PmNFgw== +bunyan@^1.0.1: + version "1.8.15" + resolved "https://registry.yarnpkg.com/bunyan/-/bunyan-1.8.15.tgz#8ce34ca908a17d0776576ca1b2f6cbd916e93b46" + integrity sha512-0tECWShh6wUysgucJcBAoYegf3JJoZWibxdqhTm7OHPeT42qdjkZ29QCMcKwbgU1kiH+auSIasNRXMLWXafXig== + optionalDependencies: + dtrace-provider "~0.8" + moment "^2.19.3" + mv "~2" + safe-json-stringify "~1" + cache-base@^1.0.1: version "1.0.1" resolved "https://registry.yarnpkg.com/cache-base/-/cache-base-1.0.1.tgz#0a7f46416831c8b662ee36fe4e7c59d76f666ab2" @@ -776,6 +786,13 @@ doctrine@^3.0.0: dependencies: esutils "^2.0.2" +dtrace-provider@~0.8: + version "0.8.8" + resolved "https://registry.yarnpkg.com/dtrace-provider/-/dtrace-provider-0.8.8.tgz#2996d5490c37e1347be263b423ed7b297fb0d97e" + integrity sha512-b7Z7cNtHPhH9EJhNNbbeqTcXB8LGFFZhq1PGgEvpeHlzd36bhbdTWoE/Ba/YguqpBSlAPKnARWhVlhunCMwfxg== + dependencies: + nan "^2.14.0" + emoji-regex@^8.0.0: version "8.0.0" resolved "https://registry.yarnpkg.com/emoji-regex/-/emoji-regex-8.0.0.tgz#e818fd69ce5ccfcb404594f842963bf53164cc37" @@ -1177,6 +1194,17 @@ glob-parent@^5.1.0, glob-parent@^5.1.2: dependencies: is-glob "^4.0.1" +glob@^6.0.1: + version "6.0.4" + resolved "https://registry.yarnpkg.com/glob/-/glob-6.0.4.tgz#0f08860f6a155127b2fadd4f9ce24b1aab6e4d22" + integrity sha1-DwiGD2oVUSey+t1PnOJLGqtuTSI= + dependencies: + inflight "^1.0.4" + inherits "2" + minimatch "2 || 3" + once "^1.3.0" + path-is-absolute "^1.0.0" + glob@^7.1.3: version "7.1.7" resolved "https://registry.yarnpkg.com/glob/-/glob-7.1.7.tgz#3b193e9233f01d42d0b3f78294bbeeb418f94a90" @@ -1797,13 +1825,18 @@ mimic-fn@^2.1.0: resolved "https://registry.yarnpkg.com/mimic-fn/-/mimic-fn-2.1.0.tgz#7ed2c2ccccaf84d3ffcb7a69b57711fc2083401b" integrity sha512-OqbOk5oEQeAZ8WXWydlu9HJjz9WVdEIvamMCcXmuqUYjTknH/sqsWvhQ3vgwKFRR1HpjvNBKQ37nbJgYzGqGcg== -minimatch@^3.0.4: +"minimatch@2 || 3", minimatch@^3.0.4: version "3.0.4" resolved "https://registry.yarnpkg.com/minimatch/-/minimatch-3.0.4.tgz#5166e286457f03306064be5497e8dbb0c3d32083" integrity sha512-yJHVQEhyqPLUTgt9B83PXu6W3rx4MvvHvSUvToogpwoGDOUQ+yDrR0HRot+yOCdCO7u4hX3pWft6kWBBcqh0UA== dependencies: brace-expansion "^1.1.7" +minimist@^1.2.5: + version "1.2.5" + resolved "https://registry.yarnpkg.com/minimist/-/minimist-1.2.5.tgz#67d66014b66a6a8aaa0c083c5fd58df4e4e97602" + integrity sha512-FM9nNUYrRBAELZQT3xeZQ7fmMOBg6nWNmJKTcgsJeaLstP/UODVpGsr5OhXhhXg6f+qtJ8uiZ+PUxkDWcgIXLw== + mixin-deep@^1.2.0: version "1.3.2" resolved "https://registry.yarnpkg.com/mixin-deep/-/mixin-deep-1.3.2.tgz#1120b43dc359a785dce65b55b82e257ccf479566" @@ -1817,6 +1850,18 @@ mkdirp@^1.0.4: resolved "https://registry.yarnpkg.com/mkdirp/-/mkdirp-1.0.4.tgz#3eb5ed62622756d79a5f0e2a221dfebad75c2f7e" integrity sha512-vVqVZQyf3WLx2Shd0qJ9xuvqgAyKPLAiqITEtqW0oIUjzo3PePDd6fW9iFz30ef7Ysp/oiWqbhszeGWW2T6Gzw== +mkdirp@~0.5.1: + version "0.5.5" + resolved "https://registry.yarnpkg.com/mkdirp/-/mkdirp-0.5.5.tgz#d91cefd62d1436ca0f41620e251288d420099def" + integrity sha512-NKmAlESf6jMGym1++R0Ra7wvhV+wFW63FaSOFPwRahvea0gMUcGUhVeAg/0BC0wiv9ih5NYPB1Wn1UEI1/L+xQ== + dependencies: + minimist "^1.2.5" + +moment@^2.19.3: + version "2.29.1" + resolved "https://registry.yarnpkg.com/moment/-/moment-2.29.1.tgz#b2be769fa31940be9eeea6469c075e35006fa3d3" + integrity sha512-kHmoybcPV8Sqy59DwNDY3Jefr64lK/by/da0ViFcuA4DH0vQg5Q6Ze5VimxkfQNSC+Mls/Kx53s7TjP1RhFEDQ== + ms@2.0.0: version "2.0.0" resolved "https://registry.yarnpkg.com/ms/-/ms-2.0.0.tgz#5608aeadfc00be6c2901df5f9861788de0d597c8" @@ -1832,6 +1877,20 @@ ms@^2.1.1: resolved "https://registry.yarnpkg.com/ms/-/ms-2.1.3.tgz#574c8138ce1d2b5861f0b44579dbadd60c6615b2" integrity sha512-6FlzubTLZG3J2a/NVCAleEhjzq5oxgHyaCU9yYXvcLsvoVaHJq/s5xXI6/XXP6tz7R9xAOtHnSO/tXtF3WRTlA== +mv@~2: + version "2.1.1" + resolved "https://registry.yarnpkg.com/mv/-/mv-2.1.1.tgz#ae6ce0d6f6d5e0a4f7d893798d03c1ea9559b6a2" + integrity sha1-rmzg1vbV4KT32JN5jQPB6pVZtqI= + dependencies: + mkdirp "~0.5.1" + ncp "~2.0.0" + rimraf "~2.4.0" + +nan@^2.14.0: + version "2.15.0" + resolved "https://registry.yarnpkg.com/nan/-/nan-2.15.0.tgz#3f34a473ff18e15c1b5626b62903b5ad6e665fee" + integrity sha512-8ZtvEnA2c5aYCZYd1cvgdnU6cqwixRoYg70xPLWUws5ORTa/lnw+u4amixRS/Ac5U5mQVgp9pnlSUnbNWFaWZQ== + nanomatch@^1.2.9: version "1.2.13" resolved "https://registry.yarnpkg.com/nanomatch/-/nanomatch-1.2.13.tgz#b87a8aa4fc0de8fe6be88895b38983ff265bd119" @@ -1854,6 +1913,11 @@ natural-compare@^1.4.0: resolved "https://registry.yarnpkg.com/natural-compare/-/natural-compare-1.4.0.tgz#4abebfeed7541f2c27acfb29bdbbd15c8d5ba4f7" integrity sha1-Sr6/7tdUHywnrPspvbvRXI1bpPc= +ncp@~2.0.0: + version "2.0.0" + resolved "https://registry.yarnpkg.com/ncp/-/ncp-2.0.0.tgz#195a21d6c46e361d2fb1281ba38b91e9df7bdbb3" + integrity sha1-GVoh1sRuNh0vsSgbo4uR6d9727M= + node-fetch@~2.6.1: version "2.6.1" resolved "https://registry.yarnpkg.com/node-fetch/-/node-fetch-2.6.1.tgz#045bd323631f76ed2e2b55573394416b639a0052" @@ -2233,6 +2297,13 @@ rimraf@^3.0.2: dependencies: glob "^7.1.3" +rimraf@~2.4.0: + version "2.4.5" + resolved "https://registry.yarnpkg.com/rimraf/-/rimraf-2.4.5.tgz#ee710ce5d93a8fdb856fb5ea8ff0e2d75934b2da" + integrity sha1-7nEM5dk6j9uFb7Xqj/Di11k0sto= + dependencies: + glob "^6.0.1" + run-parallel@^1.1.9: version "1.2.0" resolved "https://registry.yarnpkg.com/run-parallel/-/run-parallel-1.2.0.tgz#66d1368da7bdf921eb9d95bd1a9229e7f21a43ee" @@ -2252,6 +2323,11 @@ safe-buffer@~5.2.0: resolved "https://registry.yarnpkg.com/safe-buffer/-/safe-buffer-5.2.1.tgz#1eaf9fa9bdb1fdd4ec75f58f9cdb4e6b7827eec6" integrity sha512-rp3So07KcdmmKbGvgaNxQSJr7bGVSVk5S9Eq1F+ppbRo70+YeaDxkw5Dd8NPN+GD6bjnYm2VuPuCXmpuYvmCXQ== +safe-json-stringify@~1: + version "1.2.0" + resolved "https://registry.yarnpkg.com/safe-json-stringify/-/safe-json-stringify-1.2.0.tgz#356e44bc98f1f93ce45df14bcd7c01cda86e0afd" + integrity sha512-gH8eh2nZudPQO6TytOvbxnuhYBOvDBBLW52tz5q6X58lJcd/tkmqFR+5Z9adS8aJtURSXWThWy/xJtJwixErvg== + safe-regex@^1.1.0: version "1.1.0" resolved "https://registry.yarnpkg.com/safe-regex/-/safe-regex-1.1.0.tgz#40a3669f3b077d1e943d44629e157dd48023bf2e"