feat(node): pluggable logging class (#1063)

| 🚥 Resolves #1045 | | :------------------- | ## 🧰 Changes Implementation of the Node.js console logger for trace, debug and error logs. Implemented as a singleton class to make sure that its instance is the only one in the Node.js SDK. It has a config that allows you to customize the log prefix or disable the logging option, by default logging option is set to disabled and prefix is "[readmeio]". It has 3 main methods: trace, debug and errors. They can be called anywhere in the code. You need to import the logger instance from the "logger.ts" file and call the required method (logger.error(...) and so on). It takes the following fields in the object as a parameter: - message (required) - args (optional) - err (only for logger.error) ## 🧬 QA & Testing Set "logger" option in options object to true and try to send a test request. Some of the example logs provided here: <img width="445" alt="image" src="https://github.com/user-attachments/assets/b7e01af3-d637-4395-9c34-fe40d42c6a84"> <img width="815" alt="image" src="https://github.com/user-attachments/assets/9969cd26-e995-4235-9dcd-3d6910d54f42"> <img width="615" alt="image" src="https://github.com/user-attachments/assets/b3bfc0ba-a2b5-48c2-93b7-90695395096f"> --------- Co-authored-by: Gabe Ratcliff <[email protected]>
readmeio · Aug 28, 2024 · 2601a8d · 2601a8d
1 parent ab86f68
commit 2601a8d
Show file tree

Hide file tree

Showing 14 changed files with 913 additions and 46 deletions.
diff --git a/package-lock.json b/package-lock.json
diff --git a/packages/node/package.json b/packages/node/package.json
@@ -68,5 +68,9 @@
     "prettier": "prettier --list-different --write \"./**/**.{js,ts}\"",
     "test": "vitest run --coverage"
   },
-  "prettier": "@readme/eslint-config/prettier"
+  "prettier": "@readme/eslint-config/prettier",
+  "optionalDependencies": {
+    "pino": "^9.3.2",
+    "pino-pretty": "^11.2.2"
+  }
 }
diff --git a/packages/node/src/lib/ReadMe.ts b/packages/node/src/lib/ReadMe.ts
@@ -7,6 +7,7 @@ import config from '../config';
 import findAPIKey from './find-api-key';
 import { getGroupByApiKey } from './get-group-id';
 import { log } from './log';
+import { logger } from './logger';
 import { buildSetupView } from './setup-readme-view';
 import { testVerifyWebhook } from './test-verify-webhook';
 import verifyWebhook from './verify-webhook';
