From bcb99312b5ae98927bce5f502a714fc91caad87b Mon Sep 17 00:00:00 2001 From: Blaine Bublitz Date: Mon, 3 Jun 2024 17:10:42 -0400 Subject: [PATCH 01/14] feat(logger)!: Align logger with Pino API --- logger/index.ts | 136 ++++++++++++++++++++++++++++++++++++------------ 1 file changed, 102 insertions(+), 34 deletions(-) diff --git a/logger/index.ts b/logger/index.ts index 6c24e4bf0..d7f287562 100644 --- a/logger/index.ts +++ b/logger/index.ts @@ -1,45 +1,97 @@ 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 + if (typeof obj === "string") { + return format(obj, ...args); + } + + // The second argument was the message + 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, ...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 +108,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; From d0525737462b2dc6b1e53235bf2258e7e3fb6c9b Mon Sep 17 00:00:00 2001 From: Blaine Bublitz Date: Tue, 4 Jun 2024 10:08:49 -0400 Subject: [PATCH 02/14] update arcjet package so the logger works --- analyze/index.ts | 41 ++++--- analyze/package.json | 2 +- arcjet/index.ts | 209 ++++++++++++++++++++------------- arcjet/test/index.node.test.ts | 50 +++++++- protocol/index.ts | 20 +++- 5 files changed, 218 insertions(+), 104 deletions(-) diff --git a/analyze/index.ts b/analyze/index.ts index 9dfeff477..b8953d9c3 100644 --- a/analyze/index.ts +++ b/analyze/index.ts @@ -1,4 +1,4 @@ -import logger from "@arcjet/logger"; +import type { ArcjetContext } from "@arcjet/protocol"; import * as core from "./wasm/arcjet_analyze_js_req.component.js"; import type { @@ -73,22 +73,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: Omit) { + 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 +118,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: Omit, + 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 +160,11 @@ export async function generateFingerprint(ip: string): Promise { } export async function isValidEmail( + context: ArcjetContext, candidate: string, - options?: EmailValidationConfig, + options: EmailValidationConfig = {}, ) { - const analyze = await init(); + const analyze = await init(context); if (typeof analyze !== "undefined") { return analyze.isValidEmail(candidate, options); @@ -169,11 +175,12 @@ export async function isValidEmail( } export async function detectBot( + context: ArcjetContext, 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..f7d41430e 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 { LogLevel, Logger } 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: Omit = { + key, + ...ctx, + log, + }; + + const fingerprint = await analyze.generateFingerprint(baseContext, ip); + log.debug("fingerprint (%s): %s", runtime(), 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/protocol/index.ts b/protocol/index.ts index d9f9a3144..948b6a50b 100644 --- a/protocol/index.ts +++ b/protocol/index.ts @@ -744,9 +744,25 @@ export interface ArcjetShieldRule extends ArcjetRule { type: "SHIELD"; } -export type ArcjetContext = { - [key: string]: unknown; +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 interface ArcjetContext { key: string; fingerprint: string; runtime: string; + log: ArcjetLogger; }; From 8164f8c89860305c089a43c5aec0603384ac98c3 Mon Sep 17 00:00:00 2001 From: Blaine Bublitz Date: Tue, 4 Jun 2024 12:20:49 -0400 Subject: [PATCH 03/14] undo defaulting --- analyze/index.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/analyze/index.ts b/analyze/index.ts index b8953d9c3..dfb372648 100644 --- a/analyze/index.ts +++ b/analyze/index.ts @@ -162,7 +162,7 @@ export async function generateFingerprint( export async function isValidEmail( context: ArcjetContext, candidate: string, - options: EmailValidationConfig = {}, + options?: EmailValidationConfig, ) { const analyze = await init(context); From 502cee4177219408d8b3f49b72283799f3373eec Mon Sep 17 00:00:00 2001 From: Blaine Bublitz Date: Tue, 4 Jun 2024 12:23:57 -0400 Subject: [PATCH 04/14] reorder import --- arcjet/index.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/arcjet/index.ts b/arcjet/index.ts index f7d41430e..5443ca14c 100644 --- a/arcjet/index.ts +++ b/arcjet/index.ts @@ -40,7 +40,7 @@ import { } from "@arcjet/protocol/proto.js"; import * as analyze from "@arcjet/analyze"; import * as duration from "@arcjet/duration"; -import { LogLevel, Logger } from "@arcjet/logger"; +import { Logger, type LogLevel } from "@arcjet/logger"; import ArcjetHeaders from "@arcjet/headers"; import { runtime } from "@arcjet/runtime"; From df6aff1a81f59751df2fdf71650125357653f631 Mon Sep 17 00:00:00 2001 From: Blaine Bublitz Date: Tue, 4 Jun 2024 12:24:36 -0400 Subject: [PATCH 05/14] allow log to be overridden by adapter context --- arcjet/index.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/arcjet/index.ts b/arcjet/index.ts index 5443ca14c..521333ae2 100644 --- a/arcjet/index.ts +++ b/arcjet/index.ts @@ -1148,8 +1148,8 @@ export default function arcjet< const baseContext: Omit = { key, - ...ctx, log, + ...ctx, }; const fingerprint = await analyze.generateFingerprint(baseContext, ip); From 058f2f8e4b17429825f54b42779e7fddf9421454 Mon Sep 17 00:00:00 2001 From: Blaine Bublitz Date: Tue, 4 Jun 2024 12:33:25 -0400 Subject: [PATCH 06/14] fmt --- logger/index.ts | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/logger/index.ts b/logger/index.ts index d7f287562..7077d197b 100644 --- a/logger/index.ts +++ b/logger/index.ts @@ -29,11 +29,7 @@ function getTimeLabel(label: string) { return `${PREFIX} LATENCY ${label}`; } -function getMessage( - obj: unknown, - msg: unknown, - args: unknown[], -) { +function getMessage(obj: unknown, msg: unknown, args: unknown[]) { // The first argument was the message if (typeof obj === "string") { return format(obj, ...args); From 5d4af74511e62440ee43f632d15741ba695398f6 Mon Sep 17 00:00:00 2001 From: Blaine Bublitz Date: Tue, 4 Jun 2024 12:35:33 -0400 Subject: [PATCH 07/14] simplify analyze context --- analyze/index.ts | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-) diff --git a/analyze/index.ts b/analyze/index.ts index dfb372648..c0ab71bc1 100644 --- a/analyze/index.ts +++ b/analyze/index.ts @@ -1,4 +1,4 @@ -import type { ArcjetContext } from "@arcjet/protocol"; +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,7 +77,7 @@ async function moduleFromPath(path: string): Promise { throw new Error(`Unknown path: ${path}`); } -async function init(context: Omit) { +async function init(context: AnalyzeContext) { const { log } = context; const coreImports: ImportObject = { @@ -119,7 +123,7 @@ export { * @returns A SHA-256 string fingerprint. */ export async function generateFingerprint( - context: Omit, + context: AnalyzeContext, ip: string, ): Promise { if (ip == "") { @@ -160,7 +164,7 @@ export async function generateFingerprint( } export async function isValidEmail( - context: ArcjetContext, + context: AnalyzeContext, candidate: string, options?: EmailValidationConfig, ) { @@ -175,7 +179,7 @@ export async function isValidEmail( } export async function detectBot( - context: ArcjetContext, + context: AnalyzeContext, headers: string, patterns_add: string, patterns_remove: string, From bab08995c960b7ca03889717e294798872139cda Mon Sep 17 00:00:00 2001 From: Blaine Bublitz Date: Tue, 4 Jun 2024 12:38:41 -0400 Subject: [PATCH 08/14] fmt --- analyze/index.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/analyze/index.ts b/analyze/index.ts index c0ab71bc1..f9b798db8 100644 --- a/analyze/index.ts +++ b/analyze/index.ts @@ -9,7 +9,7 @@ import type { } from "./wasm/arcjet_analyze_js_req.component.js"; interface AnalyzeContext { - log: ArcjetLogger + log: ArcjetLogger; } // TODO: Do we actually need this wasmCache or does `import` cache correctly? From 2785900710a12d1e301497b00f12a181cd12d6bd Mon Sep 17 00:00:00 2001 From: Blaine Bublitz Date: Tue, 4 Jun 2024 12:39:39 -0400 Subject: [PATCH 09/14] undo context change --- protocol/index.ts | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/protocol/index.ts b/protocol/index.ts index 948b6a50b..356c8dbdd 100644 --- a/protocol/index.ts +++ b/protocol/index.ts @@ -760,7 +760,8 @@ export interface ArcjetLogger { error(obj: Record, msg?: string, ...args: unknown[]): void; } -export interface ArcjetContext { +export type ArcjetContext = { + [key: string]: unknown; key: string; fingerprint: string; runtime: string; From 0a71259a0c983dcddbeb260c3c2dba4f0518d7e0 Mon Sep 17 00:00:00 2001 From: Blaine Bublitz Date: Tue, 4 Jun 2024 12:41:06 -0400 Subject: [PATCH 10/14] fix baseContext error --- arcjet/index.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/arcjet/index.ts b/arcjet/index.ts index 521333ae2..4684ed38a 100644 --- a/arcjet/index.ts +++ b/arcjet/index.ts @@ -1146,7 +1146,7 @@ export default function arcjet< log.warn("generateFingerprint: ip is empty"); } - const baseContext: Omit = { + const baseContext = { key, log, ...ctx, From 73016f40ac21a3806158fbf44119bf206d72bd9a Mon Sep 17 00:00:00 2001 From: Blaine Bublitz Date: Thu, 6 Jun 2024 09:50:37 -0400 Subject: [PATCH 11/14] lockfile --- package-lock.json | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) 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", From 8d598691459290db2f4d3e1e148d1ffa508b97c8 Mon Sep 17 00:00:00 2001 From: Blaine Bublitz Date: Thu, 6 Jun 2024 10:08:43 -0400 Subject: [PATCH 12/14] fix bugs with missing logger args --- arcjet/index.ts | 2 +- logger/index.ts | 7 ++++--- 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/arcjet/index.ts b/arcjet/index.ts index 4684ed38a..93d56a365 100644 --- a/arcjet/index.ts +++ b/arcjet/index.ts @@ -1153,7 +1153,7 @@ export default function arcjet< }; const fingerprint = await analyze.generateFingerprint(baseContext, ip); - log.debug("fingerprint (%s): %s", runtime(), fingerprint); + log.debug("fingerprint (%s): %s", rt, fingerprint); log.timeEnd?.("fingerprint"); const context: ArcjetContext = { ...baseContext, fingerprint, runtime: rt }; diff --git a/logger/index.ts b/logger/index.ts index 7077d197b..599d9bde1 100644 --- a/logger/index.ts +++ b/logger/index.ts @@ -30,9 +30,10 @@ function getTimeLabel(label: string) { } function getMessage(obj: unknown, msg: unknown, args: unknown[]) { - // The first argument was the message + // The first argument was the message so juggle the args if (typeof obj === "string") { - return format(obj, ...args); + args = [msg, ...args]; + msg = obj; } // The second argument was the message @@ -46,7 +47,7 @@ function getMessage(obj: unknown, msg: unknown, args: unknown[]) { "msg" in obj && typeof obj.msg === "string" ) { - return format(obj.msg, ...args); + return format(obj.msg, [msg, ...args]); } } From ec143705b88bc2ff51b7d2dd50ca7cb93e7df41c Mon Sep 17 00:00:00 2001 From: Blaine Bublitz Date: Thu, 6 Jun 2024 10:11:43 -0400 Subject: [PATCH 13/14] add 2 space indent on object props --- logger/index.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/logger/index.ts b/logger/index.ts index 599d9bde1..0cf9b3c23 100644 --- a/logger/index.ts +++ b/logger/index.ts @@ -59,7 +59,7 @@ function getOutput(obj: unknown, msg: unknown, args: unknown[]) { if (typeof obj === "object" && obj !== null) { for (const [key, value] of Object.entries(obj)) { - output += `\n ${key}: ${tryStringify(value)}`; + output += `\n ${key}: ${tryStringify(value)}`; } } From 4e4e8950753e3a99418edcc28eb7640ffb3b17a5 Mon Sep 17 00:00:00 2001 From: Blaine Bublitz Date: Thu, 6 Jun 2024 10:19:53 -0400 Subject: [PATCH 14/14] update comment --- logger/index.ts | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/logger/index.ts b/logger/index.ts index 0cf9b3c23..fcf394f88 100644 --- a/logger/index.ts +++ b/logger/index.ts @@ -36,7 +36,8 @@ function getMessage(obj: unknown, msg: unknown, args: unknown[]) { msg = obj; } - // The second argument was the message + // 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); }