diff --git a/analyze/index.ts b/analyze/index.ts index 9dfeff477..f9b798db8 100644 --- a/analyze/index.ts +++ b/analyze/index.ts @@ -1,4 +1,4 @@ -import logger from "@arcjet/logger"; +import type { ArcjetLogger } from "@arcjet/protocol"; import * as core from "./wasm/arcjet_analyze_js_req.component.js"; import type { @@ -8,6 +8,10 @@ import type { BotType, } from "./wasm/arcjet_analyze_js_req.component.js"; +interface AnalyzeContext { + log: ArcjetLogger; +} + // TODO: Do we actually need this wasmCache or does `import` cache correctly? const wasmCache = new Map(); @@ -73,22 +77,24 @@ async function moduleFromPath(path: string): Promise { throw new Error(`Unknown path: ${path}`); } -const coreImports: ImportObject = { - "arcjet:js-req/logger": { - debug(msg) { - logger.debug(msg); +async function init(context: AnalyzeContext) { + const { log } = context; + + const coreImports: ImportObject = { + "arcjet:js-req/logger": { + debug(msg) { + log.debug(msg); + }, + error(msg) { + log.error(msg); + }, }, - error(msg) { - logger.error(msg); - }, - }, -}; + }; -async function init() { try { return core.instantiate(moduleFromPath, coreImports); } catch { - logger.debug("WebAssembly is not supported in this runtime"); + log.debug("WebAssembly is not supported in this runtime"); } } @@ -116,12 +122,15 @@ export { * @param ip - The IP address of the client. * @returns A SHA-256 string fingerprint. */ -export async function generateFingerprint(ip: string): Promise { +export async function generateFingerprint( + context: AnalyzeContext, + ip: string, +): Promise { if (ip == "") { return ""; } - const analyze = await init(); + const analyze = await init(context); if (typeof analyze !== "undefined") { return analyze.generateFingerprint(ip); @@ -155,10 +164,11 @@ export async function generateFingerprint(ip: string): Promise { } export async function isValidEmail( + context: AnalyzeContext, candidate: string, options?: EmailValidationConfig, ) { - const analyze = await init(); + const analyze = await init(context); if (typeof analyze !== "undefined") { return analyze.isValidEmail(candidate, options); @@ -169,11 +179,12 @@ export async function isValidEmail( } export async function detectBot( + context: AnalyzeContext, headers: string, patterns_add: string, patterns_remove: string, ): Promise { - const analyze = await init(); + const analyze = await init(context); if (typeof analyze !== "undefined") { return analyze.detectBot(headers, patterns_add, patterns_remove); diff --git a/analyze/package.json b/analyze/package.json index 8c7dd1351..cd1133fe6 100644 --- a/analyze/package.json +++ b/analyze/package.json @@ -46,7 +46,7 @@ "./wasm/arcjet_analyze_js_req_bg.js" ], "dependencies": { - "@arcjet/logger": "1.0.0-alpha.13" + "@arcjet/protocol": "1.0.0-alpha.13" }, "devDependencies": { "@arcjet/eslint-config": "1.0.0-alpha.13", diff --git a/arcjet/index.ts b/arcjet/index.ts index ef730c415..93d56a365 100644 --- a/arcjet/index.ts +++ b/arcjet/index.ts @@ -21,6 +21,7 @@ import { ArcjetFixedWindowRateLimitRule, ArcjetSlidingWindowRateLimitRule, ArcjetShieldRule, + ArcjetLogger, } from "@arcjet/protocol"; import { ArcjetBotTypeToProtocol, @@ -39,7 +40,7 @@ import { } from "@arcjet/protocol/proto.js"; import * as analyze from "@arcjet/analyze"; import * as duration from "@arcjet/duration"; -import logger from "@arcjet/logger"; +import { Logger, type LogLevel } from "@arcjet/logger"; import ArcjetHeaders from "@arcjet/headers"; import { runtime } from "@arcjet/runtime"; @@ -321,6 +322,8 @@ export function createRemoteClient( details: ArcjetRequestDetails, rules: ArcjetRule[], ): Promise { + const { log } = context; + // Build the request object from the Protobuf generated class. const decideRequest = new DecideRequest({ sdkStack, @@ -342,7 +345,7 @@ export function createRemoteClient( rules: rules.map(ArcjetRuleToProtocol), }); - logger.debug("Decide request to %s", baseUrl); + log.debug("Decide request to %s", baseUrl); const response = await client.decide(decideRequest, { headers: { Authorization: `Bearer ${context.key}` }, @@ -351,16 +354,19 @@ export function createRemoteClient( const decision = ArcjetDecisionFromProtocol(response.decision); - logger.debug("Decide response", { - id: decision.id, - fingerprint: context.fingerprint, - path: details.path, - runtime: context.runtime, - ttl: decision.ttl, - conclusion: decision.conclusion, - reason: decision.reason, - ruleResults: decision.results, - }); + log.debug( + { + id: decision.id, + fingerprint: context.fingerprint, + path: details.path, + runtime: context.runtime, + ttl: decision.ttl, + conclusion: decision.conclusion, + reason: decision.reason, + ruleResults: decision.results, + }, + "Decide response", + ); return decision; }, @@ -371,6 +377,8 @@ export function createRemoteClient( decision: ArcjetDecision, rules: ArcjetRule[], ): void { + const { log } = context; + // Build the request object from the Protobuf generated class. const reportRequest = new ReportRequest({ sdkStack, @@ -392,7 +400,7 @@ export function createRemoteClient( receivedAt: Timestamp.now(), }); - logger.debug("Report request to %s", baseUrl); + log.debug("Report request to %s", baseUrl); // We use the promise API directly to avoid returning a promise from this function so execution can't be paused with `await` client @@ -401,19 +409,19 @@ export function createRemoteClient( timeoutMs: 2_000, // 2 seconds }) .then((response) => { - logger.debug("Report response", { - id: response.decision?.id, - fingerprint: context.fingerprint, - path: details.path, - runtime: context.runtime, - ttl: decision.ttl, - }); + log.debug( + { + id: response.decision?.id, + fingerprint: context.fingerprint, + path: details.path, + runtime: context.runtime, + ttl: decision.ttl, + }, + "Report response", + ); }) .catch((err: unknown) => { - logger.log( - "Encountered problem sending report: %s", - errorMessage(err), - ); + log.info("Encountered problem sending report: %s", errorMessage(err)); }); }, }); @@ -778,7 +786,7 @@ export function validateEmail( context: ArcjetContext, { email }: ArcjetRequestDetails & { email: string }, ): Promise { - if (await analyze.isValidEmail(email, analyzeOpts)) { + if (await analyze.isValidEmail(context, email, analyzeOpts)) { return new ArcjetRuleResult({ ttl: 0, state: "RUN", @@ -885,6 +893,7 @@ export function detectBot( } const botResult = await analyze.detectBot( + context, JSON.stringify(headersKV), JSON.stringify( Object.fromEntries( @@ -1014,6 +1023,10 @@ export interface ArcjetOptions { * when creating the SDK, such as inside @arcjet/next or mocked in tests. */ client?: RemoteClient; + /** + * The logger used to emit useful information from the SDK. + */ + log?: ArcjetLogger; } /** @@ -1046,6 +1059,20 @@ export interface Arcjet { ): Arcjet>>; } +function getEnvLogLevel(): LogLevel { + const level = process.env["ARCJET_LOG_LEVEL"]; + switch (level) { + case "debug": + case "info": + case "warn": + case "error": + return level; + default: + // Default to warn if not set + return "warn"; + } +} + /** * Create a new Arcjet client with the specified {@link ArcjetOptions}. * @@ -1058,6 +1085,11 @@ export default function arcjet< const { key, rules, client } = options; const rt = runtime(); + const log = options.log + ? options.log + : new Logger({ + level: getEnvLogLevel(), + }); // TODO(#207): Remove this when we can default the transport so client is not required // It is currently optional in the options so the Next SDK can override it for the user @@ -1103,31 +1135,38 @@ export default function arcjet< email: typeof request.email === "string" ? request.email : undefined, }); - logger.time("local"); + log.time?.("local"); - logger.time("fingerprint"); + log.time?.("fingerprint"); let ip = ""; if (typeof details.ip === "string") { ip = details.ip; } if (details.ip === "") { - logger.warn("generateFingerprint: ip is empty"); + log.warn("generateFingerprint: ip is empty"); } - const fingerprint = await analyze.generateFingerprint(ip); - logger.debug("fingerprint (%s): %s", rt, fingerprint); - logger.timeEnd("fingerprint"); - const context: ArcjetContext = { key, ...ctx, fingerprint, runtime: rt }; + const baseContext = { + key, + log, + ...ctx, + }; + + const fingerprint = await analyze.generateFingerprint(baseContext, ip); + log.debug("fingerprint (%s): %s", rt, fingerprint); + log.timeEnd?.("fingerprint"); + + const context: ArcjetContext = { ...baseContext, fingerprint, runtime: rt }; if (rules.length < 1) { // TODO(#607): Error if no rules configured after deprecation period - logger.warn( + log.warn( "Calling `protect()` with no rules is deprecated. Did you mean to configure the Shield rule?", ); } if (rules.length > 10) { - logger.error("Failure running rules. Only 10 rules may be specified."); + log.error("Failure running rules. Only 10 rules may be specified."); const decision = new ArcjetErrorDecision({ ttl: 0, @@ -1164,18 +1203,21 @@ export default function arcjet< // serverless environments where every request is isolated, but there may be // some instances where the instance is not recycled immediately. If so, we // can take advantage of that. - logger.time("cache"); + log.time?.("cache"); const existingBlockReason = blockCache.get(fingerprint); - logger.timeEnd("cache"); + log.timeEnd?.("cache"); // If already blocked then we can async log to the API and return the // decision immediately. if (existingBlockReason) { - logger.timeEnd("local"); - logger.debug("decide: alreadyBlocked", { - fingerprint, - existingBlockReason, - }); + log.timeEnd?.("local"); + log.debug( + { + fingerprint, + existingBlockReason, + }, + "decide: alreadyBlocked", + ); const decision = new ArcjetDenyDecision({ ttl: blockCache.ttl(fingerprint), reason: existingBlockReason, @@ -1185,13 +1227,16 @@ export default function arcjet< remoteClient.report(context, details, decision, rules); - logger.debug("decide: already blocked", { - id: decision.id, - conclusion: decision.conclusion, - fingerprint, - reason: existingBlockReason, - runtime: rt, - }); + log.debug( + { + id: decision.id, + conclusion: decision.conclusion, + fingerprint, + reason: existingBlockReason, + runtime: rt, + }, + "decide: already blocked", + ); return decision; } @@ -1206,24 +1251,27 @@ export default function arcjet< continue; } - logger.time(rule.type); + log.time?.(rule.type); try { localRule.validate(context, details); results[idx] = await localRule.protect(context, details); - logger.debug("Local rule result:", { - id: results[idx].ruleId, - rule: rule.type, - fingerprint, - path: details.path, - runtime: rt, - ttl: results[idx].ttl, - conclusion: results[idx].conclusion, - reason: results[idx].reason, - }); + log.debug( + { + id: results[idx].ruleId, + rule: rule.type, + fingerprint, + path: details.path, + runtime: rt, + ttl: results[idx].ttl, + conclusion: results[idx].conclusion, + reason: results[idx].reason, + }, + "Local rule result:", + ); } catch (err) { - logger.error( + log.error( "Failure running rule: %s due to %s", rule.type, errorMessage(err), @@ -1237,10 +1285,10 @@ export default function arcjet< }); } - logger.timeEnd(rule.type); + log.timeEnd?.(rule.type); if (results[idx].isDenied()) { - logger.timeEnd("local"); + log.timeEnd?.("local"); const decision = new ArcjetDenyDecision({ ttl: results[idx].ttl, @@ -1257,11 +1305,15 @@ export default function arcjet< // and return this DENY decision. if (rule.mode !== "DRY_RUN") { if (results[idx].ttl > 0) { - logger.debug("Caching decision for %d seconds", decision.ttl, { - fingerprint, - conclusion: decision.conclusion, - reason: decision.reason, - }); + log.debug( + { + fingerprint, + conclusion: decision.conclusion, + reason: decision.reason, + }, + "Caching decision for %d seconds", + decision.ttl, + ); blockCache.set( fingerprint, @@ -1273,7 +1325,7 @@ export default function arcjet< return decision; } - logger.warn( + log.warn( `Dry run mode is enabled for "%s" rule. Overriding decision. Decision was: %s`, rule.type, decision.conclusion, @@ -1281,23 +1333,20 @@ export default function arcjet< } } - logger.timeEnd("local"); - logger.time("remote"); + log.timeEnd?.("local"); + log.time?.("remote"); // With no cached values, we take a decision remotely. We use a timeout to // fail open. try { - logger.time("decideApi"); + log.time?.("decideApi"); const decision = await remoteClient.decide(context, details, rules); - logger.timeEnd("decideApi"); + log.timeEnd?.("decideApi"); // If the decision is to block and we have a non-zero TTL, we cache the // block locally if (decision.isDenied() && decision.ttl > 0) { - logger.debug( - "decide: Caching block locally for %d seconds", - decision.ttl, - ); + log.debug("decide: Caching block locally for %d seconds", decision.ttl); blockCache.set( fingerprint, @@ -1308,7 +1357,7 @@ export default function arcjet< return decision; } catch (err) { - logger.error( + log.error( "Encountered problem getting remote decision: %s", errorMessage(err), ); @@ -1322,7 +1371,7 @@ export default function arcjet< return decision; } finally { - logger.timeEnd("remote"); + log.timeEnd?.("remote"); } } @@ -1337,7 +1386,7 @@ export default function arcjet< return withRule(rule); }, async protect( - ctx: ArcjetContext, + ctx: ArcjetAdapterContext, request: ArcjetRequest>, ): Promise { return protect(rules, ctx, request); @@ -1350,7 +1399,7 @@ export default function arcjet< return withRule(rule); }, async protect( - ctx: ArcjetContext, + ctx: ArcjetAdapterContext, request: ArcjetRequest>, ): Promise { return protect(rootRules, ctx, request); diff --git a/arcjet/test/index.node.test.ts b/arcjet/test/index.node.test.ts index 8fc6a4042..03840f6e7 100644 --- a/arcjet/test/index.node.test.ts +++ b/arcjet/test/index.node.test.ts @@ -24,7 +24,7 @@ import { RuleResult, RuleState, } from "@arcjet/protocol/proto"; -import logger from "@arcjet/logger"; +import { Logger } from "@arcjet/logger"; import arcjet, { ArcjetDecision, @@ -165,6 +165,8 @@ class ArcjetInvalidDecision extends ArcjetDecision { } } +const log = new Logger({ level: "info" }); + describe("defaultBaseUrl", () => { test("uses process.env.ARCJET_BASE_URL if set and allowed", () => { jest.replaceProperty(process, "env", { @@ -245,6 +247,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -299,6 +302,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -354,6 +358,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -407,6 +412,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -461,6 +467,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -520,6 +527,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -562,6 +570,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -603,6 +612,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -644,6 +654,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -688,6 +699,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -738,6 +750,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -780,6 +793,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const receivedAt = Timestamp.now(); const details = { @@ -847,6 +861,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const receivedAt = Timestamp.now(); const details = { @@ -913,6 +928,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const receivedAt = Timestamp.now(); const details = { @@ -986,6 +1002,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const receivedAt = Timestamp.now(); const details = { @@ -1052,6 +1069,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const receivedAt = Timestamp.now(); const details = { @@ -1114,6 +1132,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const receivedAt = Timestamp.now(); const details = { @@ -1202,6 +1221,7 @@ describe("createRemoteClient", () => { key, fingerprint, runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -1217,7 +1237,7 @@ describe("createRemoteClient", () => { const [promise, resolve] = deferred(); - const logSpy = jest.spyOn(logger, "log").mockImplementation(() => { + const logSpy = jest.spyOn(log, "info").mockImplementation(() => { resolve(); }); @@ -1486,6 +1506,7 @@ describe("Primitive > detectBot", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { headers: new Headers(), @@ -1504,6 +1525,7 @@ describe("Primitive > detectBot", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { headers: undefined, @@ -1522,6 +1544,7 @@ describe("Primitive > detectBot", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -1566,6 +1589,7 @@ describe("Primitive > detectBot", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -1620,6 +1644,7 @@ describe("Primitive > detectBot", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -1674,6 +1699,7 @@ describe("Primitive > detectBot", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -1715,6 +1741,7 @@ describe("Primitive > detectBot", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -1778,6 +1805,7 @@ describe("Primitive > detectBot", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -1826,6 +1854,7 @@ describe("Primitive > detectBot", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -1873,6 +1902,7 @@ describe("Primitive > detectBot", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -2688,6 +2718,7 @@ describe("Primitive > validateEmail", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { email: "abc@example.com", @@ -2706,6 +2737,7 @@ describe("Primitive > validateEmail", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { email: undefined, @@ -2724,6 +2756,7 @@ describe("Primitive > validateEmail", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -2756,6 +2789,7 @@ describe("Primitive > validateEmail", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -2788,6 +2822,7 @@ describe("Primitive > validateEmail", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -2820,6 +2855,7 @@ describe("Primitive > validateEmail", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -2854,6 +2890,7 @@ describe("Primitive > validateEmail", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -2886,6 +2923,7 @@ describe("Primitive > validateEmail", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -2918,6 +2956,7 @@ describe("Primitive > validateEmail", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -2952,6 +2991,7 @@ describe("Primitive > validateEmail", () => { key: "test-key", fingerprint: "test-fingerprint", runtime: "test", + log, }; const details = { ip: "172.100.1.1", @@ -4063,7 +4103,7 @@ describe("SDK", () => { "extra-test": "extra-test-value", }; - const errorLogSpy = jest.spyOn(logger, "error"); + const errorLogSpy = jest.spyOn(log, "error"); function testRuleLocalThrowString(): ArcjetLocalRule { return { @@ -4081,6 +4121,7 @@ describe("SDK", () => { key: "test-key", rules: [[testRuleLocalThrowString()]], client, + log, }); const _ = await aj.protect({}, request); @@ -4115,7 +4156,7 @@ describe("SDK", () => { "extra-test": "extra-test-value", }; - const errorLogSpy = jest.spyOn(logger, "error"); + const errorLogSpy = jest.spyOn(log, "error"); function testRuleLocalThrowNull(): ArcjetLocalRule { return { @@ -4133,6 +4174,7 @@ describe("SDK", () => { key: "test-key", rules: [[testRuleLocalThrowNull()]], client, + log, }); const _ = await aj.protect({}, request); diff --git a/logger/index.ts b/logger/index.ts index 6c24e4bf0..fcf394f88 100644 --- a/logger/index.ts +++ b/logger/index.ts @@ -1,45 +1,95 @@ import format from "@arcjet/sprintf"; -export type LogLevel = "DEBUG" | "LOG" | "WARN" | "ERROR"; - -function getEnvLogLevel(): LogLevel | undefined { - const level = process.env["ARCJET_LOG_LEVEL"]; - switch (level) { - case "DEBUG": - case "LOG": - case "WARN": - case "ERROR": - return level; - default: - return undefined; +function bigintReplacer(key: string, value: unknown) { + if (typeof value === "bigint") { + return "[BigInt]"; + } + + return value; +} + +// TODO: Deduplicate this and sprintf implementation +function tryStringify(o: unknown) { + try { + return JSON.stringify(o, bigintReplacer); + } catch (e) { + return "[Circular]"; } } +export type LogLevel = "debug" | "info" | "warn" | "error"; + +export interface LoggerOptions { + level: LogLevel; +} + +const PREFIX = "✦Aj"; + function getTimeLabel(label: string) { - return `✦Aj Latency ${label}`; + return `${PREFIX} LATENCY ${label}`; +} + +function getMessage(obj: unknown, msg: unknown, args: unknown[]) { + // The first argument was the message so juggle the args + if (typeof obj === "string") { + args = [msg, ...args]; + msg = obj; + } + + // Prefer a string message over `obj.msg`, as per Pino: + // https://github.com/pinojs/pino/blob/8db130eba0439e61c802448d31eb1998cebfbc98/docs/api.md#message-string + if (typeof msg === "string") { + return format(msg, ...args); + } + + if ( + typeof obj === "object" && + obj !== null && + "msg" in obj && + typeof obj.msg === "string" + ) { + return format(obj.msg, [msg, ...args]); + } +} + +function getOutput(obj: unknown, msg: unknown, args: unknown[]) { + let output = getMessage(obj, msg, args); + if (typeof output !== "string") { + return; + } + + if (typeof obj === "object" && obj !== null) { + for (const [key, value] of Object.entries(obj)) { + output += `\n ${key}: ${tryStringify(value)}`; + } + } + + return output; } export class Logger { #logLevel: number; - constructor() { - const levelStr = getEnvLogLevel() ?? "WARN"; - switch (levelStr) { - case "DEBUG": + constructor(opts: LoggerOptions) { + if (typeof opts.level !== "string") { + throw new Error(`Invalid log level`); + } + + switch (opts.level) { + case "debug": this.#logLevel = 0; break; - case "LOG": + case "info": this.#logLevel = 1; break; - case "WARN": + case "warn": this.#logLevel = 2; break; - case "ERROR": + case "error": this.#logLevel = 3; break; default: { - const _exhaustiveCheck: never = levelStr; - throw new Error(`Unknown log level: ${levelStr}`); + throw new Error(`Unknown log level: ${opts.level}`); } } } @@ -56,31 +106,47 @@ export class Logger { } } - debug(msg: string, ...details: unknown[]) { + debug(msg: string, ...args: unknown[]): void; + debug(obj: Record, msg?: string, ...args: unknown[]): void; + debug(obj: unknown, msg?: unknown, ...args: unknown[]): void { if (this.#logLevel <= 0) { - console.debug("✦Aj %s", format(msg, ...details)); + const output = getOutput(obj, msg, args); + if (typeof output !== "undefined") { + console.debug(`${PREFIX} DEBUG ${output}`); + } } } - log(msg: string, ...details: unknown[]) { + info(msg: string, ...args: unknown[]): void; + info(obj: Record, msg?: string, ...args: unknown[]): void; + info(obj: unknown, msg?: unknown, ...args: unknown[]): void { if (this.#logLevel <= 1) { - console.log("✦Aj %s", format(msg, ...details)); + const output = getOutput(obj, msg, args); + if (typeof output !== "undefined") { + console.info(`${PREFIX} INFO ${output}`); + } } } - warn(msg: string, ...details: unknown[]) { + warn(msg: string, ...args: unknown[]): void; + warn(obj: Record, msg?: string, ...args: unknown[]): void; + warn(obj: unknown, msg?: unknown, ...args: unknown[]): void { if (this.#logLevel <= 2) { - console.warn("✦Aj %s", format(msg, ...details)); + const output = getOutput(obj, msg, args); + if (typeof output !== "undefined") { + console.warn(`${PREFIX} WARN ${output}`); + } } } - error(msg: string, ...details: unknown[]) { + error(msg: string, ...args: unknown[]): void; + error(obj: Record, msg?: string, ...args: unknown[]): void; + error(obj: unknown, msg?: unknown, ...args: unknown[]): void { if (this.#logLevel <= 3) { - console.error("✦Aj %s", format(msg, ...details)); + const output = getOutput(obj, msg, args); + if (typeof output !== "undefined") { + console.error(`${PREFIX} ERROR ${output}`); + } } } } - -// Singleton logger that only accounts for `process.env["ARCJET_LOG_LEVEL"]` at module-load time -const logger = new Logger(); -export default logger; diff --git a/package-lock.json b/package-lock.json index 59cda8cdf..bcf3b3bb8 100644 --- a/package-lock.json +++ b/package-lock.json @@ -19,7 +19,7 @@ "version": "1.0.0-alpha.13", "license": "Apache-2.0", "dependencies": { - "@arcjet/logger": "1.0.0-alpha.13" + "@arcjet/protocol": "1.0.0-alpha.13" }, "devDependencies": { "@arcjet/eslint-config": "1.0.0-alpha.13", @@ -175,8 +175,8 @@ "version": "1.0.0-alpha.13", "license": "Apache-2.0", "dependencies": { - "@arcjet/logger": "1.0.0-alpha.13", - "@arcjet/protocol": "1.0.0-alpha.13" + "@arcjet/protocol": "1.0.0-alpha.13", + "@arcjet/sprintf": "1.0.0-alpha.13" }, "devDependencies": { "@arcjet/eslint-config": "1.0.0-alpha.13", diff --git a/protocol/index.ts b/protocol/index.ts index d9f9a3144..356c8dbdd 100644 --- a/protocol/index.ts +++ b/protocol/index.ts @@ -744,9 +744,26 @@ export interface ArcjetShieldRule extends ArcjetRule { type: "SHIELD"; } +export interface ArcjetLogger { + // Latency logs will be emitted if `time` and `timeEnd` calls exist on the + // logger interface, but they are optional since Pino doesn't have them. + time?(label: string): void; + timeEnd?(label: string): void; + // Pino-compatible logging functions are required. + debug(msg: string, ...args: unknown[]): void; + debug(obj: Record, msg?: string, ...args: unknown[]): void; + info(msg: string, ...args: unknown[]): void; + info(obj: Record, msg?: string, ...args: unknown[]): void; + warn(msg: string, ...args: unknown[]): void; + warn(obj: Record, msg?: string, ...args: unknown[]): void; + error(msg: string, ...args: unknown[]): void; + error(obj: Record, msg?: string, ...args: unknown[]): void; +} + export type ArcjetContext = { [key: string]: unknown; key: string; fingerprint: string; runtime: string; + log: ArcjetLogger; };