diff --git a/EXAMPLES.md b/EXAMPLES.md index 73c26fd44..cc6f13af7 100644 --- a/EXAMPLES.md +++ b/EXAMPLES.md @@ -135,6 +135,13 @@ - [Customizing Auth Handlers](#customizing-auth-handlers) - [Run custom code before Auth Handlers](#run-custom-code-before-auth-handlers) - [Run code after callback](#run-code-after-callback) +- [Instrumentation](#instrumentation) + - [Environment Variable Configuration](#environment-variable-configuration-1) + - [Basic Console Logger](#basic-console-logger) + - [Filtering by Log Level](#filtering-by-log-level) + - [Filtering by Event Name](#filtering-by-event-name) + - [Sending Events to an External Service](#sending-events-to-an-external-service) + - [Event Reference](#event-reference) - [Next.js 16 Compatibility](#nextjs-16-compatibility) - [Multi-Factor Authentication (MFA)](#multi-factor-authentication-mfa) - [Step-up Authentication](#step-up-authentication) @@ -3348,6 +3355,187 @@ export async function middleware(request) { Please refer to [onCallback](https://github.com/auth0/nextjs-auth0/blob/main/EXAMPLES.md#oncallback) for details on how to run code after callback. +## Instrumentation + +The SDK supports an optional `instrumentation.logger` callback that receives structured, PII-filtered events at key points in the auth lifecycle. This is useful for debugging, monitoring, and observability. + +- **Zero overhead** when not configured — no object allocation, no string formatting. +- **PII-safe** — tokens, secrets, user claims, cookies, and state/nonce values are never included in event data. +- **Non-breaking** — logger errors are silently swallowed and never affect auth flows. + +Each event has the following shape: + +```typescript +interface InstrumentationEvent { + /** Namespaced event name, e.g. 'auth:login:start', 'discovery:complete' */ + event: string; + /** 'debug' | 'info' | 'warn' | 'error' */ + level: LogLevel; + /** ISO 8601 timestamp */ + timestamp: string; + /** PII-filtered data (shape varies per event) */ + data: Record; + /** Duration in ms (present on timed 'complete' events) */ + durationMs?: number; +} +``` + +### Environment Variable Configuration + +The quickest way to enable logging is via environment variables — no code changes required: + +```bash +# .env.local + +# Logging target. Currently only "console" is supported. +# If unset, no logging occurs. +AUTH0_LOGGING_TARGET=console + +# Minimum log level: "debug", "info", "warn", or "error". +# Defaults to "info" when a target is configured. +AUTH0_LOGGING_LEVEL=debug +``` + +| Variable | Values | Default | Description | +|----------|--------|---------|-------------| +| `AUTH0_LOGGING_TARGET` | `console` | _(unset)_ | Where to send log output. If unset or invalid, no logging occurs. | +| `AUTH0_LOGGING_LEVEL` | `debug`, `info`, `warn`, `error` | `info` | Minimum severity level to emit. Events below this level are filtered out. | + +Example output with `AUTH0_LOGGING_TARGET=console` and `AUTH0_LOGGING_LEVEL=info`: + +``` +[auth0/info] auth:login:start { domain: 'example.auth0.com', scope: 'openid profile email' } +[auth0/info] auth:login:redirect { authorizationUrl: 'https://example.auth0.com/authorize' } +[auth0/warn] auth:logout:fallback { domain: 'example.auth0.com', reason: 'rp_initiated_logout_not_supported' } +[auth0/error] error { operation: 'discovery', errorType: 'Error', message: 'fetch failed' } +``` + +> [!NOTE] +> A programmatic `instrumentation.logger` always takes precedence over environment variables. If both are configured, the env vars are ignored. + +### Basic Console Logger + +```typescript +import { Auth0Client } from "@auth0/nextjs-auth0/server"; + +export const auth0 = new Auth0Client({ + instrumentation: { + logger: (event) => { + console.log(`[${event.level}] ${event.event}`, event.data); + }, + }, +}); +``` + +Example output during a login flow: + +``` +[info] auth:login:start { domain: 'example.auth0.com', scope: 'openid profile email' } +[debug] discovery:start { domain: 'example.auth0.com' } +[debug] discovery:complete { domain: 'example.auth0.com', durationMs: 120 } +[info] auth:login:redirect { authorizationUrl: 'https://example.auth0.com/authorize' } +``` + +### Filtering by Log Level + +```typescript +export const auth0 = new Auth0Client({ + instrumentation: { + logger: (event) => { + // Only log info, warn, and error events — skip debug + if (event.level === "debug") return; + + console.log(`[${event.level}] ${event.event}`, event.data); + }, + }, +}); +``` + +### Filtering by Event Name + +Events use colon-separated namespaces (`auth:*`, `token:*`, `discovery:*`, `session:*`, `mfa:*`, `error`), so you can filter by prefix: + +```typescript +export const auth0 = new Auth0Client({ + instrumentation: { + logger: (event) => { + // Only log auth flow and error events + if (event.event.startsWith("auth:") || event.event === "error") { + console.log(`[${event.level}] ${event.event}`, event.data); + } + }, + }, +}); +``` + +### Sending Events to an External Service + +The logger is called synchronously, but you can perform async work inside it. If the logger returns a Promise, it is not awaited — the SDK attaches a `.catch()` to prevent unhandled rejections. + +```typescript +export const auth0 = new Auth0Client({ + instrumentation: { + logger: (event) => { + // Fire-and-forget to your logging service + fetch("https://logging.example.com/ingest", { + method: "POST", + headers: { "Content-Type": "application/json" }, + body: JSON.stringify(event), + }).catch(() => { + // Handle send failure silently + }); + }, + }, +}); +``` + +For high-throughput scenarios, consider batching events: + +```typescript +const eventBuffer: InstrumentationEvent[] = []; + +function flushEvents() { + if (eventBuffer.length === 0) return; + const batch = eventBuffer.splice(0); + fetch("https://logging.example.com/ingest", { + method: "POST", + headers: { "Content-Type": "application/json" }, + body: JSON.stringify(batch), + }).catch(() => {}); +} + +// Flush every 5 seconds +setInterval(flushEvents, 5000); + +export const auth0 = new Auth0Client({ + instrumentation: { + logger: (event) => { + eventBuffer.push(event); + }, + }, +}); +``` + +### Event Reference + +The SDK emits events across the following categories: + +| Category | Events | Level | +|----------|--------|-------| +| **Auth Flow** | `auth:login:start`, `auth:login:redirect`, `auth:callback:start`, `auth:callback:complete`, `auth:logout:start`, `auth:logout:complete`, `auth:backchannel:start`, `auth:backchannel:complete`, `auth:backchannel-logout:start`, `auth:backchannel-logout:complete`, `auth:connect-account:start` | info | +| **Token** | `token:get:start`, `token:refresh:start`, `token:connection:start` | debug | +| **Token** | `token:refresh:complete`, `token:exchange:start`, `token:exchange:complete`, `token:connection:complete` | info | +| **Discovery** | `discovery:start`, `discovery:complete`, `discovery:cache-hit` | debug | +| **Session** | `session:create`, `session:delete` | info | +| **Session** | `session:touch`, `session:update`, `session:refresh` | debug | +| **MFA** | `mfa:authenticators:start`, `mfa:challenge:start`, `mfa:enroll:start`, `mfa:verify:start`, `mfa:verify:complete` | debug | +| **MFA** | `mfa:required` | info | +| **Warnings** | `auth:logout:fallback`, `config:insecure-requests` | warn | +| **Errors** | `error` (with `operation` field in data) | error | + +> [!NOTE] +> When a logger is configured, SDK warnings (e.g., insecure requests, logout fallback) are emitted as `warn`-level events instead of `console.warn()`. If no logger is configured, the original `console.warn()` behavior is preserved. + ## Next.js 16 Compatibility To support `Next.js 16`, rename your `middleware.ts` file to `proxy.ts`, and rename the exported function from `middleware` to `proxy`. All existing examples and helpers (`getSession`, `updateSession`, `getAccessToken`, etc.) will continue to work without any other changes. diff --git a/src/client/helpers/with-page-auth-required.test.tsx b/src/client/helpers/with-page-auth-required.test.tsx index 74529a859..10bf71f6a 100644 --- a/src/client/helpers/with-page-auth-required.test.tsx +++ b/src/client/helpers/with-page-auth-required.test.tsx @@ -249,12 +249,10 @@ describe("with-page-auth-required csr", () => { await waitFor(() => { expect(window.location.assign).toHaveBeenCalled(); }); - const url = new URL( - ( - window.location.assign as MockedFunction - ).mock.calls[0][0], - "https://example.com" - ); + const assignMock = window.location.assign as MockedFunction< + typeof window.location.assign + >; + const url = new URL(assignMock.mock.calls[0][0], "https://example.com"); expect(url.searchParams.get("returnTo")).toEqual("/foo?bar=baz&qux=quux"); }); }); diff --git a/src/client/mfa/mfa-client.flow.test.ts b/src/client/mfa/mfa-client.flow.test.ts index e739fc0f9..fa9c0d160 100644 --- a/src/client/mfa/mfa-client.flow.test.ts +++ b/src/client/mfa/mfa-client.flow.test.ts @@ -118,9 +118,8 @@ describe("ClientMfaClient", () => { }); it("should throw MfaGetAuthenticatorsError for network errors", async () => { - const { MfaGetAuthenticatorsError } = await import( - "../../errors/index.js" - ); + const errors = await import("../../errors/index.js"); + const { MfaGetAuthenticatorsError } = errors; const encryptedToken = await encryptMfaToken( DEFAULT.mfaToken, @@ -650,9 +649,8 @@ describe("ClientMfaClient", () => { describe("getAuthenticators - query param validation", () => { it("should handle empty query param gracefully", async () => { - const { MfaGetAuthenticatorsError } = await import( - "../../errors/index.js" - ); + const errors = await import("../../errors/index.js"); + const { MfaGetAuthenticatorsError } = errors; // Server should reject empty mfa_token server.use( diff --git a/src/server/auth-client.ts b/src/server/auth-client.ts index c70552180..250576ea7 100644 --- a/src/server/auth-client.ts +++ b/src/server/auth-client.ts @@ -72,6 +72,7 @@ import { User, VerifyMfaOptions } from "../types/index.js"; +import type { InstrumentationLogger } from "../types/instrumentation.js"; import { resolveAppBaseUrl } from "../utils/app-base-url.js"; import { mergeAuthorizationParamsIntoSearchParams } from "../utils/authorization-params-helpers.js"; import { @@ -132,6 +133,7 @@ import { FetcherHooks, FetcherMinimalConfig } from "./fetcher.js"; +import { InstrumentationEmitter } from "./instrumentation-emitter.js"; import { AbstractSessionStore } from "./session/abstract-session-store.js"; import { TransactionState, TransactionStore } from "./transaction-store.js"; import { filterDefaultIdTokenClaims } from "./user.js"; @@ -270,6 +272,12 @@ export interface AuthClientOptions { */ mfaTokenTtl?: number; + /** + * Optional instrumentation logger callback. + * @see InstrumentationLogger + */ + logger?: InstrumentationLogger; + /** * @future This option is reserved for future implementation. * Currently not used - placeholder for upcoming nonce persistence feature. @@ -332,9 +340,14 @@ export class AuthClient { private proxyFetchers: { [audience: string]: Fetcher } = {}; + private emitter: InstrumentationEmitter; + constructor(options: AuthClientOptions) { // dependencies this.fetch = options.fetch || fetch; + this.emitter = new InstrumentationEmitter(options.logger, { + domain: options.domain + }); this.jwksCache = options.jwksCache || {}; this.allowInsecureRequests = options.allowInsecureRequests ?? false; this.httpTimeout = options.httpTimeout ?? 5000; @@ -364,9 +377,16 @@ export class AuthClient { }; if (this.allowInsecureRequests && process.env.NODE_ENV === "production") { - console.warn( - "allowInsecureRequests is enabled in a production environment. This is not recommended." - ); + this.emitter.emit("warn", "config:insecure-requests", { + environment: "production", + message: + "allowInsecureRequests is enabled in a production environment. This is not recommended." + }); + if (!this.emitter.hasLogger) { + console.warn( + "allowInsecureRequests is enabled in a production environment. This is not recommended." + ); + } } // stores @@ -552,6 +572,7 @@ export class AuthClient { ...session }); addCacheControlHeadersForSession(res); + this.emitter.emit("debug", "session:touch", {}); } return res; @@ -609,6 +630,11 @@ export class AuthClient { authorizationParams.set("state", state); authorizationParams.set("nonce", nonce); + this.emitter.emit("info", "auth:login:start", { + scope: authorizationParams.get("scope") ?? undefined, + audience: authorizationParams.get("audience") ?? undefined + }); + // Add dpop_jkt parameter if DPoP is enabled if (this.dpopKeyPair) { try { @@ -649,6 +675,10 @@ export class AuthClient { ); } + this.emitter.emit("info", "auth:login:redirect", { + authorizationUrl: authorizationUrl.origin + authorizationUrl.pathname + }); + // Set response and save transaction const res = NextResponse.redirect(authorizationUrl.toString()); @@ -678,10 +708,17 @@ export class AuthClient { async handleLogout(req: NextRequest): Promise { const session = await this.sessionStore.get(req.cookies); + + this.emitter.emit("info", "auth:logout:start", { + strategy: this.logoutStrategy, + hasSession: !!session + }); + const [discoveryError, authorizationServerMetadata] = await this.discoverAuthorizationServerMetadata(); if (discoveryError) { + this.emitter.emitError("logout", discoveryError); // Clean up session on discovery error const errorResponse = new NextResponse( "An error occurred while trying to initiate the logout request.", @@ -691,6 +728,10 @@ export class AuthClient { ); await this.sessionStore.delete(req.cookies, errorResponse.cookies); await this.transactionStore.deleteAll(req.cookies, errorResponse.cookies); + this.emitter.emit("info", "session:delete", { reason: "logout" }); + this.emitter.emit("info", "auth:logout:complete", { + sessionDeleted: true + }); return errorResponse; } @@ -757,9 +798,15 @@ export class AuthClient { } else { // Auto strategy (default): Try OIDC first, fallback to v2 if not available if (!authorizationServerMetadata.end_session_endpoint) { - console.warn( - "The Auth0 client does not have RP-initiated logout enabled, the user will be redirected to the `/v2/logout` endpoint instead. Learn how to enable it here: https://auth0.com/docs/authenticate/login/logout/log-users-out-of-auth0#enable-endpoint-discovery" - ); + this.emitter.emit("warn", "auth:logout:fallback", { + reason: "rp_initiated_logout_not_supported", + message: "RP-initiated logout not enabled, falling back to /v2/logout" + }); + if (!this.emitter.hasLogger) { + console.warn( + "The Auth0 client does not have RP-initiated logout enabled, the user will be redirected to the `/v2/logout` endpoint instead. Learn how to enable it here: https://auth0.com/docs/authenticate/login/logout/log-users-out-of-auth0#enable-endpoint-discovery" + ); + } logoutResponse = createV2LogoutResponse(); } else { logoutResponse = createOIDCLogoutResponse(); @@ -773,11 +820,21 @@ export class AuthClient { // Clear any orphaned transaction cookies await this.transactionStore.deleteAll(req.cookies, logoutResponse.cookies); + this.emitter.emit("info", "session:delete", { reason: "logout" }); + this.emitter.emit("info", "auth:logout:complete", { sessionDeleted: true }); + return logoutResponse; } async handleCallback(req: NextRequest): Promise { const state = req.nextUrl.searchParams.get("state"); + + this.emitter.emit("info", "auth:callback:start", { + hasCode: req.nextUrl.searchParams.has("code"), + hasState: !!state, + hasError: req.nextUrl.searchParams.has("error") + }); + if (!state) { return this.handleCallbackError(new MissingStateError(), {}, req); } @@ -1003,6 +1060,11 @@ export class AuthClient { } }; + this.emitter.emit("info", "session:create", { + hasRefreshToken: !!oidcRes.refresh_token, + scope: oidcRes.scope + }); + const res = await this.onCallback(null, onCallbackCtx, session); // call beforeSessionSaved callback if present @@ -1015,6 +1077,11 @@ export class AuthClient { // Clean up the current transaction cookie after successful authentication await this.transactionStore.delete(res.cookies, state); + this.emitter.emit("info", "auth:callback:complete", { + hasRefreshToken: !!oidcRes.refresh_token, + scope: oidcRes.scope + }); + return res; } @@ -1243,6 +1310,8 @@ export class AuthClient { } async handleBackChannelLogout(req: NextRequest): Promise { + this.emitter.emit("info", "auth:backchannel-logout:start", {}); + if (!this.sessionStore.store) { return new NextResponse("A session data store is not configured.", { status: 500 @@ -1270,6 +1339,7 @@ export class AuthClient { const [error, logoutTokenClaims] = await this.verifyLogoutToken(logoutToken); if (error) { + this.emitter.emitError("backchannel_logout", error); return new NextResponse(error.message, { status: 400 }); @@ -1277,6 +1347,11 @@ export class AuthClient { await this.sessionStore.store.deleteByLogoutToken(logoutTokenClaims); + this.emitter.emit("info", "session:delete", { + reason: "backchannel_logout" + }); + this.emitter.emit("info", "auth:backchannel-logout:complete", {}); + return new NextResponse(null, { status: 204 }); @@ -1440,6 +1515,12 @@ export class AuthClient { sessionData: SessionData, options: GetAccessTokenOptions = {} ): Promise<[null, GetTokenSetResponse] | [SdkError, null]> { + this.emitter.emit("debug", "token:get:start", { + audience: options.audience, + hasRefreshToken: !!sessionData.tokenSet.refreshToken, + forceRefresh: !!options.refresh + }); + // This will merge the scopes from the authorization parameters and the options. // The scope from the options will be added to the scopes from the authorization parameters. // If there are duplicate scopes, they will be removed. @@ -1537,6 +1618,9 @@ export class AuthClient { async backchannelAuthentication( options: BackchannelAuthenticationOptions ): Promise<[null, BackchannelAuthenticationResponse] | [SdkError, null]> { + this.emitter.emit("info", "auth:backchannel:start", {}); + const backchannelStart = Date.now(); + const [discoveryError, authorizationServerMetadata] = await this.discoverAuthorizationServerMetadata(); if (discoveryError) { @@ -1609,6 +1693,13 @@ export class AuthClient { Math.floor(Date.now() / 1000) + Number(tokenEndpointResponse.expires_in); + this.emitter.emit( + "info", + "auth:backchannel:complete", + { scope: tokenEndpointResponse.scope }, + Date.now() - backchannelStart + ); + return [ null, { @@ -1624,6 +1715,10 @@ export class AuthClient { } ]; } catch (e: any) { + this.emitter.emitError("backchannel_authentication", e, { + errorType: "BackchannelAuthenticationError", + durationMs: Date.now() - backchannelStart + }); return [ new BackchannelAuthenticationError({ cause: new OAuth2Error({ @@ -1640,10 +1735,14 @@ export class AuthClient { [null, oauth.AuthorizationServer] | [SdkError, null] > { if (this.authorizationServerMetadata) { + this.emitter.emit("debug", "discovery:cache-hit", {}); return [null, this.authorizationServerMetadata]; } const issuer = new URL(this.issuer); + this.emitter.emit("debug", "discovery:start", {}); + + const start = Date.now(); try { const authorizationServerMetadata = await oauth @@ -1656,12 +1755,20 @@ export class AuthClient { this.authorizationServerMetadata = authorizationServerMetadata; + this.emitter.emit("debug", "discovery:complete", {}, Date.now() - start); + return [null, authorizationServerMetadata]; } catch (e) { - console.error( - `An error occurred while performing the discovery request. issuer=${issuer.toString()}, error:`, - e - ); + this.emitter.emitError("discovery", e, { + errorType: "DiscoveryError", + durationMs: Date.now() - start + }); + if (!this.emitter.hasLogger) { + console.error( + `An error occurred while performing the discovery request. issuer=${issuer.toString()}, error:`, + e + ); + } return [ new DiscoveryError( "Discovery failed for the OpenID Connect configuration." @@ -1705,6 +1812,8 @@ export class AuthClient { req: NextRequest, state?: string ): Promise { + this.emitter.emitError("callback", error); + const response = await this.onCallback(error, ctx, null); // Clean up the transaction cookie on error to prevent accumulation @@ -1936,6 +2045,12 @@ export class AuthClient { ): Promise< [AccessTokenForConnectionError, null] | [null, ConnectionTokenSet] > { + this.emitter.emit("debug", "token:connection:start", { + connection: options.connection, + hasCachedToken: !!connectionTokenSet + }); + const connStart = Date.now(); + // If we do not have a refresh token // and we do not have a connection token set in the cache or the one we have is expired, // there is nothing to retrieve and we return an error. @@ -2034,6 +2149,11 @@ export class AuthClient { } ); } catch (err: any) { + this.emitter.emitError("connection_token_exchange", err, { + errorType: "AccessTokenForConnectionError", + code: AccessTokenForConnectionErrorCode.FAILED_TO_EXCHANGE, + durationMs: Date.now() - connStart + }); return [ new AccessTokenForConnectionError( AccessTokenForConnectionErrorCode.FAILED_TO_EXCHANGE, @@ -2047,6 +2167,13 @@ export class AuthClient { ]; } + this.emitter.emit( + "debug", + "token:connection:complete", + { connection: options.connection }, + Date.now() - connStart + ); + return [ null, { @@ -2146,6 +2273,12 @@ export class AuthClient { ): Promise< [CustomTokenExchangeError, null] | [null, CustomTokenExchangeResponse] > { + this.emitter.emit("info", "token:exchange:start", { + subjectTokenType: options.subjectTokenType, + audience: options.audience + }); + const cteStart = Date.now(); + // Note: CTE tokens are not cached per RWA SDK spec. // Caller is responsible for token storage if needed. @@ -2265,6 +2398,10 @@ export class AuthClient { ...this.dpopOptions?.retry }); } catch (err: any) { + this.emitter.emitError("custom_token_exchange", err, { + errorType: "CustomTokenExchangeError", + durationMs: Date.now() - cteStart + }); return [ new CustomTokenExchangeError( CustomTokenExchangeErrorCode.EXCHANGE_FAILED, @@ -2278,6 +2415,16 @@ export class AuthClient { ]; } + this.emitter.emit( + "info", + "token:exchange:complete", + { + subjectTokenType: options.subjectTokenType, + scope: tokenEndpointResponse.scope + }, + Date.now() - cteStart + ); + // Map response: snake_case → camelCase return [ null, @@ -2326,6 +2473,9 @@ export class AuthClient { options: ConnectAccountOptions & { tokenSet: TokenSet }, req?: NextRequest ): Promise<[ConnectAccountError, null] | [null, NextResponse]> { + this.emitter.emit("info", "auth:connect-account:start", { + connection: options.connection + }); const appBaseUrl = resolveAppBaseUrl(this.appBaseUrl, req); const redirectUri = createRouteUrl( this.routes.callback, @@ -2698,6 +2848,7 @@ export class AuthClient { * @throws {MfaGetAuthenticatorsError} On Auth0 API failure */ async mfaGetAuthenticators(encryptedToken: string): Promise { + this.emitter.emit("debug", "mfa:authenticators:start", {}); // Decrypt token to extract context const context = await decryptMfaToken( encryptedToken, @@ -2776,6 +2927,7 @@ export class AuthClient { challengeType: string, authenticatorId?: string ): Promise { + this.emitter.emit("debug", "mfa:challenge:start", { challengeType }); // Decrypt token to extract context const context = await decryptMfaToken( encryptedToken, @@ -2862,6 +3014,9 @@ export class AuthClient { encryptedToken: string, options: Omit ): Promise { + this.emitter.emit("debug", "mfa:enroll:start", { + authenticatorTypes: options.authenticatorTypes + }); // Decrypt token to extract context const context = await decryptMfaToken( encryptedToken, @@ -2934,6 +3089,8 @@ export class AuthClient { * @throws {MfaRequiredError} For chained MFA (with encrypted token) */ async mfaVerify(options: VerifyMfaOptions): Promise { + this.emitter.emit("debug", "mfa:verify:start", {}); + const mfaVerifyStart = Date.now(); // Decrypt token to extract context const { mfaToken, audience, scope } = await decryptMfaToken( options.mfaToken, @@ -3042,6 +3199,13 @@ export class AuthClient { : "Bearer" } as MfaVerifyResponse; + this.emitter.emit( + "debug", + "mfa:verify:complete", + {}, + Date.now() - mfaVerifyStart + ); + return result; } @@ -3322,6 +3486,13 @@ export class AuthClient { | [null, { updatedTokenSet: TokenSet; idTokenClaims: oauth.IDToken }] | [SdkError, null] > { + this.emitter.emit("debug", "token:refresh:start", { + audience: options.audience, + scope: options.scope + }); + + const refreshStart = Date.now(); + const [discoveryError, authorizationServerMetadata] = await this.discoverAuthorizationServerMetadata(); @@ -3386,6 +3557,12 @@ export class AuthClient { } catch (e: any) { // Check if this is an MFA required error if (isMfaRequiredError(e)) { + this.emitter.emit("info", "mfa:required", { + operation: "token_refresh", + audience: options.audience, + hasMfaToken: !!extractMfaErrorDetails(e).mfa_token + }); + const { mfa_token, error_description, mfa_requirements } = extractMfaErrorDetails(e); @@ -3419,9 +3596,11 @@ export class AuthClient { // 1. The refresh token was issued before MFA was enrolled // 2. The API doesn't support step-up (no authorization policies) // User needs to re-authenticate to get a new session with MFA - console.error( - "MFA required but no mfa_token - user needs to re-authenticate" - ); + if (!this.emitter.hasLogger) { + console.error( + "MFA required but no mfa_token - user needs to re-authenticate" + ); + } return [ new MfaRequiredError( error_description ?? @@ -3438,6 +3617,12 @@ export class AuthClient { } } + this.emitter.emitError("token_refresh", e, { + errorType: "AccessTokenError", + code: AccessTokenErrorCode.FAILED_TO_REFRESH_TOKEN, + durationMs: Date.now() - refreshStart + }); + return [ new AccessTokenError( AccessTokenErrorCode.FAILED_TO_REFRESH_TOKEN, @@ -3487,6 +3672,16 @@ export class AuthClient { updatedTokenSet.refreshToken = tokenSet.refreshToken; } + this.emitter.emit( + "debug", + "token:refresh:complete", + { + scope: oauthRes.scope, + rotated: !!oauthRes.refresh_token + }, + Date.now() - refreshStart + ); + return [ null, { diff --git a/src/server/client.ts b/src/server/client.ts index ef897eb81..c590ee9c0 100644 --- a/src/server/client.ts +++ b/src/server/client.ts @@ -28,6 +28,7 @@ import { StartInteractiveLoginOptions, User } from "../types/index.js"; +import type { InstrumentationLogger } from "../types/instrumentation.js"; import { DEFAULT_MFA_CONTEXT_TTL_SECONDS, DEFAULT_SCOPES @@ -52,6 +53,10 @@ import { WithPageAuthRequiredAppRouterOptions, WithPageAuthRequiredPageRouterOptions } from "./helpers/with-page-auth-required.js"; +import { + InstrumentationEmitter, + resolveLoggerFromEnvironment +} from "./instrumentation-emitter.js"; import { ServerMfaClient } from "./mfa/server-mfa-client.js"; import { toNextRequest, toNextResponse } from "./next-compat.js"; import { @@ -221,6 +226,31 @@ export interface Auth0ClientOptions { */ enableTelemetry?: boolean; + /** + * Instrumentation configuration for SDK observability. + * When provided, the SDK emits structured events for auth flow lifecycle, + * token operations, errors, and session management. + * + * @example + * ```typescript + * const auth0 = new Auth0Client({ + * instrumentation: { + * logger: (event) => console.log(`[${event.level}] ${event.event}`, event.data) + * } + * }); + * ``` + */ + instrumentation?: { + /** + * Logger callback invoked synchronously at each instrumentation point. + * If the logger throws, the error is silently swallowed. + * If the logger returns a Promise, it is not awaited. + * + * @see InstrumentationLogger + */ + logger: InstrumentationLogger; + }; + /** * Boolean value to enable the `/auth/access-token` endpoint for use in the client app. * @@ -405,10 +435,17 @@ export class Auth0Client { private routes: Routes; private domain: string; private _mfa?: ServerMfaClient; + private emitter: InstrumentationEmitter; #options: Auth0ClientOptions; constructor(options: Auth0ClientOptions = {}) { this.#options = options; + + // Programmatic logger takes precedence; fall back to env-based logger + const logger = + options.instrumentation?.logger ?? resolveLoggerFromEnvironment(); + this.emitter = new InstrumentationEmitter(logger); + // Extract and validate required options const { domain, @@ -600,7 +637,8 @@ export class Auth0Client { useDPoP: options.useDPoP || false, dpopKeyPair: options.dpopKeyPair || resolvedDpopKeyPair, dpopOptions: options.dpopOptions || resolvedDpopOptions, - mfaTokenTtl + mfaTokenTtl, + logger }); } @@ -812,6 +850,7 @@ export class Auth0Client { tokenSet.idToken ); await this.saveToSession(finalSession, req, res); + this.emitter.emit("debug", "session:refresh", {}); } return { @@ -1060,6 +1099,8 @@ export class Auth0Client { res = toNextResponse(res); } + this.emitter.emit("debug", "session:update", {}); + if (!res) { // app router: Server Actions, Route Handlers const existingSession = await this.getSession(); diff --git a/src/server/index.ts b/src/server/index.ts index 2ac06e8dd..f44cd3e7b 100644 --- a/src/server/index.ts +++ b/src/server/index.ts @@ -27,3 +27,10 @@ export { WithPageAuthRequiredPageRouter, WithPageAuthRequiredAppRouter } from "./helpers/with-page-auth-required.js"; + +// Instrumentation types for logger configuration +export type { + LogLevel, + InstrumentationEvent, + InstrumentationLogger +} from "../types/instrumentation.js"; diff --git a/src/server/instrumentation-emitter.ts b/src/server/instrumentation-emitter.ts new file mode 100644 index 000000000..3b01a59f0 --- /dev/null +++ b/src/server/instrumentation-emitter.ts @@ -0,0 +1,169 @@ +import type { + InstrumentationLogger, + LogLevel +} from "../types/instrumentation.js"; + +/** + * Numeric severity for log level comparison. + * Higher value = more severe. + */ +const LOG_LEVEL_SEVERITY: Record = { + debug: 0, + info: 1, + warn: 2, + error: 3 +}; + +const VALID_LOG_LEVELS = new Set(["debug", "info", "warn", "error"]); +const VALID_LOG_TARGETS = new Set(["console"]); + +/** + * Resolve an InstrumentationLogger from environment variables. + * + * - `AUTH0_LOGGING_TARGET`: Logging target. Currently only `"console"` is supported. + * If unset or invalid, returns `undefined` (no logging). + * - `AUTH0_LOGGING_LEVEL`: Minimum log level to emit. One of `"debug"`, `"info"`, + * `"warn"`, `"error"`. Defaults to `"info"` when a target is configured. + * + * @returns An InstrumentationLogger or undefined if env-based logging is not configured. + */ +export function resolveLoggerFromEnvironment(): + | InstrumentationLogger + | undefined { + const target = process.env.AUTH0_LOGGING_TARGET?.toLowerCase(); + if (!target || !VALID_LOG_TARGETS.has(target)) { + return undefined; + } + + const levelEnv = process.env.AUTH0_LOGGING_LEVEL?.toLowerCase(); + const minLevel: LogLevel = + levelEnv && VALID_LOG_LEVELS.has(levelEnv) + ? (levelEnv as LogLevel) + : "info"; + const minSeverity = LOG_LEVEL_SEVERITY[minLevel]; + + return (event) => { + if (LOG_LEVEL_SEVERITY[event.level] < minSeverity) { + return; + } + + const method = + event.level === "error" + ? "error" + : event.level === "warn" + ? "warn" + : "log"; + + const parts: unknown[] = [ + `[auth0/${event.level}]`, + event.event, + event.data + ]; + if (event.durationMs !== undefined) { + parts.push(`(${event.durationMs}ms)`); + } + // eslint-disable-next-line no-console + console[method](...parts); + }; +} + +/** + * Encapsulates all instrumentation emission logic. + * Constructed with an optional logger and optional base context data + * that is automatically merged into every emitted event. + * No-op when logger is absent. Never lets logger errors propagate to auth flows. + */ +export class InstrumentationEmitter { + /** Whether a logger was configured. Used to gate console.warn/error suppression. */ + readonly hasLogger: boolean; + + private logger?: InstrumentationLogger; + private baseData: Record; + + constructor( + logger?: InstrumentationLogger, + baseData: Record = {} + ) { + this.logger = logger; + this.hasLogger = !!logger; + this.baseData = baseData; + } + + /** + * Emit an instrumentation event to the configured logger. + * Base context data is merged under call-site data (call-site wins on conflict). + * No-op when logger is not configured. Swallows all logger errors. + */ + emit( + level: LogLevel, + event: string, + data: Record, + durationMs?: number + ): void { + if (!this.logger) { + return; + } + + try { + const result: any = this.logger({ + event, + level, + timestamp: new Date().toISOString(), + data: { ...this.baseData, ...data }, + ...(durationMs !== undefined ? { durationMs } : {}) + }); + // Prevent unhandled rejection if logger is async + if (result && typeof result.catch === "function") { + result.catch(() => {}); + } + } catch { + // Swallow - never let logger errors break auth flows + } + } + + /** + * Emit an error-level instrumentation event, extracting fields from the error object. + * + * Extracts from the error: + * - `errorType`: from `error.constructor.name` (overridable via options) + * - `message`: from `error.error_description` (OAuth) → `error.message` → `String(error)` + * - `code`: from `options.code` → `error.code` → `error.error` (OAuth) + */ + emitError( + operation: string, + error: unknown, + options?: { + code?: string | number; + errorType?: string; + durationMs?: number; + } + ): void { + if (!this.logger) { + return; + } + + const isErrorLike = error !== null && typeof error === "object"; + const err = error as Record; + + const errorType = + options?.errorType ?? + (isErrorLike && err.constructor?.name ? err.constructor.name : "Error"); + const message = isErrorLike + ? (err.error_description ?? err.message ?? String(error)) + : String(error); + const code = + options?.code ?? (isErrorLike ? (err.code ?? err.error) : undefined); + + this.emit( + "error", + "error", + { + operation, + errorType, + message, + ...(code !== undefined ? { code } : {}) + }, + options?.durationMs + ); + } +} diff --git a/src/server/instrumentation.flow.test.ts b/src/server/instrumentation.flow.test.ts new file mode 100644 index 000000000..16b300ed5 --- /dev/null +++ b/src/server/instrumentation.flow.test.ts @@ -0,0 +1,650 @@ +import { NextRequest } from "next/server.js"; +import { http, HttpResponse } from "msw"; +import { setupServer } from "msw/node"; +import { + afterAll, + afterEach, + beforeAll, + beforeEach, + describe, + expect, + it, + vi +} from "vitest"; + +import { getDefaultRoutes } from "../test/defaults.js"; +import { generateSecret } from "../test/utils.js"; +import type { SessionData } from "../types/index.js"; +import type { + InstrumentationEvent, + InstrumentationLogger +} from "../types/instrumentation.js"; +import { AuthClient } from "./auth-client.js"; +import { encrypt } from "./cookies.js"; +import { StatelessSessionStore } from "./session/stateless-session-store.js"; +import { TransactionStore } from "./transaction-store.js"; + +// Test constants +const DEFAULT = { + domain: "auth0.local", + clientId: "test-client-id", + clientSecret: "test-client-secret", + appBaseUrl: "http://localhost:3000", + sub: "test-user-id", + sid: "test-session-id", + idToken: "test-id-token", + accessToken: "test-access-token", + refreshToken: "test-refresh-token" +}; + +// Mock authorization server metadata +const authorizationServerMetadata = { + issuer: `https://${DEFAULT.domain}/`, + authorization_endpoint: `https://${DEFAULT.domain}/authorize`, + token_endpoint: `https://${DEFAULT.domain}/oauth/token`, + userinfo_endpoint: `https://${DEFAULT.domain}/userinfo`, + jwks_uri: `https://${DEFAULT.domain}/.well-known/jwks.json`, + end_session_endpoint: `https://${DEFAULT.domain}/oidc/logout`, + response_types_supported: ["code"], + subject_types_supported: ["public"], + id_token_signing_alg_values_supported: ["RS256"], + scopes_supported: ["openid", "profile", "email"] +}; + +const handlers = [ + http.get(`https://${DEFAULT.domain}/.well-known/openid-configuration`, () => { + return HttpResponse.json(authorizationServerMetadata); + }) +]; + +const server = setupServer(...handlers); + +beforeAll(() => { + server.listen({ onUnhandledRequest: "error" }); +}); + +afterEach(() => { + server.resetHandlers(); +}); + +afterAll(() => { + server.close(); +}); + +async function createSessionCookie( + session: SessionData, + secret: string +): Promise { + const maxAge = 60 * 60; + const expiration = Math.floor(Date.now() / 1000 + maxAge); + return await encrypt(session, secret, expiration); +} + +function createTestSetup(logger: InstrumentationLogger) { + let secret: string; + let transactionStore: TransactionStore; + let sessionStore: StatelessSessionStore; + + const setup = async () => { + secret = await generateSecret(32); + transactionStore = new TransactionStore({ secret }); + sessionStore = new StatelessSessionStore({ secret }); + return { + secret, + authClient: new AuthClient({ + domain: DEFAULT.domain, + clientId: DEFAULT.clientId, + clientSecret: DEFAULT.clientSecret, + appBaseUrl: DEFAULT.appBaseUrl, + secret, + transactionStore, + sessionStore, + routes: getDefaultRoutes(), + logger + }), + transactionStore, + sessionStore + }; + }; + + return setup; +} + +describe("Instrumentation Flow Tests", () => { + let events: InstrumentationEvent[]; + let logger: InstrumentationLogger; + let setup: ReturnType; + + beforeEach(() => { + events = []; + logger = (event) => events.push(event); + setup = createTestSetup(logger); + }); + + // FT-1: Login flow emits auth:login:start and auth:login:redirect + describe("FT-1: Login flow", () => { + it("emits auth:login:start and auth:login:redirect", async () => { + const { authClient } = await setup(); + + const req = new NextRequest(`${DEFAULT.appBaseUrl}/auth/login`, { + method: "GET" + }); + + await authClient.handler(req); + + const loginStart = events.find((e) => e.event === "auth:login:start"); + expect(loginStart).toBeDefined(); + expect(loginStart!.level).toBe("info"); + expect(loginStart!.data.domain).toBe(DEFAULT.domain); + + const loginRedirect = events.find( + (e) => e.event === "auth:login:redirect" + ); + expect(loginRedirect).toBeDefined(); + expect(loginRedirect!.level).toBe("info"); + expect(loginRedirect!.data.authorizationUrl).toBeDefined(); + // Must not contain query params (PII protection) + expect( + (loginRedirect!.data.authorizationUrl as string).includes("?") + ).toBe(false); + }); + }); + + // FT-2: Logout flow emits auth:logout:start, session:delete, auth:logout:complete + describe("FT-2: Logout flow", () => { + it("emits logout events with session", async () => { + const { authClient, secret } = await setup(); + + const session: SessionData = { + user: { sub: DEFAULT.sub }, + tokenSet: { + idToken: DEFAULT.idToken, + accessToken: DEFAULT.accessToken, + refreshToken: DEFAULT.refreshToken, + scope: "openid profile email", + expiresAt: Math.floor(Date.now() / 1000) + 3600 + }, + internal: { + sid: DEFAULT.sid, + createdAt: Math.floor(Date.now() / 1000) + } + }; + + const cookieValue = await createSessionCookie(session, secret); + const req = new NextRequest(`${DEFAULT.appBaseUrl}/auth/logout`, { + method: "GET", + headers: { + cookie: `__session=${cookieValue}` + } + }); + + await authClient.handler(req); + + const logoutStart = events.find((e) => e.event === "auth:logout:start"); + expect(logoutStart).toBeDefined(); + expect(logoutStart!.data.hasSession).toBe(true); + expect(logoutStart!.data.strategy).toBeDefined(); + + const sessionDelete = events.find((e) => e.event === "session:delete"); + expect(sessionDelete).toBeDefined(); + expect(sessionDelete!.data.reason).toBe("logout"); + + const logoutComplete = events.find( + (e) => e.event === "auth:logout:complete" + ); + expect(logoutComplete).toBeDefined(); + }); + }); + + // FT-3: Discovery cache hit + describe("FT-3: Discovery caching", () => { + it("emits discovery:start on first call, discovery:cache-hit on second", async () => { + const { authClient } = await setup(); + + // First request triggers discovery + const req1 = new NextRequest(`${DEFAULT.appBaseUrl}/auth/login`, { + method: "GET" + }); + await authClient.handler(req1); + + const discoveryStart = events.find((e) => e.event === "discovery:start"); + expect(discoveryStart).toBeDefined(); + + const discoveryComplete = events.find( + (e) => e.event === "discovery:complete" + ); + expect(discoveryComplete).toBeDefined(); + expect(discoveryComplete!.durationMs).toBeTypeOf("number"); + + // Clear events for second request + events.length = 0; + + // Second login request should hit cache + const req2 = new NextRequest(`${DEFAULT.appBaseUrl}/auth/login`, { + method: "GET" + }); + await authClient.handler(req2); + + const cacheHit = events.find((e) => e.event === "discovery:cache-hit"); + expect(cacheHit).toBeDefined(); + }); + }); + + // FT-4: Discovery failure emits error + describe("FT-4: Discovery failure", () => { + it("emits error event on discovery failure", async () => { + // Override discovery to fail + server.use( + http.get( + `https://${DEFAULT.domain}/.well-known/openid-configuration`, + () => { + return new HttpResponse(null, { status: 500 }); + } + ) + ); + + const { authClient } = await setup(); + const req = new NextRequest(`${DEFAULT.appBaseUrl}/auth/logout`, { + method: "GET" + }); + + await authClient.handler(req); + + const errorEvent = events.find( + (e) => e.event === "error" && e.data.operation === "discovery" + ); + expect(errorEvent).toBeDefined(); + expect(errorEvent!.level).toBe("error"); + expect(errorEvent!.durationMs).toBeTypeOf("number"); + }); + }); + + // FT-5: Callback with missing state emits error + describe("FT-5: Callback error handling", () => { + it("emits error on callback with missing state", async () => { + const { authClient } = await setup(); + const req = new NextRequest(`${DEFAULT.appBaseUrl}/auth/callback`, { + method: "GET" + }); + + await authClient.handler(req); + + const callbackStart = events.find( + (e) => e.event === "auth:callback:start" + ); + expect(callbackStart).toBeDefined(); + expect(callbackStart!.data.hasState).toBe(false); + + const errorEvent = events.find( + (e) => e.event === "error" && e.data.operation === "callback" + ); + expect(errorEvent).toBeDefined(); + expect(errorEvent!.level).toBe("error"); + expect(errorEvent!.data.errorType).toBe("MissingStateError"); + }); + }); + + // FT-6: getTokenSet emits debug events + describe("FT-6: getTokenSet instrumentation", () => { + it("emits token:get:start", async () => { + const { authClient } = await setup(); + + const session: SessionData = { + user: { sub: DEFAULT.sub }, + tokenSet: { + accessToken: DEFAULT.accessToken, + scope: "openid profile email", + expiresAt: Math.floor(Date.now() / 1000) + 3600 + }, + internal: { + sid: DEFAULT.sid, + createdAt: Math.floor(Date.now() / 1000) + } + }; + + await authClient.getTokenSet(session); + + const tokenGetStart = events.find((e) => e.event === "token:get:start"); + expect(tokenGetStart).toBeDefined(); + expect(tokenGetStart!.level).toBe("debug"); + }); + }); + + // FT-7: Backchannel logout emits events + describe("FT-7: Backchannel logout", () => { + it("emits auth:backchannel-logout:start", async () => { + const { authClient } = await setup(); + + // Backchannel logout requires a session store with deleteByLogoutToken + // Without it, it returns 500 but should still emit start + const req = new NextRequest( + `${DEFAULT.appBaseUrl}/auth/backchannel-logout`, + { + method: "POST", + body: "logout_token=test-token" + } + ); + + await authClient.handler(req); + + const bclStart = events.find( + (e) => e.event === "auth:backchannel-logout:start" + ); + expect(bclStart).toBeDefined(); + expect(bclStart!.level).toBe("info"); + }); + }); + + // FT-8: Profile endpoint (no instrumentation expected, just ensure no crash) + describe("FT-8: Profile endpoint", () => { + it("handles profile request without crash when logger present", async () => { + const { authClient } = await setup(); + const req = new NextRequest(`${DEFAULT.appBaseUrl}/auth/profile`, { + method: "GET" + }); + + const res = await authClient.handler(req); + expect(res.status).toBe(401); + }); + }); + + // FT-9: Access token endpoint with no session + describe("FT-9: Access token endpoint", () => { + it("handles access-token request without crash when logger present", async () => { + const { authClient } = await setup(); + const req = new NextRequest(`${DEFAULT.appBaseUrl}/auth/access-token`, { + method: "GET" + }); + + const res = await authClient.handler(req); + expect(res.status).toBe(401); + }); + }); + + // FT-15: session:touch emits on rolling session pass-through + describe("FT-15: Session touch", () => { + it("emits session:touch at debug level on non-auth routes with active session", async () => { + const { authClient, secret } = await setup(); + + const session: SessionData = { + user: { sub: DEFAULT.sub }, + tokenSet: { + accessToken: DEFAULT.accessToken, + scope: "openid profile email", + expiresAt: Math.floor(Date.now() / 1000) + 3600 + }, + internal: { + sid: DEFAULT.sid, + createdAt: Math.floor(Date.now() / 1000) + } + }; + + const cookieValue = await createSessionCookie(session, secret); + const req = new NextRequest(`${DEFAULT.appBaseUrl}/some/page`, { + method: "GET", + headers: { cookie: `__session=${cookieValue}` } + }); + + await authClient.handler(req); + + const touchEvent = events.find((e) => e.event === "session:touch"); + expect(touchEvent).toBeDefined(); + expect(touchEvent!.level).toBe("debug"); + }); + + it("does not emit session:touch when no session exists", async () => { + const { authClient } = await setup(); + + const req = new NextRequest(`${DEFAULT.appBaseUrl}/some/page`, { + method: "GET" + }); + + await authClient.handler(req); + + const touchEvent = events.find((e) => e.event === "session:touch"); + expect(touchEvent).toBeUndefined(); + }); + }); + + // FT-10: Logout fallback warning emits event + suppresses console.warn + describe("FT-10: Logout fallback warning", () => { + it("emits auth:logout:fallback when RP-initiated logout not available", async () => { + server.use( + http.get( + `https://${DEFAULT.domain}/.well-known/openid-configuration`, + () => { + const { end_session_endpoint: _, ...metadataWithout } = + authorizationServerMetadata; + return HttpResponse.json(metadataWithout); + } + ) + ); + + const consoleWarnSpy = vi + .spyOn(console, "warn") + .mockImplementation(() => {}); + + const { authClient } = await setup(); + const req = new NextRequest(`${DEFAULT.appBaseUrl}/auth/logout`, { + method: "GET" + }); + + await authClient.handler(req); + + const fallbackEvent = events.find( + (e) => e.event === "auth:logout:fallback" + ); + expect(fallbackEvent).toBeDefined(); + expect(fallbackEvent!.level).toBe("warn"); + + // console.warn should be suppressed when logger is present + const warnCalls = consoleWarnSpy.mock.calls.map((c) => c[0]); + const hasRpLogoutWarn = warnCalls.some( + (msg) => typeof msg === "string" && msg.includes("RP-initiated logout") + ); + expect(hasRpLogoutWarn).toBe(false); + + consoleWarnSpy.mockRestore(); + }); + }); + + // FT-11: Discovery console.error suppressed when logger present + describe("FT-11: Discovery error console suppression", () => { + it("suppresses console.error when logger is present", async () => { + server.use( + http.get( + `https://${DEFAULT.domain}/.well-known/openid-configuration`, + () => { + return new HttpResponse(null, { status: 500 }); + } + ) + ); + + const consoleErrorSpy = vi + .spyOn(console, "error") + .mockImplementation(() => {}); + + const { authClient } = await setup(); + const req = new NextRequest(`${DEFAULT.appBaseUrl}/auth/logout`, { + method: "GET" + }); + + await authClient.handler(req); + + // console.error should be suppressed when logger present + const errorCalls = consoleErrorSpy.mock.calls.map((c) => c[0]); + const hasDiscoveryError = errorCalls.some( + (msg) => typeof msg === "string" && msg.includes("discovery request") + ); + expect(hasDiscoveryError).toBe(false); + + // Logger should have the error + const errorEvent = events.find( + (e) => e.event === "error" && e.data.operation === "discovery" + ); + expect(errorEvent).toBeDefined(); + + consoleErrorSpy.mockRestore(); + }); + }); + + // FT-12: Event ordering - login flow events are in order + describe("FT-12: Event ordering", () => { + it("login events appear in correct order", async () => { + const { authClient } = await setup(); + const req = new NextRequest(`${DEFAULT.appBaseUrl}/auth/login`, { + method: "GET" + }); + + await authClient.handler(req); + + const eventNames = events.map((e) => e.event); + const loginStartIdx = eventNames.indexOf("auth:login:start"); + const loginRedirectIdx = eventNames.indexOf("auth:login:redirect"); + + expect(loginStartIdx).toBeGreaterThanOrEqual(0); + expect(loginRedirectIdx).toBeGreaterThanOrEqual(0); + expect(loginStartIdx).toBeLessThan(loginRedirectIdx); + }); + }); + + // FT-13: Timestamp format + describe("FT-13: Timestamp format", () => { + it("all events have valid ISO 8601 timestamps", async () => { + const { authClient } = await setup(); + const req = new NextRequest(`${DEFAULT.appBaseUrl}/auth/login`, { + method: "GET" + }); + + await authClient.handler(req); + + for (const event of events) { + expect(event.timestamp).toMatch( + /^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{3}Z$/ + ); + } + }); + }); + + // FT-14: Multiple flows don't cross-contaminate + describe("FT-14: No cross-contamination between flows", () => { + it("events from separate flows are independent", async () => { + const { authClient, secret } = await setup(); + + // Login flow + const loginReq = new NextRequest(`${DEFAULT.appBaseUrl}/auth/login`, { + method: "GET" + }); + await authClient.handler(loginReq); + + const loginEvents = [...events]; + events.length = 0; + + // Logout flow + const session: SessionData = { + user: { sub: DEFAULT.sub }, + tokenSet: { + accessToken: DEFAULT.accessToken, + scope: "openid profile email", + expiresAt: Math.floor(Date.now() / 1000) + 3600 + }, + internal: { + sid: DEFAULT.sid, + createdAt: Math.floor(Date.now() / 1000) + } + }; + const cookieValue = await createSessionCookie(session, secret); + const logoutReq = new NextRequest(`${DEFAULT.appBaseUrl}/auth/logout`, { + method: "GET", + headers: { cookie: `__session=${cookieValue}` } + }); + await authClient.handler(logoutReq); + + const logoutEvents = events; + + // Login events should not contain logout events + expect(loginEvents.some((e) => e.event.includes("logout"))).toBe(false); + // Logout events should not contain login:redirect events + expect(logoutEvents.some((e) => e.event === "auth:login:redirect")).toBe( + false + ); + }); + }); + + // EC-9: Logger throwing during flow does not break auth + describe("EC-9: Logger exception during flow", () => { + it("auth flow completes even when logger throws on every call", async () => { + let callCount = 0; + const throwingLogger: InstrumentationLogger = () => { + callCount++; + throw new Error(`Logger error #${callCount}`); + }; + + const throwSetup = createTestSetup(throwingLogger); + const { authClient } = await throwSetup(); + + const req = new NextRequest(`${DEFAULT.appBaseUrl}/auth/login`, { + method: "GET" + }); + + const res = await authClient.handler(req); + // Should still redirect (302) + expect(res.status).toBe(307); + expect(callCount).toBeGreaterThan(0); + }); + }); + + // EC-10: Slow async logger does not block flow + describe("EC-10: Slow async logger", () => { + it("auth flow does not wait for slow logger", async () => { + let resolveLogger: () => void; + const slowLogger: InstrumentationLogger = () => { + // Return a promise that resolves after 5 seconds (but we don't await it) + return new Promise((resolve) => + setTimeout(() => { + resolve(undefined); + resolveLogger!(); + }, 5000) + ) as any; + }; + + const slowSetup = createTestSetup(slowLogger); + const { authClient } = await slowSetup(); + + const start = Date.now(); + const req = new NextRequest(`${DEFAULT.appBaseUrl}/auth/login`, { + method: "GET" + }); + + const res = await authClient.handler(req); + const elapsed = Date.now() - start; + + // Should complete in well under 5 seconds + expect(elapsed).toBeLessThan(2000); + expect(res.status).toBe(307); + }); + }); + + // EC-11: Callback start has correct boolean data + describe("EC-11: Callback event data accuracy", () => { + it("auth:callback:start has accurate boolean fields", async () => { + const { authClient } = await setup(); + + // Callback with error param + const req = new NextRequest( + `${DEFAULT.appBaseUrl}/auth/callback?error=access_denied&state=abc`, + { method: "GET" } + ); + + await authClient.handler(req); + + const callbackStart = events.find( + (e) => e.event === "auth:callback:start" + ); + expect(callbackStart).toBeDefined(); + expect(callbackStart!.data.hasError).toBe(true); + expect(callbackStart!.data.hasState).toBe(true); + expect(callbackStart!.data.hasCode).toBe(false); + }); + }); +}); diff --git a/src/server/instrumentation.test.ts b/src/server/instrumentation.test.ts new file mode 100644 index 000000000..ab37d47e3 --- /dev/null +++ b/src/server/instrumentation.test.ts @@ -0,0 +1,761 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; + +import { getDefaultRoutes } from "../test/defaults.js"; +import { generateSecret } from "../test/utils.js"; +import type { + InstrumentationEvent, + InstrumentationLogger +} from "../types/instrumentation.js"; +import { AuthClient } from "./auth-client.js"; +import { + InstrumentationEmitter, + resolveLoggerFromEnvironment +} from "./instrumentation-emitter.js"; +import { StatelessSessionStore } from "./session/stateless-session-store.js"; +import { TransactionStore } from "./transaction-store.js"; + +// Test constants +const DEFAULT = { + domain: "auth0.local", + clientId: "test-client-id", + clientSecret: "test-client-secret", + appBaseUrl: "http://localhost:3000" +}; + +function createAuthClient( + secret: string, + logger?: InstrumentationLogger, + overrides?: Record +): AuthClient { + const transactionStore = new TransactionStore({ secret }); + const sessionStore = new StatelessSessionStore({ secret }); + + return new AuthClient({ + domain: DEFAULT.domain, + clientId: DEFAULT.clientId, + clientSecret: DEFAULT.clientSecret, + appBaseUrl: DEFAULT.appBaseUrl, + secret, + transactionStore, + sessionStore, + routes: getDefaultRoutes(), + logger, + ...overrides + }); +} + +describe("InstrumentationEmitter", () => { + it("hasLogger is false when no logger provided", () => { + const emitter = new InstrumentationEmitter(); + expect(emitter.hasLogger).toBe(false); + }); + + it("hasLogger is true when logger provided", () => { + const emitter = new InstrumentationEmitter(() => {}); + expect(emitter.hasLogger).toBe(true); + }); + + it("emit is a no-op when no logger configured", () => { + const emitter = new InstrumentationEmitter(); + // Should not throw + emitter.emit("info", "test:event", { key: "value" }); + }); + + it("emit calls logger with correct shape", () => { + const events: InstrumentationEvent[] = []; + const emitter = new InstrumentationEmitter((e) => events.push(e)); + + emitter.emit("info", "test:event", { key: "value" }); + + expect(events).toHaveLength(1); + expect(events[0].event).toBe("test:event"); + expect(events[0].level).toBe("info"); + expect(events[0].data).toEqual({ key: "value" }); + expect(events[0].durationMs).toBeUndefined(); + }); + + it("emit includes durationMs when provided", () => { + const events: InstrumentationEvent[] = []; + const emitter = new InstrumentationEmitter((e) => events.push(e)); + + emitter.emit("debug", "timed:op", {}, 42); + + expect(events[0].durationMs).toBe(42); + }); + + it("swallows synchronous logger errors", () => { + const emitter = new InstrumentationEmitter(() => { + throw new Error("boom"); + }); + // Should not throw + emitter.emit("info", "test", {}); + }); + + it("swallows async logger rejections", () => { + const emitter = new InstrumentationEmitter(() => { + return Promise.reject(new Error("async boom")) as any; + }); + // Should not throw + emitter.emit("info", "test", {}); + }); + + describe("base context", () => { + it("merges baseData into every emitted event", () => { + const events: InstrumentationEvent[] = []; + const emitter = new InstrumentationEmitter((e) => events.push(e), { + domain: "example.auth0.com" + }); + + emitter.emit("info", "test:event", { key: "value" }); + + expect(events[0].data).toEqual({ + domain: "example.auth0.com", + key: "value" + }); + }); + + it("call-site data overrides baseData on conflict", () => { + const events: InstrumentationEvent[] = []; + const emitter = new InstrumentationEmitter((e) => events.push(e), { + domain: "base.auth0.com" + }); + + emitter.emit("info", "test:event", { domain: "override.auth0.com" }); + + expect(events[0].data.domain).toBe("override.auth0.com"); + }); + + it("works with empty baseData", () => { + const events: InstrumentationEvent[] = []; + const emitter = new InstrumentationEmitter((e) => events.push(e), {}); + + emitter.emit("info", "test:event", { key: "value" }); + + expect(events[0].data).toEqual({ key: "value" }); + }); + }); + + describe("emitError", () => { + it("extracts errorType and message from standard Error", () => { + const events: InstrumentationEvent[] = []; + const emitter = new InstrumentationEmitter((e) => events.push(e)); + + class DiscoveryError extends Error { + constructor(msg: string) { + super(msg); + this.name = "DiscoveryError"; + } + } + + emitter.emitError("discovery", new DiscoveryError("not found")); + + expect(events[0].level).toBe("error"); + expect(events[0].event).toBe("error"); + expect(events[0].data).toEqual({ + operation: "discovery", + errorType: "DiscoveryError", + message: "not found" + }); + }); + + it("extracts error_description and error from OAuth-style errors", () => { + const events: InstrumentationEvent[] = []; + const emitter = new InstrumentationEmitter((e) => events.push(e)); + + const oauthError = { + error: "invalid_grant", + error_description: "The refresh token is expired" + }; + + emitter.emitError("token_refresh", oauthError); + + expect(events[0].data).toEqual({ + operation: "token_refresh", + errorType: "Object", + message: "The refresh token is expired", + code: "invalid_grant" + }); + }); + + it("allows overriding errorType and code", () => { + const events: InstrumentationEvent[] = []; + const emitter = new InstrumentationEmitter((e) => events.push(e)); + + emitter.emitError("cte", new Error("fail"), { + errorType: "CustomTokenExchangeError", + code: "EXCHANGE_FAILED" + }); + + expect(events[0].data.errorType).toBe("CustomTokenExchangeError"); + expect(events[0].data.code).toBe("EXCHANGE_FAILED"); + }); + + it("passes durationMs through", () => { + const events: InstrumentationEvent[] = []; + const emitter = new InstrumentationEmitter((e) => events.push(e)); + + emitter.emitError("discovery", new Error("timeout"), { + durationMs: 5000 + }); + + expect(events[0].durationMs).toBe(5000); + }); + + it("includes baseData in error events", () => { + const events: InstrumentationEvent[] = []; + const emitter = new InstrumentationEmitter((e) => events.push(e), { + domain: "example.auth0.com" + }); + + emitter.emitError("callback", new Error("bad state")); + + expect(events[0].data.domain).toBe("example.auth0.com"); + expect(events[0].data.operation).toBe("callback"); + }); + + it("omits code when not available", () => { + const events: InstrumentationEvent[] = []; + const emitter = new InstrumentationEmitter((e) => events.push(e)); + + emitter.emitError("logout", new Error("failed")); + + expect(events[0].data).not.toHaveProperty("code"); + }); + + it("is no-op when no logger configured", () => { + const emitter = new InstrumentationEmitter(); + // Should not throw + emitter.emitError("test", new Error("boom")); + }); + + it("handles non-Error values", () => { + const events: InstrumentationEvent[] = []; + const emitter = new InstrumentationEmitter((e) => events.push(e)); + + emitter.emitError("test", "string error"); + + expect(events[0].data.errorType).toBe("Error"); + expect(events[0].data.message).toBe("string error"); + }); + }); +}); + +describe("Instrumentation - Type Shape", () => { + // UT-1: InstrumentationEvent has correct shape + it("UT-1: event emitted by logger conforms to InstrumentationEvent shape", () => { + const events: InstrumentationEvent[] = []; + const logger: InstrumentationLogger = (event) => events.push(event); + + // Trigger a constructor warning by enabling insecure requests in production + const origEnv = process.env.NODE_ENV; + + (process.env as any).NODE_ENV = "production"; + try { + const secret = "a".repeat(64); + createAuthClient(secret, logger, { allowInsecureRequests: true }); + } catch { + // ignore constructor errors + } finally { + (process.env as any).NODE_ENV = origEnv; + } + + // At minimum, the insecure requests warning should have been emitted + expect(events.length).toBeGreaterThan(0); + const event = events[0]; + expect(event).toHaveProperty("event"); + expect(event).toHaveProperty("level"); + expect(event).toHaveProperty("timestamp"); + expect(event).toHaveProperty("data"); + expect(typeof event.event).toBe("string"); + expect(["debug", "info", "warn", "error"]).toContain(event.level); + // ISO 8601 timestamp + expect(new Date(event.timestamp).toISOString()).toBe(event.timestamp); + expect(typeof event.data).toBe("object"); + }); + + // UT-2: LogLevel is one of the 4 valid strings + it("UT-2: LogLevel values are restricted to debug|info|warn|error", () => { + // Already checked via type system, but verify runtime values + const events: InstrumentationEvent[] = []; + const logger: InstrumentationLogger = (event) => events.push(event); + + const origEnv = process.env.NODE_ENV; + + (process.env as any).NODE_ENV = "production"; + try { + const secret = "a".repeat(64); + createAuthClient(secret, logger, { allowInsecureRequests: true }); + } catch { + // ignore + } finally { + (process.env as any).NODE_ENV = origEnv; + } + + for (const event of events) { + expect(["debug", "info", "warn", "error"]).toContain(event.level); + } + }); + + // UT-3: durationMs is present only on timed operations + it("UT-3: durationMs is present on timed events, absent otherwise", () => { + // We'll test this in the flow tests where timed operations occur. + // Here, verify the constructor warning has no durationMs. + const events: InstrumentationEvent[] = []; + const logger: InstrumentationLogger = (event) => events.push(event); + + const origEnv = process.env.NODE_ENV; + + (process.env as any).NODE_ENV = "production"; + try { + const secret = "a".repeat(64); + createAuthClient(secret, logger, { allowInsecureRequests: true }); + } catch { + // ignore + } finally { + (process.env as any).NODE_ENV = origEnv; + } + + const warnEvent = events.find( + (e) => e.event === "config:insecure-requests" + ); + expect(warnEvent).toBeDefined(); + expect(warnEvent!.durationMs).toBeUndefined(); + }); +}); + +describe("Instrumentation - emit() Guard / Error Handling", () => { + let secret: string; + + beforeEach(async () => { + secret = await generateSecret(32); + }); + + // UT-4: No logger configured -> no events emitted (no-op) + it("UT-4: no logger configured means no events emitted", () => { + // Simply construct without logger and ensure no crash + const client = createAuthClient(secret, undefined); + expect(client).toBeDefined(); + }); + + // UT-5: Logger that throws synchronously does not break auth flow + it("UT-5: synchronous throw in logger is swallowed", () => { + const throwingLogger: InstrumentationLogger = () => { + throw new Error("Logger exploded"); + }; + + const origEnv = process.env.NODE_ENV; + + (process.env as any).NODE_ENV = "production"; + try { + // Should not throw + const client = createAuthClient(secret, throwingLogger, { + allowInsecureRequests: true + }); + expect(client).toBeDefined(); + } finally { + (process.env as any).NODE_ENV = origEnv; + } + }); + + // EC-1: Async logger rejection is swallowed + it("EC-1: async logger rejection is swallowed", () => { + const asyncThrowingLogger: InstrumentationLogger = () => { + return Promise.reject(new Error("Async logger exploded")) as any; + }; + + const origEnv = process.env.NODE_ENV; + + (process.env as any).NODE_ENV = "production"; + try { + const client = createAuthClient(secret, asyncThrowingLogger, { + allowInsecureRequests: true + }); + expect(client).toBeDefined(); + } finally { + (process.env as any).NODE_ENV = origEnv; + } + }); +}); + +describe("Instrumentation - PII Filtering", () => { + let secret: string; + + beforeEach(async () => { + secret = await generateSecret(32); + }); + + // UT-12 through UT-20: Verify no PII in emitted events + it("UT-12: emitted events never contain access tokens, refresh tokens, or PII", () => { + const events: InstrumentationEvent[] = []; + const logger: InstrumentationLogger = (event) => events.push(event); + + const origEnv = process.env.NODE_ENV; + + (process.env as any).NODE_ENV = "production"; + try { + createAuthClient(secret, logger, { allowInsecureRequests: true }); + } catch { + // ignore + } finally { + (process.env as any).NODE_ENV = origEnv; + } + + for (const event of events) { + const serialized = JSON.stringify(event); + // Must not contain any tokens or secrets + expect(serialized).not.toContain(secret); + expect(serialized).not.toContain("access_token"); + expect(serialized).not.toContain("refresh_token"); + expect(serialized).not.toContain("id_token"); + } + }); +}); + +describe("Instrumentation - Console.warn/error Suppression", () => { + let secret: string; + let consoleWarnSpy: ReturnType; + let consoleErrorSpy: ReturnType; + + beforeEach(async () => { + secret = await generateSecret(32); + consoleWarnSpy = vi.spyOn(console, "warn").mockImplementation(() => {}); + consoleErrorSpy = vi.spyOn(console, "error").mockImplementation(() => {}); + }); + + afterEach(() => { + consoleWarnSpy.mockRestore(); + consoleErrorSpy.mockRestore(); + }); + + // G2: console.warn for insecure requests is suppressed when logger is present + it("G2: console.warn for insecure requests is suppressed when logger present", () => { + const events: InstrumentationEvent[] = []; + const logger: InstrumentationLogger = (event) => events.push(event); + + const origEnv = process.env.NODE_ENV; + + (process.env as any).NODE_ENV = "production"; + try { + createAuthClient(secret, logger, { allowInsecureRequests: true }); + } catch { + // ignore + } finally { + (process.env as any).NODE_ENV = origEnv; + } + + // Logger should have received the event + const warnEvent = events.find( + (e) => e.event === "config:insecure-requests" + ); + expect(warnEvent).toBeDefined(); + + // console.warn should NOT have been called for this specific message + const warnCalls = consoleWarnSpy.mock.calls.map((c) => c[0]); + const hasInsecureWarn = warnCalls.some( + (msg) => typeof msg === "string" && msg.includes("allowInsecureRequests") + ); + expect(hasInsecureWarn).toBe(false); + }); + + it("console.warn for insecure requests IS emitted when no logger", () => { + const origEnv = process.env.NODE_ENV; + + (process.env as any).NODE_ENV = "production"; + try { + createAuthClient(secret, undefined, { allowInsecureRequests: true }); + } catch { + // ignore + } finally { + (process.env as any).NODE_ENV = origEnv; + } + + const warnCalls = consoleWarnSpy.mock.calls.map((c) => c[0]); + const hasInsecureWarn = warnCalls.some( + (msg) => typeof msg === "string" && msg.includes("allowInsecureRequests") + ); + expect(hasInsecureWarn).toBe(true); + }); +}); + +describe("resolveLoggerFromEnvironment", () => { + let origTarget: string | undefined; + let origLevel: string | undefined; + + beforeEach(() => { + origTarget = process.env.AUTH0_LOGGING_TARGET; + origLevel = process.env.AUTH0_LOGGING_LEVEL; + delete process.env.AUTH0_LOGGING_TARGET; + delete process.env.AUTH0_LOGGING_LEVEL; + }); + + afterEach(() => { + if (origTarget !== undefined) { + process.env.AUTH0_LOGGING_TARGET = origTarget; + } else { + delete process.env.AUTH0_LOGGING_TARGET; + } + if (origLevel !== undefined) { + process.env.AUTH0_LOGGING_LEVEL = origLevel; + } else { + delete process.env.AUTH0_LOGGING_LEVEL; + } + }); + + it("returns undefined when AUTH0_LOGGING_TARGET is not set", () => { + expect(resolveLoggerFromEnvironment()).toBeUndefined(); + }); + + it("returns undefined when AUTH0_LOGGING_TARGET is empty string", () => { + process.env.AUTH0_LOGGING_TARGET = ""; + expect(resolveLoggerFromEnvironment()).toBeUndefined(); + }); + + it("returns undefined when AUTH0_LOGGING_TARGET is an invalid value", () => { + process.env.AUTH0_LOGGING_TARGET = "FILE"; + expect(resolveLoggerFromEnvironment()).toBeUndefined(); + }); + + it("returns a logger when AUTH0_LOGGING_TARGET is console", () => { + process.env.AUTH0_LOGGING_TARGET = "console"; + const logger = resolveLoggerFromEnvironment(); + expect(logger).toBeTypeOf("function"); + }); + + it("is case-insensitive for AUTH0_LOGGING_TARGET", () => { + process.env.AUTH0_LOGGING_TARGET = "console"; + expect(resolveLoggerFromEnvironment()).toBeTypeOf("function"); + }); + + it("defaults to info level when AUTH0_LOGGING_LEVEL is not set", () => { + process.env.AUTH0_LOGGING_TARGET = "console"; + const logger = resolveLoggerFromEnvironment()!; + + const consoleSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + const consoleWarnSpy = vi + .spyOn(console, "warn") + .mockImplementation(() => {}); + const consoleErrorSpy = vi + .spyOn(console, "error") + .mockImplementation(() => {}); + + // debug should be filtered out + logger({ + event: "discovery:start", + level: "debug", + timestamp: new Date().toISOString(), + data: {} + }); + expect(consoleSpy).not.toHaveBeenCalled(); + + // info should pass through + logger({ + event: "auth:login:start", + level: "info", + timestamp: new Date().toISOString(), + data: { domain: "test.auth0.com" } + }); + expect(consoleSpy).toHaveBeenCalledTimes(1); + + consoleSpy.mockRestore(); + consoleWarnSpy.mockRestore(); + consoleErrorSpy.mockRestore(); + }); + + it("respects AUTH0_LOGGING_LEVEL=debug — emits all levels", () => { + process.env.AUTH0_LOGGING_TARGET = "console"; + process.env.AUTH0_LOGGING_LEVEL = "debug"; + const logger = resolveLoggerFromEnvironment()!; + + const consoleSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + + logger({ + event: "discovery:start", + level: "debug", + timestamp: new Date().toISOString(), + data: {} + }); + expect(consoleSpy).toHaveBeenCalledTimes(1); + + consoleSpy.mockRestore(); + }); + + it("respects AUTH0_LOGGING_LEVEL=warn — filters out debug and info", () => { + process.env.AUTH0_LOGGING_TARGET = "console"; + process.env.AUTH0_LOGGING_LEVEL = "warn"; + const logger = resolveLoggerFromEnvironment()!; + + const consoleSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + const consoleWarnSpy = vi + .spyOn(console, "warn") + .mockImplementation(() => {}); + + logger({ + event: "auth:login:start", + level: "info", + timestamp: new Date().toISOString(), + data: {} + }); + expect(consoleSpy).not.toHaveBeenCalled(); + + logger({ + event: "auth:logout:fallback", + level: "warn", + timestamp: new Date().toISOString(), + data: {} + }); + expect(consoleWarnSpy).toHaveBeenCalledTimes(1); + + consoleSpy.mockRestore(); + consoleWarnSpy.mockRestore(); + }); + + it("respects AUTH0_LOGGING_LEVEL=error — only errors pass through", () => { + process.env.AUTH0_LOGGING_TARGET = "console"; + process.env.AUTH0_LOGGING_LEVEL = "error"; + const logger = resolveLoggerFromEnvironment()!; + + const consoleSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + const consoleWarnSpy = vi + .spyOn(console, "warn") + .mockImplementation(() => {}); + const consoleErrorSpy = vi + .spyOn(console, "error") + .mockImplementation(() => {}); + + logger({ + event: "auth:login:start", + level: "info", + timestamp: new Date().toISOString(), + data: {} + }); + logger({ + event: "auth:logout:fallback", + level: "warn", + timestamp: new Date().toISOString(), + data: {} + }); + expect(consoleSpy).not.toHaveBeenCalled(); + expect(consoleWarnSpy).not.toHaveBeenCalled(); + + logger({ + event: "error", + level: "error", + timestamp: new Date().toISOString(), + data: { operation: "callback" } + }); + expect(consoleErrorSpy).toHaveBeenCalledTimes(1); + + consoleSpy.mockRestore(); + consoleWarnSpy.mockRestore(); + consoleErrorSpy.mockRestore(); + }); + + it("defaults to info when AUTH0_LOGGING_LEVEL is invalid", () => { + process.env.AUTH0_LOGGING_TARGET = "console"; + process.env.AUTH0_LOGGING_LEVEL = "verbose"; + const logger = resolveLoggerFromEnvironment()!; + + const consoleSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + + // debug should be filtered (defaulted to info) + logger({ + event: "discovery:start", + level: "debug", + timestamp: new Date().toISOString(), + data: {} + }); + expect(consoleSpy).not.toHaveBeenCalled(); + + // info should pass + logger({ + event: "auth:login:start", + level: "info", + timestamp: new Date().toISOString(), + data: {} + }); + expect(consoleSpy).toHaveBeenCalledTimes(1); + + consoleSpy.mockRestore(); + }); + + it("is case-insensitive for AUTH0_LOGGING_LEVEL", () => { + process.env.AUTH0_LOGGING_TARGET = "console"; + process.env.AUTH0_LOGGING_LEVEL = "DEBUG"; + const logger = resolveLoggerFromEnvironment()!; + + const consoleSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + + logger({ + event: "discovery:start", + level: "debug", + timestamp: new Date().toISOString(), + data: {} + }); + expect(consoleSpy).toHaveBeenCalledTimes(1); + + consoleSpy.mockRestore(); + }); + + it("uses console.error for error-level events", () => { + process.env.AUTH0_LOGGING_TARGET = "console"; + const logger = resolveLoggerFromEnvironment()!; + + const consoleErrorSpy = vi + .spyOn(console, "error") + .mockImplementation(() => {}); + + logger({ + event: "error", + level: "error", + timestamp: new Date().toISOString(), + data: { operation: "callback" } + }); + expect(consoleErrorSpy).toHaveBeenCalledTimes(1); + expect(consoleErrorSpy.mock.calls[0][0]).toBe("[auth0/error]"); + + consoleErrorSpy.mockRestore(); + }); + + it("uses console.warn for warn-level events", () => { + process.env.AUTH0_LOGGING_TARGET = "console"; + const logger = resolveLoggerFromEnvironment()!; + + const consoleWarnSpy = vi + .spyOn(console, "warn") + .mockImplementation(() => {}); + + logger({ + event: "auth:logout:fallback", + level: "warn", + timestamp: new Date().toISOString(), + data: {} + }); + expect(consoleWarnSpy).toHaveBeenCalledTimes(1); + expect(consoleWarnSpy.mock.calls[0][0]).toBe("[auth0/warn]"); + + consoleWarnSpy.mockRestore(); + }); + + it("includes durationMs in output when present", () => { + process.env.AUTH0_LOGGING_TARGET = "console"; + const logger = resolveLoggerFromEnvironment()!; + + const consoleSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + + logger({ + event: "discovery:complete", + level: "info", + timestamp: new Date().toISOString(), + data: { domain: "test.auth0.com" }, + durationMs: 150 + }); + expect(consoleSpy).toHaveBeenCalledWith( + "[auth0/info]", + "discovery:complete", + { domain: "test.auth0.com" }, + "(150ms)" + ); + + consoleSpy.mockRestore(); + }); +}); diff --git a/src/server/mfa-server.flow.test.ts b/src/server/mfa-server.flow.test.ts index add0b0879..a890bcfd8 100644 --- a/src/server/mfa-server.flow.test.ts +++ b/src/server/mfa-server.flow.test.ts @@ -435,9 +435,8 @@ describe("AuthClient MFA Methods", () => { }); it("should cache access token in session when cookies provided", async () => { - const { RequestCookies, ResponseCookies } = await import( - "@edge-runtime/cookies" - ); + const edgeCookies = await import("@edge-runtime/cookies"); + const { RequestCookies, ResponseCookies } = edgeCookies; const session: SessionData = { user: { sub: DEFAULT.sub }, diff --git a/src/types/index.ts b/src/types/index.ts index 4ffed2395..feffd7c6d 100644 --- a/src/types/index.ts +++ b/src/types/index.ts @@ -205,3 +205,9 @@ export { GRANT_TYPE_MFA_OOB, GRANT_TYPE_MFA_RECOVERY_CODE } from "./mfa.js"; + +export type { + LogLevel, + InstrumentationEvent, + InstrumentationLogger +} from "./instrumentation.js"; diff --git a/src/types/instrumentation.ts b/src/types/instrumentation.ts new file mode 100644 index 000000000..63e7f8eab --- /dev/null +++ b/src/types/instrumentation.ts @@ -0,0 +1,55 @@ +/** + * Severity/category of an instrumentation event. + * + * - `'debug'`: Verbose, dev-only. Includes discovery details, session reads, MFA steps. + * - `'info'`: General operational events. Auth flow start/complete, session create/delete. + * - `'warn'`: Unexpected but recoverable situations. + * - `'error'`: Failures that affect the auth flow. + */ +export type LogLevel = "debug" | "info" | "warn" | "error"; + +/** + * A single instrumentation event emitted by the SDK. + * All fields are PII-filtered by the SDK before emission. + * + * @example + * ```typescript + * { + * event: 'auth:login:start', + * level: 'info', + * timestamp: '2026-02-18T12:00:00.000Z', + * data: { domain: 'example.auth0.com', scope: 'openid profile' } + * } + * ``` + */ +export interface InstrumentationEvent { + /** Event name, namespaced: 'auth:login:start', 'discovery:start', etc. */ + event: string; + + /** Severity / category */ + level: LogLevel; + + /** ISO 8601 timestamp of when the event was emitted */ + timestamp: string; + + /** PII-filtered event data. Shape varies per event type. */ + data: Record; + + /** Duration in ms for timed operations (present on 'complete' events) */ + durationMs?: number; +} + +/** + * Logger callback provided by the consumer. + * The SDK calls this synchronously at each instrumentation point. + * If the logger throws, the error is silently swallowed. + * If the logger returns a Promise, it is not awaited. + * + * @example + * ```typescript + * const logger: InstrumentationLogger = (event) => { + * console.log(`[${event.level}] ${event.event}`, event.data); + * }; + * ``` + */ +export type InstrumentationLogger = (event: InstrumentationEvent) => void;