Merge pull request #118 from aserto-dev/logger

add a event based logging mechanism

Author: gimmyxd

README.md

@@ -818,6 +818,47 @@ const json = toJson(GetObjectsResponseSchema, objects)
 ```
 
 
+## Custom Logging
+aserto-node publishes log events using the Node.js [Event emitter](https://nodejs.org/en/learn/asynchronous-work/the-nodejs-event-emitter#the-nodejs-event-emitter).
+The events for each log level are defined as:
+```ts
+export enum LOG_EVENT {
+  DEBUG = "aserto-node-debug",
+  ERROR = "aserto-node-error",
+  INFO  = "aserto-node-info",
+  TRACE = "aserto-node-trace",
+  WARN  = "aserto-node-warn",
+}
+```
+Consumers can register a function when any of these events are triggered and handle the logging.
+```ts
+import { LOG_EVENT, setLogEventEmitter } from '@aserto/aserto-node'
+
+// create a new Event emitter
+const emitter = new EventEmitter()
+
+// configure aserto-node to use the emitter
+setLogEventEmitter(emitter)
+
+// handle aserto-node log events
+emitter.on(LOG_EVENT.TRACE, (message) => {
+  log.trace(message)
+})
+emitter.on(LOG_EVENT.DEBUG, (message) => {
+  log.debug(message)
+})
+
+emitter.on(LOG_EVENT.INFO, (message) => {
+  log.info(message)
+})
+emitter.on(LOG_EVENT.WARN, (message) => {
+  log.warn(message)
+})
+emitter.on(LOG_EVENT.ERROR, (message) => {
+  log.error(message)
+})
+```
+
 
 ## Deprecated Methods
 

__tests__/integration/index.test.ts

@@ -1,6 +1,8 @@
+import { EventEmitter } from "events";
 import express, { Express, Request, Response } from "express";
 import nJwt from "njwt";
 import { describe } from "node:test";
+import pino from "pino";
 import request from "supertest";
 
 import {
@@ -15,12 +17,14 @@ import {
   HEADER_ASERTO_MANIFEST_REQUEST,
   ImportMsgCase,
   ImportOpCode,
+  LOG_EVENT,
   MANIFEST_REQUEST_DEFAULT,
   NotFoundError,
   policyContext,
   policyInstance,
   readAsyncIterable,
   serializeAsyncIterable,
+  setLogEventEmitter,
 } from "../../lib";
 import { Topaz, TOPAZ_TIMEOUT } from "../topaz";
 
@@ -1716,6 +1720,59 @@ types:
         }),
       ).rejects.toThrow(NotFoundError);
     });
+
+    describe("logging", () => {
+      beforeAll(() => {
+        process.env.NODE_TRACE_MESSAGE = "true";
+        const log = pino(
+          {
+            name: "aserto-node",
+            timestamp: pino.stdTimeFunctions.isoTime,
+            level: "debug",
+            formatters: {
+              level: (label) => {
+                return { level: label };
+              },
+            },
+          },
+          pino.multistream(
+            [
+              { level: "trace", stream: process.stdout },
+              { level: "debug", stream: process.stdout },
+              { level: "info", stream: process.stdout },
+              { level: "warn", stream: process.stdout },
+              { level: "error", stream: process.stderr },
+              { level: "fatal", stream: process.stderr },
+            ],
+            {
+              levels: pino.levels.values,
+              dedupe: true,
+            },
+          ),
+        );
+        const eventEmitter = new EventEmitter();
+        setLogEventEmitter(eventEmitter);
+
+        eventEmitter.on(LOG_EVENT.DEBUG, (msg) => {
+          log.debug(msg);
+        });
+      });
+
+      afterAll(() => {
+        process.env.NODE_TRACE_MESSAGE = undefined;
+        setLogEventEmitter(undefined);
+      });
+
+      it("allows a custom logger", async () => {
+        const config = {
+          url: "localhost:9292",
+          caFile: await topaz.caCert(),
+        };
+
+        const directory = DirectoryServiceV3(config);
+        directory.objects({ objectType: "user" });
+      });
+    });
   });
 
   describe("Authorizer", () => {

__tests__/topaz.ts

@@ -2,7 +2,7 @@ import fs from "fs";
 import util from "node:util";
 
 import { DirectoryServiceV3 } from "../lib";
-import { log } from "../lib/log";
+import { logger } from "../lib/log";
 
 // eslint-disable-next-line @typescript-eslint/no-require-imports
 const exec = util.promisify(require("node:child_process").exec);
@@ -17,11 +17,11 @@ export class Topaz {
     const certsDir = await this.caCert();
 
     await retry(async () => fs.readFileSync(certsDir), RETRY_OPTIONS);
-    log("certificates are ready");
+    logger.debug("certificates are ready");
 
     await execute("topaz config info");
 
-    log(`topaz start with ${certsDir}`);
+    logger.debug(`topaz start with ${certsDir}`);
 
     const directoryClient = DirectoryServiceV3({
       url: "localhost:9292",
@@ -63,11 +63,11 @@ const retry = async <T>(
   try {
     return await fn();
   } catch (error) {
-    log((error as Error).message);
+    logger.debug((error as Error).message);
     if (retries <= 0) {
       throw error;
     }
-    log(`Retrying...`);
+    logger.debug(`Retrying...`);
     await sleep(retryIntervalMs);
     return retry(fn, { retries: retries - 1, retryIntervalMs });
   }
@@ -77,11 +77,11 @@ const sleep = (ms = 0) => new Promise((resolve) => setTimeout(resolve, ms));
 const execute = async (command: string) => {
   const { error, stdout, stderr } = await exec(command);
   if (error) {
-    log(`error: ${error.message}`);
+    logger.debug(`error: ${error.message}`);
     return;
   }
   if (stderr) {
-    log(`stderr: ${stderr}`);
+    logger.debug(`stderr: ${stderr}`);
     return;
   }
   return stdout;

lib/directory/v3/index.ts

@@ -47,7 +47,7 @@ import {
 import { createGrpcTransport } from "@connectrpc/connect-node";
 import { createAsyncIterable as createAsyncIterable$ } from "@connectrpc/connect/protocol";
 
-import { log } from "../../log";
+import { logger } from "../../log";
 import {
   handleError,
   setCustomHeaders,
@@ -651,7 +651,7 @@ export class DirectoryV3 {
  * @param {T[]} items - The array of items to iterate over.
  */
 export async function* createAsyncIterable<T>(items: T[]) {
-  log("[Deprecated]: please use `createImportRequest`");
+  logger.warn("[Deprecated]: please use `createImportRequest`");
   yield* createImportRequest(items as ImportRequest$[]);
 }
 
@@ -678,7 +678,7 @@ export async function* createImportRequest(params: ImportRequest$[]) {
  * @returns The converted Protobuf Struct.
  */
 export function objectPropertiesAsStruct(value: JsonObject): JsonObject {
-  log(
+  logger.warn(
     "[Deprecated]: This version of SDK does not require conversion from JSON to Struct. Use the value directly",
   );
   return value;

lib/errorHandler.ts

@@ -1,6 +1,6 @@
 import { NextFunction, Response } from "express";
 
-import { log } from "./log";
+import { logger } from "./log";
 
 const errorHandler =
   (next: NextFunction, failWithError: boolean) =>
@@ -13,7 +13,7 @@ const errorHandler =
           message: `aserto-node: ${err_message}`,
         });
       }
-      log(err_message, "ERROR");
+      logger.error(err_message);
       res.append(
         "WWW-Authenticate",
         `Bearer error="${encodeURIComponent(err_message)}"`,

lib/identityContext.ts

@@ -5,7 +5,7 @@ import { jwtDecode } from "jwt-decode";
 import { IdentityType } from "@aserto/node-authorizer/src/gen/cjs/aserto/authorizer/v2/api/identity_context_pb";
 
 import identityContext from "./authorizer/model/identityContext";
-import { log } from "./log";
+import { logger } from "./log";
 
 export interface IdentityContextOptions {
   useAuthorizationHeader: boolean;
@@ -36,11 +36,11 @@ export default (req: express.Request, options: IdentityContextOptions) => {
         : "";
 
       type = "JWT";
-
-      // eslint-disable-next-line @typescript-eslint/no-unused-vars
     } catch (error) {
-      // TODO: resolve error type ${error.message}
-      log(`Authorization header contained malformed JWT:`, "ERROR");
+      logger.error(
+        `Authorization header contained malformed JWT: ${(error as Error).message}`,
+      );
+
       type = "NONE";
     }
   } else {

lib/index.ts

@@ -1,4 +1,5 @@
 import { Opcode } from "@aserto/node-directory/src/gen/cjs/aserto/directory/importer/v3/importer_pb";
+import { JsonValue } from "@bufbuild/protobuf";
 
 import { Authorizer, authz } from "./authorizer";
 import AnonymousIdentityMapper from "./authorizer/mapper/identity/anonymous";
@@ -31,6 +32,56 @@ import { CustomHeaders, DirectoryV3Config } from "./directory/v3/types";
 import { displayStateMap } from "./displayStateMap";
 import { is } from "./is";
 import { AuthzOptions, jwtAuthz } from "./jwtAuthz";
+import {
+  getLogEventEmitter,
+  LOG_EVENT,
+  LOG_LEVELS,
+  setLogEventEmitter,
+} from "./log";
+
+type LogLevel = keyof typeof LOG_LEVELS;
+const currentLevel = LOG_LEVELS[(process.env.LOG_LEVEL || "INFO") as LogLevel];
+
+const log = (message: JsonValue, level: number = LOG_LEVELS.INFO) => {
+  const timestamp = new Date().toISOString();
+  if (process.env.NODE_TRACE) {
+    // eslint-disable-next-line no-console
+    console.trace(`${timestamp} ${level}: ${JSON.stringify(message)}`);
+  } else {
+    if (level === LOG_LEVELS.ERROR) {
+      // eslint-disable-next-line no-console
+      console.error(`${timestamp} ${level}: ${JSON.stringify(message)}`);
+    } else if (level >= currentLevel) {
+      // eslint-disable-next-line no-console
+      console.log(
+        `${timestamp} ${level}: aserto-node: ${JSON.stringify(message)}`,
+      );
+    }
+  }
+};
+
+const logEventEmitter = getLogEventEmitter();
+
+logEventEmitter.on(LOG_EVENT.DEBUG, (message) => {
+  log(message, LOG_LEVELS.DEBUG);
+});
+
+logEventEmitter.on(LOG_EVENT.ERROR, (message) => {
+  log(message, LOG_LEVELS.ERROR);
+});
+
+logEventEmitter.on(LOG_EVENT.INFO, (message) => {
+  log(message, LOG_LEVELS.INFO);
+});
+
+logEventEmitter.on(LOG_EVENT.TRACE, (message) => {
+  log(message, LOG_LEVELS.TRACE);
+});
+
+logEventEmitter.on(LOG_EVENT.WARN, (message) => {
+  log(message, LOG_LEVELS.WARN);
+});
+
 export {
   AnonymousIdentityMapper,
   Authorizer,
@@ -51,6 +102,8 @@ export {
   is,
   jwtAuthz,
   JWTIdentityMapper,
+  LOG_EVENT,
+  logEventEmitter,
   MANIFEST_REQUEST_DEFAULT,
   MANIFEST_REQUEST_METADATA_ONLY,
   MANIFEST_REQUEST_MODEL_ONLY,
@@ -65,6 +118,7 @@ export {
   queryOptions,
   readAsyncIterable,
   serializeAsyncIterable,
+  setLogEventEmitter,
   SubIdentityMapper,
 };