@@ -102,15 +103,17 @@ export default class ReadMe {
 
       const getUser: GetUserFunction = async ({ byAPIKey, byEmail, manualAPIKey }) => {
         if (!byAPIKey && !options.disableMetrics) {
-          console.error(
-            'Missing required definition for `byAPIKey`. Learn more here: https://docs.readme.com/main/docs/unified-snippet-docs#getuserbyapikey',
-          );
+          logger.error({
+            message:
+              'Missing required definition for `byAPIKey`. Learn more here: https://docs.readme.com/main/docs/unified-snippet-docs#getuserbyapikey',
+          });
           return next();
         }
         if (!byEmail && !options.disableWebhook) {
-          console.error(
-            'Missing required definition for `byEmail`. Learn more here: https://docs.readme.com/main/docs/unified-snippet-docs#getuserbyapikey',
-          );
+          logger.error({
+            message:
+              'Missing required definition for `byEmail`. Learn more here: https://docs.readme.com/main/docs/unified-snippet-docs#getuserbyapikey',
+          });
           return next();
         }
 
@@ -130,10 +133,12 @@ export default class ReadMe {
         // Try to figure out where the api key is
         try {
           requestAPIKey = findAPIKey(req);
-        } catch (e) {
-          console.error(
-            'Could not automatically find an API key in the request. You should pass the API key via `manualAPIKey` in the `getUser` function. Learn more here: https://docs.readme.com/main/docs/unified-snippet-docs#getuserbyapikey',
-          );
+        } catch (err) {
+          logger.error({
+            err,
+            message:
+              'Could not automatically find an API key in the request. You should pass the API key via `manualAPIKey` in the `getUser` function. Learn more here: https://docs.readme.com/main/docs/unified-snippet-docs#getuserbyapikey',
+          });
         }
         return byAPIKey(requestAPIKey);
       };
@@ -156,14 +161,12 @@ export default class ReadMe {
           this.readmeVersionData = await fetch(new URL('/api/v1/version', readmeAPIOrigin), {
             headers,
           }).then(r => r.json() as Promise<ReadMeVersion[]>);
-        } catch (e) {
+        } catch (err) {
           // TODO: Maybe send this to sentry?
-          if (e.status === 401) {
-            console.error('Invalid ReadMe API key. Contact [email protected] for help!');
-            console.error(e.data);
+          if (err.status === 401) {
+            logger.error({ err, message: 'Invalid ReadMe API key. Contact [email protected] for help!' });
           } else {
-            console.error('Error calling ReadMe API. Contact [email protected] for help!');
-            console.error(e.data);
+            logger.error({ err, message: 'Error calling ReadMe API. Contact [email protected] for help!' });
           }
           // Don't want to cause an error in their API
           return next();
@@ -179,8 +182,9 @@ export default class ReadMe {
           );
           const user = await userFunction(req, getUser);
           return res.send(user);
-        } catch (e) {
-          return res.status(400).json({ error: (e as Error).message });
+        } catch (err) {
+          logger.error({ err, message: 'Verify webhook error' });
+          return res.status(400).json({ error: (err as Error).message });
         }
       } else if (req.path === '/readme-setup' && options.development) {
         const setupHtml = buildSetupView({
@@ -197,8 +201,9 @@ export default class ReadMe {
         try {
           const webhookData = await testVerifyWebhook(baseUrl, email, this.readmeProjectData.jwtSecret as string);
           return res.json({ ...webhookData });
-        } catch (e) {
-          return res.status(400).json({ error: (e as Error).message });
+        } catch (err) {
+          logger.error({ err, message: 'Webhook verification failed.' });
+          return res.status(400).json({ error: (err as Error).message });
         }
       }
 
@@ -208,11 +213,11 @@ export default class ReadMe {
 
         const group = getGroupByApiKey(user, requestAPIKey);
         if (!group) {
-          console.error(
-            usingManualAPIKey
+          logger.error({
+            message: usingManualAPIKey
               ? 'The API key you passed in via `manualAPIKey` could not be found in the user object you provided.'
               : 'Could not automatically find an API key in the request. You should pass the API key via `manualAPIKey` in the `getUser` function. Learn more here: https://docs.readme.com/main/docs/unified-snippet-docs#/getuserbyapikey',
-          );
+          });
           return next();
         }
 

diff --git a/packages/node/src/lib/console-logger.ts b/packages/node/src/lib/console-logger.ts
@@ -0,0 +1,67 @@
+import type { Log, ErrorLog, LoggerStrategy } from './logger';
+
+/**
+ * Implementation of the console logger strategy.
+ */
+export default class ConsoleLogger implements LoggerStrategy {
+  /**
+   * This method takes a level of the log and a message and formats it to the unified log format
+   * @returns A formatted log message
+   */
+  // eslint-disable-next-line class-methods-use-this
+  private formatMessage(level: 'DEBUG' | 'ERROR' | 'INFO' | 'VERBOSE', message: string): string[] {
+    return [`${level} ${new Date().toISOString()} [readmeio] ${message}`];
+  }
+
+  /**
+   * Logs a verbose message to the console.
+   * @param log The verbose log entry. Contains the message as required field and optional args.
+   */
+  verbose({ message, args }: Log): void {
+    const params: unknown[] = this.formatMessage('VERBOSE', message);
+    console.log(...params);
+    if (args) {
+      console.dir(args, { depth: null });
+      console.log('\n');
+    }
+  }
+
+  /**
+   * Logs a debug message to the console.
+   * @param log The debug log entry. Contains the message as required field and optional args.
+   */
+  debug({ message, args }: Log): void {
+    const params: unknown[] = this.formatMessage('DEBUG', message);
+    if (args) {
+      params.push('\nArguments:', args);
+    }
+    console.debug(...params, '\n');
+  }
+
+  /**
+   * Logs an info message to the console.
+   * @param log The debug log entry. Contains the message as required field and optional args.
+   */
+  info({ message, args }: Log): void {
+    const params: unknown[] = this.formatMessage('INFO', message);
+    if (args) {
+      params.push('\nArguments:', args);
+    }
+    console.info(...params, '\n');
+  }
+
+  /**
+   * Logs an error message to the console.
+   * @param log The error log entry. Contains the message and error object as required fields and optional args.
+   */
+  error({ message, args, err }: ErrorLog): void {
+    const params: unknown[] = this.formatMessage('ERROR', message);
+    if (args) {
+      params.push('\nArguments:', args);
+    }
+    if (err) {
+      params.push('\n', err);
+    }
+    console.error(...params, '\n');
+  }
+}
diff --git a/packages/node/src/lib/construct-payload.ts b/packages/node/src/lib/construct-payload.ts
@@ -1,3 +1,4 @@
+import type { LoggerStrategy } from './logger';
 import type { OutgoingLogBody } from './metrics-log';
 import type { UUID } from 'node:crypto';
 import type { IncomingMessage, ServerResponse } from 'node:http';
@@ -54,6 +55,11 @@ export interface LogOptions {
    */
   fireAndForget?: boolean;
 
+  /**
+   * If true, the errors and other logs will be displayed in console. Your own logger strategy can be passed.
+   */
+  logger?: LoggerStrategy | boolean;
+
   /**
    * @deprecated use `allowList` instead
    */

diff --git a/packages/node/src/lib/get-project-base-url.ts b/packages/node/src/lib/get-project-base-url.ts
@@ -7,6 +7,8 @@ import timeoutSignal from 'timeout-signal';
 import pkg from '../../package.json';
 import config from '../config';
 
+import { logger } from './logger';
+
 export function getCache(readmeApiKey: string) {
   const encodedApiKey = Buffer.from(`${readmeApiKey}:`).toString('base64');
   const cacheDir = findCacheDir({ name: pkg.name, create: true });
@@ -48,7 +50,10 @@ export async function getProjectBaseUrl(readmeApiKey: string, requestTimeout = c
         if (res.status >= 400 && res.status <= 599) {
           throw res;
         }
-
+        const logLevel = res.ok ? 'info' : 'error';
+        logger[logLevel]({
+          message: `Fetch Base URL: Service responded with status ${res.status}: ${res.statusText}.`,
+        });
         return res.json() as Promise<{ baseUrl: string }>;
       })
       .then(project => {
@@ -71,6 +76,7 @@ export async function getProjectBaseUrl(readmeApiKey: string, requestTimeout = c
 
     return baseUrl;
   }
-
-  return cache.getKey('baseUrl');
+  const cachedBaseUrl = cache.getKey('baseUrl');
+  logger.verbose({ message: 'Retrieved baseUrl from cache.', args: { baseUrl: cachedBaseUrl } });
+  return cachedBaseUrl;
 }
diff --git a/packages/node/src/lib/log.ts b/packages/node/src/lib/log.ts
@@ -12,6 +12,7 @@ import config from '../config';
 import { constructPayload } from './construct-payload';
 import { getProjectBaseUrl } from './get-project-base-url';
 import isRequest from './is-request';
+import { logger } from './logger';
 import { metricsAPICall } from './metrics-log';
 import { patchRequest } from './patch-request';
 import { patchResponse } from './patch-response';
@@ -24,10 +25,14 @@ function doSend(readmeApiKey: string, options: Options) {
   queue = [];
 
   // Make the log call
-  metricsAPICall(readmeApiKey, json, options).catch(e => {
+  metricsAPICall(readmeApiKey, json, options).catch(err => {
     // Silently discard errors and timeouts.
-    if (options.development) throw e;
+    if (options.development) {
+      logger.error({ message: 'Failed to capture API request.', err });
+    }
   });
+
+  logger.debug({ message: 'Queue flushed.', args: { queue } });
 }
 // Make sure we flush the queue if the process is exited
 process.on('exit', doSend);
@@ -76,8 +81,12 @@ function setDocumentationHeader(res: ServerResponse, baseLogUrl: string, logId:
   // do with a test, but it's a little difficult to test. Maybe with a nock()
   // delay timeout.
   if (res.headersSent) return;
-
-  res.setHeader('x-documentation-url', `${baseLogUrl}/logs/${logId}`);
+  const documentationUrl = `${baseLogUrl}/logs/${logId}`;
+  logger.verbose({
+    message: 'Created URL to your API request log.',
+    args: { 'x-documentation-url': documentationUrl },
+  });
+  res.setHeader('x-documentation-url', documentationUrl);
 }
 
 /**
@@ -102,6 +111,10 @@ export function log(
 ) {
   if (!readmeApiKey) throw new Error('You must provide your ReadMe API key');
   if (!group) throw new Error('You must provide a group');
+  if (options.logger) {
+    if (typeof options.logger === 'boolean') logger.configure({ isLoggingEnabled: true });
+    else logger.configure({ isLoggingEnabled: true, strategy: options.logger });
+  }
 
   // Ensures the buffer length is between 1 and 30
   const bufferLength = clamp(options.bufferLength || config.bufferLength, 1, 30);
@@ -164,6 +177,7 @@ export function log(
     );
 
     queue.push(payload);
+    logger.debug({ message: 'Request enqueued.', args: { queue } });
     if (queue.length >= bufferLength) doSend(readmeApiKey, options);
 
     cleanup(); // eslint-disable-line @typescript-eslint/no-use-before-define

diff --git a/packages/node/src/lib/logger.ts b/packages/node/src/lib/logger.ts
@@ -0,0 +1,103 @@
+import ConsoleLogger from './console-logger';
+import PinoLogger from './pino-logger';
+
+interface LoggerConfig {
+  isLoggingEnabled: boolean;
+  strategy: LoggerStrategy;
+}
+
+export interface Log {
+  args?: Record<string, unknown>;
+  message: string;
+}
+
+export type ErrorLog = Log & { err?: Error };
+
+export interface LoggerStrategy {
+  debug(log: Log): void;
+  error(log: ErrorLog): void;
+  info(log: Log): void;
+  verbose(log: Log): void;
+}
+
+export interface Logger extends LoggerStrategy {
+  configure(config: Partial<LoggerConfig>): void;
+}
+
+/**
+ * Default implementation of the Logger interface. Represents a signleton class of logger with selected strategy.
+ */
+export class DefaultLogger implements Logger {
+  private static instance: Logger;
+
+  private config: LoggerConfig;
+
+  constructor(config: LoggerConfig) {
+    this.config = config;
+  }
+
+  /**
+   * Method for getting instance of the logger class
+   * @returns A single instance of the logger
+   */
+  static getInstance(): Logger {
+    if (!DefaultLogger.instance) {
+      let defaultConfig: LoggerConfig;
+      try {
+        defaultConfig = {
+          isLoggingEnabled: false,
+          strategy: new PinoLogger(),
+        };
+      } catch (e) {
+        defaultConfig = {
+          isLoggingEnabled: false,
+          strategy: new ConsoleLogger(),
+        };
+      }
+      DefaultLogger.instance = new DefaultLogger(defaultConfig);
+    }
+    return DefaultLogger.instance;
+  }
+
+  /**
+   * Updates the logger configuration dynamically
+   * @param config - Partial configuration to be updated
+   */
+  configure(config: Partial<LoggerConfig>): void {
+    this.config = { ...this.config, ...config };
+  }
+
+  /**
+   * Logs an error message.
+   * @param log The error log entry. Contains the message and error object as required fields and optional args.
+   */
+  error(log: ErrorLog): void {
+    if (!this.config.isLoggingEnabled) return;
+    this.config.strategy.error(log);
+  }
+
+  /**
+   * Logs a debug message.
+   * @param log The debug log entry. Contains the message as required field and optional args.
+   */
+  debug(log: Log): void {
+    if (!this.config.isLoggingEnabled) return;
+    this.config.strategy.debug(log);
+  }
+
+  /**
+   * Logs a trace message.
+   * @param log The trace log entry. Contains the message as required field and optional args.
+   */
+  verbose(log: Log): void {
+    if (!this.config.isLoggingEnabled) return;
+    this.config.strategy.verbose(log);
+  }
+
+  info(log: Log): void {
+    if (!this.config.isLoggingEnabled) return;
+    this.config.strategy.info(log);
+  }
+}
+
+export const logger = DefaultLogger.getInstance();