feat: Add NODE_DEBUG-style logging to Favro API requests, allowing de…

…vs to opt into a ton of info for triangulating request issues.

README.md

@@ -78,15 +78,16 @@ const bravoClient = new BravoClient({
    6. [Add a Card Attachment](#add-a-card-attachment)
    7. [Validate a Webhook Signature](#validate-a-webhook-signature)
    8. [Ensure up-to-date data (clear caches)](#ensure-up-to-date-data-clear-caches)
-7. [The Favro Data Model](#the-favro-data-model)
+7. [Debugging](#debugging)
+8. [The Favro Data Model](#the-favro-data-model)
    1. [Collections](#collections)
    2. [Widgets (a.k.a. "Boards")](#widgets-aka-boards)
    3. [Columns (a.k.a. "Board Statuses")](#columns-aka-board-statuses)
    4. [Cards](#cards)
    5. [Built-In Card Fields](#built-in-card-fields)
    6. [Custom Fields](#custom-fields)
    7. [Webhooks (Outgoing)](#webhooks-outgoing)
-8. [Tips, Tricks, and Limitations](#tips-tricks-and-limitations)
+9. [Tips, Tricks, and Limitations](#tips-tricks-and-limitations)
    1. [API rate limits are very low](#api-rate-limits-are-very-low)
    2. [Search options are extremely limited](#search-options-are-extremely-limited)
    3. [Webhooks used by Automations have incomplete data](#webhooks-used-by-automations-have-incomplete-data)
@@ -293,6 +294,21 @@ await card.refresh();
 ```
 
 
+
+## Debugging
+
+To help diagnose problems in various contexts, Bravo provides a few useful mechanisms for logging.
+
+- **Custom Errors:** If you have a custom Error class you want to use instead of the Bravo one (e.g. if your error class is hooked up to your logging utilities), you can provide that class as an option when setting up your `BravoClient`.
+- **Custom Console:** If you have a custom drop-in replacement for Node's `console` object, you can also provide that object as an option when setting up your `BravoClient`. You can use this with custom loggers, or to divert logs to a file or other I/O mechanism.
+- **DEBUG:** In addition to regular logging (for warnings, errors, and info), you can get more verbose logging by setting the `DEBUG` environment variable. Bravo uses the popular [debug](https://www.npmjs.com/package/debug) package for this, with the following namespaces:
+  - `bravo:*`: Everything below.
+  - `bravo:http:*`: HTTP requests and responses (maximally verbose)
+  - `bravo:http:basic`: HTTP requests and responses (simple summaries of requests and responses, like URLs, methods, and status codes)
+  - `bravo:http:headers`: Request and response headers (WARNING: will include your API Token!)
+  - `bravo:http:bodies`: Request and response bodies (extremely verbose)
+  - `bravo:http:stats`: Summary of requests made, logged after each request, including Favro API rate limit information.
+
 ## The Favro Data Model
 
 The Favro API gives us access to some of the underlying data models used by Favro. While not exactly *unintuitive*, it is tricky to figure out how everything works together and what Favro's terms and names mean.

load-env.js

@@ -0,0 +1,2 @@
+const dotenv = require('dotenv');
+dotenv.config();

package.json

@@ -24,7 +24,7 @@
     "build/types/**/*"
   ],
   "scripts": {
-    "test": "npm run build && mocha --inspect --require source-map-support/register --bail --timeout 6000 ./build/test/",
+    "test": "npm run build && mocha --inspect --require source-map-support/register --bail --timeout 6000 --require ./load-env.js ./build/test/",
     "build": "rimraf build && tsc && tsc-alias",
     "preversion": "npm run lint && npm run build && npm test",
     "version": "conventional-changelog -p angular -i CHANGELOG.md -s -r 0 && npm run format && git add -A",
@@ -35,11 +35,13 @@
   },
   "license": "MIT",
   "dependencies": {
+    "debug": "^4.3.2",
     "node-fetch": "^2.6.1"
   },
   "devDependencies": {
     "@microsoft/api-extractor": "^7.18.7",
     "@types/chai": "^4.2.21",
+    "@types/debug": "^4.1.7",
     "@types/mocha": "^9.0.0",
     "@types/node": "^16.6.2",
     "@types/node-fetch": "^2.5.12",

src/lib/Logger.ts

@@ -0,0 +1,65 @@
+import type { AnyFunction } from '$/types/Utility.js';
+import debug from 'debug';
+import { sortPaths } from './utility.js';
+
+const requiredLogLevels = ['log', 'error'] as const;
+const optionalLogLevels = ['info', 'trace', 'warn', 'dir'] as const;
+
+type RequiredLogLevel = typeof requiredLogLevels[number];
+type OptionalLogLevel = typeof optionalLogLevels[number];
+
+export type LoggerUtility = {
+  [OptionalLoggerName in OptionalLogLevel]?: AnyFunction;
+} &
+  {
+    [RequiredLoggerName in RequiredLogLevel]: AnyFunction;
+  };
+
+export class Logger {
+  private static _debuggers: { [namePath: string]: debug.Debugger } = {};
+  private static _utility: LoggerUtility = console;
+
+  private static _debuggerPaths: Set<string> = new Set();
+
+  /**
+   * Always log something using the provided logging utility's `log` method,
+   * without using `DEBUG` environment variable settings.
+   */
+  static log(...args: any[]) {
+    Logger._utility.log.bind(Logger._utility)(...args);
+  }
+
+  /**
+   * Always log something using the provided logging utility's `warn` method,
+   * without using `DEBUG` environment variable settings.
+   */
+  static warn(...args: any[]) {
+    (Logger._utility.warn || Logger._utility.error).bind(Logger._utility)(
+      ...args,
+    );
+  }
+
+  /**
+   * Always log something using the provided logging utility's `error` method,
+   * without using `DEBUG` environment variable settings.
+   */
+  static error(...args: any[]) {
+    Logger._utility.error.bind(Logger._utility)(...args);
+  }
+
+  static getDebugLogger(path: string, parentPath?: string) {
+    const fullPath = parentPath ? `${parentPath}:${path}` : path;
+    this._debuggers[fullPath] ||= debug(fullPath);
+    this._debuggers[fullPath].log = Logger.log;
+    this._debuggerPaths.add(fullPath);
+    return this._debuggers[fullPath];
+  }
+
+  static set loggingUtility(utility: LoggerUtility) {
+    Logger._utility = utility;
+  }
+
+  static get debugPaths() {
+    return sortPaths([...this._debuggerPaths], ':');
+  }
+}

src/lib/clientLib/FavroClient.ts

@@ -3,7 +3,7 @@ import fetch from 'node-fetch';
 import { URL } from 'url';
 import { FavroResponse } from '$lib/clientLib/FavroResponse';
 import { isNullish, toBase64 } from '$lib/utility.js';
-import type { AnyFunction } from '$/types/Utility.js';
+import { Logger, LoggerUtility } from '../Logger';
 
 type OptionFavroHttpMethod = 'get' | 'post' | 'put' | 'delete';
 
@@ -92,14 +92,6 @@ export interface FavroClientAuth {
   userEmail: string;
 }
 
-export type Logger = {
-  log?: AnyFunction;
-  error: AnyFunction;
-  info: AnyFunction;
-  trace?: AnyFunction;
-  warn: AnyFunction;
-};
-
 export class FavroClient {
   protected _token!: string;
   protected _organizationId!: string;
@@ -121,8 +113,6 @@ export class FavroClient {
   private _backendId?: string;
   private _fetch = fetch;
 
-  private _logger: Logger;
-
   readonly error = BravoError;
 
   /**
@@ -134,13 +124,13 @@ export class FavroClient {
     options?: FavroClientAuth,
     extendedOptions?: {
       customFetch?: typeof fetch;
-      logger?: Logger;
+      logger?: LoggerUtility;
       /** Optionally use a custom Error class */
       error?: typeof BravoError;
     },
   ) {
     this.error = extendedOptions?.error || BravoError;
-    this._logger = extendedOptions?.logger || console;
+    Logger.loggingUtility = extendedOptions?.logger || console;
     for (const [optionsName, envName] of [
       ['token', 'FAVRO_TOKEN'],
       ['userEmail', 'FAVRO_USER_EMAIL'],
@@ -191,14 +181,19 @@ export class FavroClient {
      */
     customFetch?: Fetcher,
   ) {
+    const debugBase = `bravo:http:`;
+    const debugBasic = Logger.getDebugLogger(`${debugBase}basic`);
+    const debugHeaders = Logger.getDebugLogger(`${debugBase}headers`);
+    const debugBodies = Logger.getDebugLogger(`${debugBase}bodies`);
+    const debugStats = Logger.getDebugLogger(`${debugBase}stats`);
     this.assert(
       this._organizationId || !options?.requireOrganizationId,
       'An organizationId must be set for this request',
     );
     const method = options?.method || 'get';
     throwIfBodyAndMethodIncompatible(method, options?.body);
     // Ensure initial slash
-    url = createFavroApiUrl(url, options?.query);
+    const fullUrl = createFavroApiUrl(url, options?.query);
     const { contentType, body } = computeBodyProps(options?.body);
     const headers = cleanHeaders({
       Host: 'favro.com', // Required by API (otherwise fails without explanation)
@@ -212,36 +207,43 @@ export class FavroClient {
       'X-Favro-Backend-Identifier': options?.backendId || this._backendId!,
     });
     this._requestsMade++;
-    const rawResponse = await (customFetch || this._fetch)(url, {
+    const reqOptions = {
       method,
       headers, // Force it to assume no undefineds
       body,
-    });
+    };
+    debugBasic(`sent ${method.toUpperCase()} ${url}`);
+    debugHeaders(`sent %O`, headers);
+    debugBodies(`sent %O`, body);
+    const rawResponse = await (customFetch || this._fetch)(fullUrl, reqOptions);
     const res = new FavroResponse<Data, this>(this, rawResponse);
     this._backendId = res.backendId || this._backendId;
     this._limitResetsAt = res.limitResetsAt;
     this._requestsLimit = res.limit;
     this._requestsRemaining = res.requestsRemaining;
-
+    const requestStats = {
+      status: res.status,
+      remaining: this._requestsRemaining,
+      made: this._requestsMade,
+      limit: res.limit,
+      resetAt: this._limitResetsAt,
+    };
+    debugBasic(`got ${res.status} ${res.contentType} %o`, requestStats);
+    debugHeaders(`got %O`, headers);
+    debugBodies(`got %O`, body);
+    debugStats(`%O`, requestStats);
     if (this._requestsRemaining < 1 || res.status == 429) {
       // TODO: Set an interval before allowing requests to go through again, OR SOMETHING
-      this._requestsRemaining = 0;
-      this._logger.warn(
+      Logger.warn(
         `Favro API rate limit reached! ${JSON.stringify(
-          {
-            status: res.status,
-            remaining: this._requestsRemaining,
-            made: this._requestsMade,
-            limit: res.limit,
-            resetAt: this._limitResetsAt,
-          },
+          requestStats,
           null,
           2,
         )}`,
       );
     }
     if (res.status > 299) {
-      this._logger.error(`Favro API Error: ${res.status}`, {
+      Logger.error(`Favro API Error: ${res.status}`, {
         url,
         method,
         body: await rawResponse.text(),
@@ -256,7 +258,7 @@ export class FavroClient {
     ) {
       // @ts-expect-error
       const message = parsedBody.message;
-      throw new BravoError(
+      throw new this.error(
         `Unexpected combo of status code (${res.status}) and response body ("${message}")`,
       );
     }

src/lib/clientLib/FavroResponse.ts

@@ -82,12 +82,15 @@ export class FavroResponse<
     );
   }
 
+  get contentType() {
+    return this._response.headers.get('Content-Type');
+  }
+
   async getParsedBody() {
     if (typeof this._parsedBody != 'undefined') {
       return this._parsedBody;
     }
-    const type = this._response.headers.get('Content-Type');
-    if (!type?.startsWith('application/json')) {
+    if (!this.contentType?.startsWith('application/json')) {
       this._parsedBody = null;
       return this._parsedBody;
     }

src/lib/utility.ts

@@ -328,3 +328,16 @@ export function stringToNumber(
     `Cannot convert ${string} to a number`,
   );
 }
+
+export function sortPaths(paths: string[], delimiter: string) {
+  return paths.sort((a, b) => {
+    const aParts = a.split(delimiter);
+    const bParts = b.split(delimiter);
+    for (let i = 0; i < aParts.length; i++) {
+      if (aParts[i] !== bParts[i]) {
+        return aParts[i].localeCompare(bParts[i], 'en', { numeric: true });
+      }
+    }
+    return 0;
+  });
+}

src/test/client.test.ts

@@ -31,7 +31,6 @@
 
 import { BravoClient } from '$lib/BravoClient.js';
 import { expect } from 'chai';
-import dotenv from 'dotenv';
 import fetch from 'node-fetch';
 import type { BravoCollection } from '$entities/BravoCollection.js';
 import type { BravoWidget } from '$entities/BravoWidget.js';
@@ -53,7 +52,6 @@ import type { BravoGroup } from '$/types/Bravo.js';
  * @remarks A root .env file must be populated with the required
  * env vars in order to run tests!
  */
-dotenv.config();
 const organizationId = process.env.FAVRO_ORGANIZATION_ID!;
 const myUserEmail = process.env.FAVRO_USER_EMAIL!;