Merge pull request #48 from AckeeCZ/feat/sentry-message-details

Add context details to Sentry logging

CHANGELOG.md

@@ -1,5 +1,13 @@
 ## [Unpublished]
 
+### Added
+- change Sentry scope per message
+
+### Changed
+- initializing Sentry support in logger
+
+## [2.0.0] - 2020-06-22
+
 ### Fixed
 - child logger type
 

README.md

@@ -86,20 +86,48 @@ All loglevels from warning up (inclusive) - warning, error, fatal - are logged t
 
 ## Using Sentry
 
-Cosmas logs every message to [Sentry](https://sentry.io/) for you, when configured. This feature is disabled by default.
+You can enhance cosmas logger with automatic [Sentry](https://sentry.io/) logging functionality.
 
 Sentry SDK `@sentry/node` is a peer dependency. If you want cosmas to use it, install it in your project.
 
 ```js
+import extendSentry from 'cosmas'
+
 // (1) Let cosmas initialize sentry with provided DSN
-const myLogger = logger({ sentry: 'https://<key>@sentry.io/<project>' })
+const myLogger = loggerFactory();
+extendSentry(myLogger, { sentry: 'https://<key>@sentry.io/<project>' }); // this will CHANGE the logger instance and returns it
+// or
+const sentryLogger = extendSentry(myLogger, { sentry: 'https://<key>@sentry.io/<project>' });
 
 // (2) Configure sentry yourself and let cosmas use it
 Sentry.init({/*...*/})
-const myLogger = logger({ sentry: true })
+const myLogger = loggerFactory();
+extendSentry(myLogger, { sentry: true });
+```
 
-// (3) Disable sentry (default, no need to send false option)
-const myLogger = logger({ sentry: false })
+After sentry extension, the interface of log methods will change.
+
+```js
+const myLogger = loggerFactory();
+myLogger.fatal('message');
+myLogger.fatal({ foo: 'bar' }, 'message');
+
+const sentryLogger = extendSentry(myLogger);
+sentryLogger.fatal('message', sentryCallback);
+sentryLogger.fatal({ foo: 'bar' }, sentryCallback);
+sentryLogger.fatal({ foo: 'bar' }, 'message', sentryCallback);
+```
+
+All log methods accept an optional `sentryCallback` argument. You can use it to pass a function which will obtain a [Sentry `scope`](https://docs.sentry.io/platforms/node/enriching-events/scopes/) which can be edited that way.
+
+```js
+import { Scope } from '@sentry/node';
+
+sentryLogger.fatal('message', (scope: Scope) => {
+    // scope.setContext
+    // scope.setTags
+    // scope.setExtras
+});
 ```
 
 When configured, cosmas (additionally to standard logging) captures all logs via Sentry SDK. Logs containing `stack` are logged as exceptions via `captureException` (preserves stack trace) and all other messages via `captureMessage`.

package.json

@@ -31,7 +31,8 @@
   },
   "dependencies": {
     "@types/express": "^4.16.0",
-    "@types/pino": "^6.0.0",
+    "@types/pino": "^6.3.1",
+    "cls-hooked": "^4.2.2",
     "lodash.foreach": "^4.5.0",
     "lodash.isempty": "^4.4.0",
     "lodash.isobject": "^3.0.2",
@@ -40,14 +41,15 @@
     "on-finished": "^2.3.0",
     "on-headers": "^1.0.1",
     "pick-deep": "^1.0.0",
-    "pino": "^6.2.0",
+    "pino": "^6.6.1",
     "pino-multi-stream": "^5.0.0"
   },
   "peerDependencies": {
     "@sentry/node": "^5.9.0"
   },
   "devDependencies": {
     "@sentry/node": "^5.9.0",
+    "@types/cls-hooked": "^4.3.1",
     "@types/jest": "^25.1.3",
     "@types/lodash.foreach": "^4.5.4",
     "@types/lodash.isempty": "^4.4.4",

src/index.ts

@@ -1,3 +1,4 @@
+import { Scope } from '@sentry/node';
 import { ErrorRequestHandler } from 'express';
 import * as fs from 'fs';
 import isObject = require('lodash.isobject');
@@ -14,16 +15,37 @@ import { initLoggerStreams } from './streams';
 
 export type PinoLogger = pino.BaseLogger;
 export type Level = pino.LevelWithSilent;
+export type PinoHooks = { logMethod: (inputArgs: any, method: any) => void };
 
 export interface Cosmas extends PinoLogger {
     warning: pino.LogFn;
     options: CosmasOptions;
     express: CosmasExpressMiddleware;
     expressError: ErrorRequestHandler;
     stream: Writable;
+    realHooks: PinoHooks;
     (childName: string): Cosmas;
 }
 
+export interface LogFnSentry {
+    (msg: string, sentryCallback?: (scope: Scope) => void, ...args: any[]): void;
+    (obj: object, sentryCallback?: (scope: Scope) => void, ...args: any[]): void;
+    (obj: object, msg?: string, sentryCallback?: (scope: Scope) => void, ...args: any[]): void;
+}
+
+export interface CosmasSentry extends Cosmas {
+    fatal: LogFnSentry;
+    error: LogFnSentry;
+    warning: LogFnSentry;
+    warn: LogFnSentry;
+    info: LogFnSentry;
+    debug: LogFnSentry;
+    trace: LogFnSentry;
+    silent: LogFnSentry;
+}
+
+export * from './sentry';
+
 export interface CosmasFactory extends Cosmas {
     (data?: string | CosmasOptions): Cosmas;
 }
@@ -52,7 +74,7 @@ const objEmpty = (obj: object) => Object.keys(obj).length === 0;
 // The original version was pino-multistream 4.2.0 (commit bf7941f) - https://github.com/pinojs/pino-multi-stream/blob/bf7941f77661b6c14dd40840ff4a4db6897f08eb/multistream.js#L43
 const maxLevelWrite: pino.WriteFn = function (this: any, data: object): void {
     let stream;
-    const metadata = Symbol.for('pino.metadata');
+    const metadata = pino.symbols.needsMetadataGsym;
     const level = this.lastLevel;
     const streams = this.streams;
     for (const dest of streams) {
@@ -105,38 +127,39 @@ const initFormatters = (options: CosmasOptions & { loggerName?: string }) => {
 };
 
 const initHooks = (options: CosmasOptions & { loggerName?: string }) => {
-    const hooks: { logMethod?: (inputArgs: any, method: any) => void } = {};
-    if (!options.loggerName) return hooks;
-
+    const realHooks: PinoHooks = {
+        logMethod(inputArgs, method) {
+            return method.apply(this, inputArgs);
+        },
+    };
+    const hooks: PinoHooks = {
+        logMethod(inputArgs, method) {
+            return realHooks.logMethod.call(this, inputArgs, method);
+        },
+    };
+    if (!options.loggerName) return { hooks, realHooks };
     // always put logger name to message
-    hooks.logMethod = function (inputArgs, method) {
+    realHooks.logMethod = function (inputArgs, method) {
         const text = inputArgs[inputArgs.length - 1];
         if (typeof text === 'string' || text instanceof String) {
             inputArgs[inputArgs.length - 1] = `[${options.loggerName}] ${text}`;
         }
         return method.apply(this, inputArgs);
     };
-    return hooks;
+    return { hooks, realHooks };
 };
 
 const defaultLogger = (options: CosmasOptions & { loggerName?: string } = {}): Cosmas => {
     serializers.disablePaths(options.disableFields);
     serializers.enablePaths(options.enableFields);
 
-    if (options.sentry) {
-        const sentry = require('@sentry/node');
-        if (typeof options.sentry === 'string') {
-            sentry.init({ dsn: options.sentry });
-        }
-    }
-
     const isTesting = process.env.NODE_ENV === 'test';
     const defaultLevel: Level = options.defaultLevel || (isTesting ? 'silent' : 'debug');
     const messageKey = 'message'; // best option for Google Stackdriver,
     const streams = initLoggerStreams(defaultLevel, Object.assign({}, options, { messageKey }));
 
     const formatters = initFormatters(options);
-    const hooks = initHooks(options);
+    const { hooks, realHooks } = initHooks(options);
 
     options.ignoredHttpMethods = options.ignoredHttpMethods || ['OPTIONS'];
     const logger = (pino(
@@ -161,14 +184,15 @@ const defaultLogger = (options: CosmasOptions & { loggerName?: string } = {}): C
 
     // Add maxLevel support to pino-multi-stream
     // This could be replaced with custom pass-through stream being passed to multistream, which would filter the messages
-    const loggerStream = (logger as any)[(pino as any).symbols.streamSym] as any;
+    const loggerStream = (logger as any)[pino.symbols.streamSym];
     const streamMaxLevelWrite = maxLevelWrite.bind(loggerStream);
     loggerStream.write = (chunk: any) => {
         streamMaxLevelWrite(chunk);
         return true;
     };
     return Object.assign(logger, {
         options,
+        realHooks,
         express: expressMiddleware.bind(logger),
         expressError: expressErrorMiddleware as any,
     });
@@ -202,6 +226,6 @@ const loggerFactory = (data: string | CosmasOptions = {}, loggerOptions: CosmasO
     return loggerProxy;
 };
 
-const factoryProxy = makeCallable(loggerFactory(), loggerFactory);
+const factoryProxy: CosmasFactory = makeCallable(loggerFactory(), loggerFactory);
 
 export default factoryProxy;

src/interfaces.ts

@@ -22,8 +22,6 @@ export interface CosmasOptions {
     ignoredHttpMethods?: string[];
     config?: LoggerOptions;
     pretty?: boolean;
-    sentry?: string | boolean;
-    sentryLevel?: pino.LevelWithSilent;
     loggerName?: string;
     skip?: (req: Request, res?: Response) => boolean;
 }

src/sentry.ts

@@ -1,8 +1,13 @@
-import { captureException, captureMessage, Severity, withScope } from '@sentry/node';
-import { Transform, TransformCallback } from 'stream';
-import { CosmasOptions } from './interfaces';
+import { captureException, captureMessage, Scope, Severity, withScope } from '@sentry/node';
+import { createNamespace } from 'cls-hooked';
+import * as pino from 'pino';
+import { Cosmas, CosmasSentry } from '.';
 import { levels } from './levels';
 
+const clsNamespace = createNamespace('cosmas.sentryExtend');
+
+type SentryCallback = (scope: Scope) => void;
+
 const reportToSentry = (obj: any) => {
     if (!obj.stack) {
         return captureMessage(obj.message || obj);
@@ -23,20 +28,55 @@ const PINO_TO_SENTRY: { [key: number]: Severity } = {
     60: Severity.Critical,
 };
 
-export const createSentryTransformStream = (options: CosmasOptions): any => {
-    return class SentryTransformStream extends Transform {
-        // tslint:disable-next-line:function-name
-        public _transform(chunk: any, _encoding: string, callback: TransformCallback) {
-            const obj = JSON.parse(chunk);
-            if (obj.level >= (options.sentryLevel || levels.warn)) {
-                withScope((scope) => {
-                    scope.setLevel(PINO_TO_SENTRY[obj.level]);
-                    scope.setExtras(obj);
-                    reportToSentry(obj);
-                });
-            }
-            this.push(chunk);
-            callback();
+export const extendSentry = (logger: Cosmas, options: { sentry: string | true; sentryLevel?: number }) => {
+    const sentry = require('@sentry/node');
+    if (typeof options.sentry === 'string') {
+        sentry.init({ dsn: options.sentry });
+    }
+
+    const originalWrite = (logger as any)[pino.symbols.streamSym].write;
+    // unfortunately, this is the only place in pino, we can hook onto, where we can be sure all
+    // the hooks, formatters and serializers are already applied
+    (logger as any)[pino.symbols.streamSym].write = function (s: string) {
+        originalWrite.call(this, s);
+        const obj = JSON.parse(s);
+        if (obj.level < (options.sentryLevel || levels.warn)) return;
+        const sentryCallback: SentryCallback | undefined = clsNamespace.get('sentryCallback');
+        withScope((scope) => {
+            scope.setLevel(PINO_TO_SENTRY[obj.level]);
+            scope.setExtras(obj);
+            if (sentryCallback) sentryCallback(scope);
+            reportToSentry(obj);
+        });
+    };
+
+    logger.realHooks.logMethod = function (inputArgs, method) {
+        // TODO: automatic types for logFn calls
+        let sentryCallback: SentryCallback | undefined;
+        let obj: object;
+        let rest: any;
+        let msg: string;
+        let newArgs: any;
+        if (typeof inputArgs[0] === 'string') {
+            [msg, sentryCallback, ...rest] = inputArgs;
+            newArgs = [msg, ...rest];
+        } else if (typeof inputArgs[1] === 'string') {
+            [obj, msg, sentryCallback, ...rest] = inputArgs;
+            newArgs = [obj, msg, ...rest];
+        } else {
+            [obj, sentryCallback, ...rest] = inputArgs;
+            newArgs = [obj, ...rest];
+        }
+
+        if (!sentryCallback) {
+            return method.apply(this, inputArgs);
         }
+
+        clsNamespace.runAndReturn(() => {
+            clsNamespace.set('sentryCallback', sentryCallback);
+            return method.apply(this, newArgs);
+        });
     };
+
+    return logger as CosmasSentry;
 };

src/streams.ts

@@ -52,11 +52,6 @@ const initLoggerStreams = (
 
     streams = decorateStreams(streams, getDefaultTransformStream(options));
 
-    if (options.sentry) {
-        const { createSentryTransformStream } = require('./sentry');
-        streams = decorateStreams(streams, createSentryTransformStream(options));
-    }
-
     return streams;
 };
 

src/tests/index.test.ts

@@ -187,14 +187,14 @@ test('Child logger takes parent config', () => {
 });
 
 test('Child logger inherits parent name', () => {
-    const logger = loggerFactory('parent', { disableStackdriverFormat: true });
+    const logger = loggerFactory('parent');
     const childLogger = logger('child');
 
     expect(childLogger.options.loggerName).toBe('parentchild');
 });
 
 test('Child logger can create another child', () => {
-    const logger = loggerFactory('parent', { disableStackdriverFormat: true });
+    const logger = loggerFactory('parent');
     const childLogger = logger('child');
     const kid = childLogger('grandkid');