diff --git a/README.md b/README.md index 9d85404..ef33d94 100644 --- a/README.md +++ b/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 diff --git a/__tests__/integration/index.test.ts b/__tests__/integration/index.test.ts index 96014be..ba8d435 100644 --- a/__tests__/integration/index.test.ts +++ b/__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", () => { diff --git a/__tests__/topaz.ts b/__tests__/topaz.ts index 8e30c2a..766679a 100644 --- a/__tests__/topaz.ts +++ b/__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 ( 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; diff --git a/lib/directory/v3/index.ts b/lib/directory/v3/index.ts index 36e9030..d4e7c10 100644 --- a/lib/directory/v3/index.ts +++ b/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(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; diff --git a/lib/errorHandler.ts b/lib/errorHandler.ts index 3a401ba..76db78b 100644 --- a/lib/errorHandler.ts +++ b/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)}"`, diff --git a/lib/identityContext.ts b/lib/identityContext.ts index 3868817..307cb04 100644 --- a/lib/identityContext.ts +++ b/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 { diff --git a/lib/index.ts b/lib/index.ts index 46064a8..8bed9a9 100644 --- a/lib/index.ts +++ b/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, }; diff --git a/lib/log.ts b/lib/log.ts index e6e1896..44017f6 100644 --- a/lib/log.ts +++ b/lib/log.ts @@ -1,28 +1,56 @@ -const currentLevel = process.env.LOG_LEVEL || "INFO"; +import EventEmitter from "events"; -const logLevels = { - ERROR: 0, - INFO: 1, - DETAIL: 2, -}; +import { JsonValue } from "@bufbuild/protobuf"; + +export enum LOG_EVENT { + DEBUG = "aserto-node-debug", + ERROR = "aserto-node-error", + INFO = "aserto-node-info", + TRACE = "aserto-node-trace", + WARN = "aserto-node-warn", +} + +export const LOG_LEVELS = { + ERROR: 4, + WARN: 3, + INFO: 2, + DEBUG: 1, + TRACE: 0, +} as const; + +class Logger { + eventEmitter: EventEmitter; + + constructor(eventEmitter: EventEmitter = getLogEventEmitter()) { + this.eventEmitter = eventEmitter; + } + + trace(message: JsonValue) { + this.eventEmitter.emit(LOG_EVENT.TRACE, message); + } -const log = (message: string, level = "INFO") => { - const timestamp = new Date().toISOString(); - if (process.env.NODE_TRACE) { - // eslint-disable-next-line no-console - console.trace(`${timestamp} ${level}: ${message}`); - } else { - if (level === "ERROR") { - // eslint-disable-next-line no-console - console.error(`${timestamp} ${level}: ${message}`); - // eslint-disable-next-line @typescript-eslint/ban-ts-comment - /* @ts-ignore */ - //TODO: Remove this ts-ignore - } else if (logLevels[level] <= logLevels[currentLevel]) { - // eslint-disable-next-line no-console - console.log(`${timestamp} ${level}: aserto-node: ${message}`); - } + info(message: JsonValue) { + this.eventEmitter.emit(LOG_EVENT.INFO, message); } + debug(message: JsonValue) { + this.eventEmitter.emit(LOG_EVENT.DEBUG, message); + } + + warn(message: JsonValue) { + this.eventEmitter?.emit(LOG_EVENT.WARN, message); + } + + error(message: JsonValue) { + this.eventEmitter.emit(LOG_EVENT.ERROR, message); + } +} + +const logEventEmitter = new EventEmitter(); +let logger = new Logger(logEventEmitter); +const setLogEventEmitter = (eventEmitter?: EventEmitter) => { + logger = new Logger(eventEmitter || logEventEmitter); }; -export { log }; +export const getLogEventEmitter = () => logEventEmitter; + +export { logger, setLogEventEmitter }; diff --git a/lib/processOptions.ts b/lib/processOptions.ts index 2cbebd7..1b3e02b 100644 --- a/lib/processOptions.ts +++ b/lib/processOptions.ts @@ -3,7 +3,7 @@ import express from "express"; import { IdentityContextOptions } from "./identityContext"; import { AuthzOptions } from "./jwtAuthz"; -import { log } from "./log"; +import { logger } from "./log"; export default ( options: AuthzOptions, @@ -22,7 +22,7 @@ export default ( message: `aserto-node: ${err_message}`, }); } - log(err_message, "ERROR"); + logger.error(err_message); res.status(403).send(err_message); }; diff --git a/lib/util/connect.ts b/lib/util/connect.ts index d0d2bcb..a0eb31d 100644 --- a/lib/util/connect.ts +++ b/lib/util/connect.ts @@ -14,7 +14,7 @@ import { NotFoundError, UnauthenticatedError, } from "../errors"; -import { log } from "../log"; +import { logger } from "../log"; export const setHeader = ( req: @@ -27,15 +27,13 @@ export const setHeader = ( }; export const traceMessage: Interceptor = (next) => async (req) => { - log( - JSON.stringify({ - message: req.message, - method: req.method.toString(), - requestMethod: req.requestMethod.toString(), - service: req.service.toString(), - url: req.url.toString(), - }), - ); + logger.debug({ + message: JSON.parse(JSON.stringify(req.message)), + method: req.method.toString(), + requestMethod: req.requestMethod.toString(), + service: req.service.toString(), + url: req.url.toString(), + }); return await next(req); }; diff --git a/package.json b/package.json index fe115ed..1a25049 100644 --- a/package.json +++ b/package.json @@ -72,6 +72,7 @@ "knip": "^5.45.0", "njwt": "^2.0.1", "node-mocks-http": "^1.16.2", + "pino": "^9.6.0", "prettier": "^3.5.3", "supertest": "^7.0.0", "ts-jest": "^29.2.6", diff --git a/yarn.lock b/yarn.lock index 0a50b37..ea679f3 100644 --- a/yarn.lock +++ b/yarn.lock @@ -45,6 +45,7 @@ __metadata: knip: "npm:^5.45.0" njwt: "npm:^2.0.1" node-mocks-http: "npm:^1.16.2" + pino: "npm:^9.6.0" prettier: "npm:^3.5.3" supertest: "npm:^7.0.0" ts-jest: "npm:^29.2.6" @@ -1608,6 +1609,13 @@ __metadata: languageName: node linkType: hard +"atomic-sleep@npm:^1.0.0": + version: 1.0.0 + resolution: "atomic-sleep@npm:1.0.0" + checksum: 10/3ab6d2cf46b31394b4607e935ec5c1c3c4f60f3e30f0913d35ea74b51b3585e84f590d09e58067f11762eec71c87d25314ce859030983dc0e4397eed21daa12e + languageName: node + linkType: hard + "babel-jest@npm:^29.7.0": version: 29.7.0 resolution: "babel-jest@npm:29.7.0" @@ -2687,6 +2695,13 @@ __metadata: languageName: node linkType: hard +"fast-redact@npm:^3.1.1": + version: 3.5.0 + resolution: "fast-redact@npm:3.5.0" + checksum: 10/24b27e2023bd5a62f908d97a753b1adb8d89206b260f97727728e00b693197dea2fc2aa3711147a385d0ec6e713569fd533df37a4ef947e08cb65af3019c7ad5 + languageName: node + linkType: hard + "fast-safe-stringify@npm:^2.1.1": version: 2.1.1 resolution: "fast-safe-stringify@npm:2.1.1" @@ -4439,6 +4454,13 @@ __metadata: languageName: node linkType: hard +"on-exit-leak-free@npm:^2.1.0": + version: 2.1.2 + resolution: "on-exit-leak-free@npm:2.1.2" + checksum: 10/f7b4b7200026a08f6e4a17ba6d72e6c5cbb41789ed9cf7deaf9d9e322872c7dc5a7898549a894651ee0ee9ae635d34a678115bf8acdfba8ebd2ba2af688b563c + languageName: node + linkType: hard + "on-finished@npm:2.4.1": version: 2.4.1 resolution: "on-finished@npm:2.4.1" @@ -4661,6 +4683,43 @@ __metadata: languageName: node linkType: hard +"pino-abstract-transport@npm:^2.0.0": + version: 2.0.0 + resolution: "pino-abstract-transport@npm:2.0.0" + dependencies: + split2: "npm:^4.0.0" + checksum: 10/e5699ecb06c7121055978e988e5cecea5b6892fc2589c64f1f86df5e7386bbbfd2ada268839e911b021c6b3123428aed7c6be3ac7940eee139556c75324c7e83 + languageName: node + linkType: hard + +"pino-std-serializers@npm:^7.0.0": + version: 7.0.0 + resolution: "pino-std-serializers@npm:7.0.0" + checksum: 10/884e08f65aa5463d820521ead3779d4472c78fc434d8582afb66f9dcb8d8c7119c69524b68106cb8caf92c0487be7794cf50e5b9c0383ae65b24bf2a03480951 + languageName: node + linkType: hard + +"pino@npm:^9.6.0": + version: 9.6.0 + resolution: "pino@npm:9.6.0" + dependencies: + atomic-sleep: "npm:^1.0.0" + fast-redact: "npm:^3.1.1" + on-exit-leak-free: "npm:^2.1.0" + pino-abstract-transport: "npm:^2.0.0" + pino-std-serializers: "npm:^7.0.0" + process-warning: "npm:^4.0.0" + quick-format-unescaped: "npm:^4.0.3" + real-require: "npm:^0.2.0" + safe-stable-stringify: "npm:^2.3.1" + sonic-boom: "npm:^4.0.1" + thread-stream: "npm:^3.0.0" + bin: + pino: bin.js + checksum: 10/0a36125718dc2350bbaff243e4856108a80805dc1b305da1e246460cd22396d11a8b3a78b39b0b270cce4fb8ae6aa6e584f5387f6c2ee47348aae5db49d919e6 + languageName: node + linkType: hard + "pirates@npm:^4.0.4": version: 4.0.6 resolution: "pirates@npm:4.0.6" @@ -4729,6 +4788,13 @@ __metadata: languageName: node linkType: hard +"process-warning@npm:^4.0.0": + version: 4.0.1 + resolution: "process-warning@npm:4.0.1" + checksum: 10/8b0ec9129845215c1e4a72f3a66082e3aa76f81e265374de6c70f2213f4516856316ed88338b8520e9274dab947d6b3750684b448f45148f57757f365e96793f + languageName: node + linkType: hard + "promise-retry@npm:^2.0.1": version: 2.0.1 resolution: "promise-retry@npm:2.0.1" @@ -4798,6 +4864,13 @@ __metadata: languageName: node linkType: hard +"quick-format-unescaped@npm:^4.0.3": + version: 4.0.4 + resolution: "quick-format-unescaped@npm:4.0.4" + checksum: 10/591eca457509a99368b623db05248c1193aa3cedafc9a077d7acab09495db1231017ba3ad1b5386e5633271edd0a03b312d8640a59ee585b8516a42e15438aa7 + languageName: node + linkType: hard + "range-parser@npm:^1.2.0, range-parser@npm:~1.2.1": version: 1.2.1 resolution: "range-parser@npm:1.2.1" @@ -4824,6 +4897,13 @@ __metadata: languageName: node linkType: hard +"real-require@npm:^0.2.0": + version: 0.2.0 + resolution: "real-require@npm:0.2.0" + checksum: 10/ddf44ee76301c774e9c9f2826da8a3c5c9f8fc87310f4a364e803ef003aa1a43c378b4323051ced212097fff1af459070f4499338b36a7469df1d4f7e8c0ba4c + languageName: node + linkType: hard + "require-directory@npm:^2.1.1": version: 2.1.1 resolution: "require-directory@npm:2.1.1" @@ -4928,6 +5008,13 @@ __metadata: languageName: node linkType: hard +"safe-stable-stringify@npm:^2.3.1": + version: 2.5.0 + resolution: "safe-stable-stringify@npm:2.5.0" + checksum: 10/2697fa186c17c38c3ca5309637b4ac6de2f1c3d282da27cd5e1e3c88eca0fb1f9aea568a6aabdf284111592c8782b94ee07176f17126031be72ab1313ed46c5c + languageName: node + linkType: hard + "safer-buffer@npm:>= 2.1.2 < 3, safer-buffer@npm:>= 2.1.2 < 3.0.0": version: 2.1.2 resolution: "safer-buffer@npm:2.1.2" @@ -5120,6 +5207,15 @@ __metadata: languageName: node linkType: hard +"sonic-boom@npm:^4.0.1": + version: 4.2.0 + resolution: "sonic-boom@npm:4.2.0" + dependencies: + atomic-sleep: "npm:^1.0.0" + checksum: 10/385ef7fb5ea5976c1d2a1fef0b6df8df6b7caba8696d2d67f689d60c05e3ea2d536752ce7e1c69b9fad844635f1036d07c446f8e8149f5c6a80e0040a455b310 + languageName: node + linkType: hard + "source-map-support@npm:0.5.13": version: 0.5.13 resolution: "source-map-support@npm:0.5.13" @@ -5137,6 +5233,13 @@ __metadata: languageName: node linkType: hard +"split2@npm:^4.0.0": + version: 4.2.0 + resolution: "split2@npm:4.2.0" + checksum: 10/09bbefc11bcf03f044584c9764cd31a252d8e52cea29130950b26161287c11f519807c5e54bd9e5804c713b79c02cefe6a98f4688630993386be353e03f534ab + languageName: node + linkType: hard + "sprintf-js@npm:^1.1.3": version: 1.1.3 resolution: "sprintf-js@npm:1.1.3" @@ -5355,6 +5458,15 @@ __metadata: languageName: node linkType: hard +"thread-stream@npm:^3.0.0": + version: 3.1.0 + resolution: "thread-stream@npm:3.1.0" + dependencies: + real-require: "npm:^0.2.0" + checksum: 10/ea2d816c4f6077a7062fac5414a88e82977f807c82ee330938fb9691fe11883bb03f078551c0518bb649c239e47ba113d44014fcbb5db42c5abd5996f35e4213 + languageName: node + linkType: hard + "tmpl@npm:1.0.5": version: 1.0.5 resolution: "tmpl@npm:1.0.5"