import { Hono } from 'hono' import { requestId } from 'hono/request-id' import type { Hex } from 'ox' import * as Log from './Log.js' import * as Response from './Response.js' import * as Timing from './Timing.js' function app(options: { emit: Log.Emit }) { const app = new Hono() app.use('*', requestId()) app.use('*', Log.middleware(options)) app.use('*', Timing.middleware()) return app } function stable(entry: Log.Entry) { const { duration: _duration, requestId: _requestId, timings: _timings, ...rest } = entry return rest } describe('middleware', () => { test('emits one canonical entry per request', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.get('/things/:id', async (c) => { await Timing.time(c, 'rpc.example', () => Promise.resolve()) return c.json({ ok: true }, 200) }) await api.request('/things/42?chainId=4217') expect(entries.length).toMatchInlineSnapshot(`1`) const entry = entries[0]! expect(typeof entry.duration).toMatchInlineSnapshot(`"number"`) expect(typeof entry.requestId).toMatchInlineSnapshot(`"string"`) expect(Object.keys(entry.timings ?? {})).toMatchInlineSnapshot(` [ "rpc.example", ] `) expect(stable(entry)).toMatchInlineSnapshot(` { "level": "info", "method": "GET", "path": "/things/42", "query": "chainId=4217", "route": "/things/:id", "status": 200, } `) }) test('includes failed optional funding counts', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.get('/v1/funding/transfers', (c) => { c.set('fundingDepositCountFailed', true) c.set('fundingTransferCountFailed', true) return c.json({ data: [], nextCursor: null }, 200) }) await api.request('/v1/funding/transfers?include=totalCount') expect(stable(entries[0]!)).toMatchInlineSnapshot(` { "fundingDepositCountFailed": true, "fundingTransferCountFailed": true, "level": "info", "method": "GET", "path": "/v1/funding/transfers", "query": "include=totalCount", "route": "/v1/funding/transfers", "status": 200, } `) }) test('keeps the longest duration when a timing name repeats', async () => { vi.useFakeTimers() try { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.get('/', async (c) => { await Timing.time(c, 'transactions', () => vi.advanceTimersByTime(20)) await Timing.time(c, 'transactions', () => vi.advanceTimersByTime(5)) return c.json({ ok: true }, 200) }) await api.request('/') expect(entries[0]?.timings).toMatchInlineSnapshot(` { "transactions": 20, } `) } finally { vi.useRealTimers() } }) test('includes the caller principal, never the raw token', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.use('*', async (c, next) => { c.set('principal', { apiKey: { allowedIps: [], environment: 'production', id: 'key_1', orgId: 'org_1', scopes: ['data:read'], }, environment: 'production', id: 'key_1', orgId: 'org_1', type: 'api_key', }) await next() }) api.get('/secure', (c) => c.json({ ok: true }, 200)) await api.request('/secure?key=opaque-secret&chainId=mainnet') expect(stable(entries[0]!)).toMatchInlineSnapshot(` { "level": "info", "method": "GET", "path": "/secure", "principal": { "billingActive": false, "environment": "production", "id": "key_1", "orgId": "org_1", "type": "api_key", }, "query": "chainId=mainnet", "route": "/secure", "status": 200, } `) }) test('includes the MPP payment reason for paid calls', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.use('*', async (c, next) => { c.set('principal', { id: 'ip:203.0.113.7', payment: { payer: `0x${'aa'.repeat(20)}`, reason: 'public_over_quota', type: 'mpp' }, type: 'public', }) await next() }) api.get('/paid', (c) => c.json({ ok: true }, 200)) await api.request('/paid') expect(stable(entries[0]!)).toMatchInlineSnapshot(` { "level": "info", "method": "GET", "path": "/paid", "payment": "public_over_quota", "principal": { "id": "ip:203.0.113.7", "type": "public", }, "route": "/paid", "status": 200, } `) }) test('records the error code and warn level for error envelopes', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.get('/missing', (c) => Response.error(c, { code: 'not_found', message: 'Route not found', status: 404 }), ) await api.request('/missing') expect(stable(entries[0]!)).toMatchInlineSnapshot(` { "errorCode": "not_found", "level": "warn", "method": "GET", "path": "/missing", "route": "/missing", "status": 404, } `) }) test('records a JSON-RPC error returned with HTTP 200', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.post('/rpc/sponsor', (c) => { const body = { error: { code: -32602, data: { code: 'billing_required', retryable: false }, message: 'Sponsorship requires an active billing source.', }, id: 1, jsonrpc: '2.0', } c.set('rpcResponse', Log.rpcErrors(body)) return c.json(body) }) const response = await api.request('/rpc/sponsor', { method: 'POST' }) expect(response.status).toBe(200) expect(stable(entries[0]!)).toMatchInlineSnapshot(` { "level": "warn", "method": "POST", "path": "/rpc/sponsor", "route": "/rpc/sponsor", "rpc": { "code": -32602, "dataCode": "billing_required", "errors": 1, }, "status": 200, } `) }) test('includes bounded sponsorship rejection diagnostics', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.post('/rpc/sponsor', (c) => { const body = { error: { code: -32602, data: { code: 'production_api_key_required' }, message: 'Sponsorship rejected.', }, id: 1, jsonrpc: '2.0', } c.set('rpcResponse', Log.rpcErrors(body)) c.set('sponsorship', { chainId: 4217, method: 'eth_signRawTransaction', outcome: 'rejected', payloadHash: `0x${'aa'.repeat(32)}` as Hex.Hex, reason: 'production_api_key_required', rejections: 1, }) return c.json(body) }) await api.request('/rpc/sponsor', { method: 'POST' }) expect(stable(entries[0]!)).toMatchInlineSnapshot(` { "level": "warn", "method": "POST", "path": "/rpc/sponsor", "route": "/rpc/sponsor", "rpc": { "code": -32602, "dataCode": "production_api_key_required", "errors": 1, }, "sponsorship": { "chainId": 4217, "method": "eth_signRawTransaction", "outcome": "rejected", "payloadHash": "0xaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", "reason": "production_api_key_required", "rejections": 1, }, "status": 200, } `) }) test('records an MPP relay failure returned with HTTP 200', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.post('/v1/mpp/validate', (c) => { c.set('mpp', { chainId: 4217, errorCode: 'unknown', feePayer: false, operation: 'verify', outcome: 'failure', }) return c.json({ success: false }, 200) }) const response = await api.request('/v1/mpp/validate', { method: 'POST' }) expect(response.status).toBe(200) expect(stable(entries[0]!)).toMatchInlineSnapshot(` { "level": "error", "method": "POST", "mpp": { "chainId": 4217, "errorCode": "unknown", "feePayer": false, "operation": "verify", "outcome": "failure", }, "path": "/v1/mpp/validate", "route": "/v1/mpp/validate", "status": 200, } `) }) test('logs JSON-RPC server errors at error level', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.post('/rpc/sponsor', (c) => { const body = { error: { code: -32603, data: { code: 'internal_error' }, message: 'Internal error', }, id: 1, jsonrpc: '2.0', } c.set('rpcResponse', Log.rpcErrors(body)) return c.json(body) }) await api.request('/rpc/sponsor', { method: 'POST' }) expect(entries[0]?.level).toBe('error') }) test('logs internal sponsorship failures at error level', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.post('/rpc/sponsor', (c) => { c.set('sponsorship', { internalErrors: 1, outcome: 'rejected', rejections: 1, }) return c.json({ id: 1, jsonrpc: '2.0', result: {} }) }) await api.request('/rpc/sponsor', { method: 'POST' }) expect(entries[0]?.level).toBe('error') }) test('escalates mixed JSON-RPC batches containing server errors', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.post('/rpc/relay', (c) => { const body = [ { id: 1, jsonrpc: '2.0', result: '0x1' }, { error: { code: -32602, message: 'Invalid params.' }, id: 2, jsonrpc: '2.0' }, { error: { code: -32603, data: { code: 'Internal Error' }, message: 'Internal error.' }, id: 3, jsonrpc: '2.0', }, ] c.set('rpcResponse', Log.rpcErrors(body)) return c.json(body) }) await api.request('/rpc/relay', { method: 'POST' }) expect(stable(entries[0]!)).toMatchInlineSnapshot(` { "level": "error", "method": "POST", "path": "/rpc/relay", "route": "/rpc/relay", "rpc": { "errors": 2, "serverErrors": 1, }, "status": 200, } `) }) test('keeps routine node rejections out of server-error alerts', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.post('/rpc/relay', (c) => { const body = { error: { code: -32_000, message: 'insufficient funds' }, id: 1, jsonrpc: '2.0', } c.set('rpcResponse', Log.rpcErrors(body)) return c.json(body) }) await api.request('/rpc/relay', { method: 'POST' }) expect(stable(entries[0]!)).toMatchInlineSnapshot(` { "level": "warn", "method": "POST", "path": "/rpc/relay", "route": "/rpc/relay", "rpc": { "code": -32000, "errors": 1, }, "status": 200, } `) }) test('includes redacted provider failure details', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.get('/provider', (c) => { c.set('providerFailure', { code: 'UNAUTHORIZED', failure: 'http', id: 'relay', operation: 'getQuote', status: 401, }) return Response.error(c, { code: 'provider_error', message: 'Provider request failed', status: 502, }) }) await api.request('/provider') expect(stable(entries[0]!)).toMatchInlineSnapshot(` { "errorCode": "provider_error", "level": "error", "method": "GET", "path": "/provider", "provider": { "code": "UNAUTHORIZED", "failure": "http", "id": "relay", "operation": "getQuote", "status": 401, }, "route": "/provider", "status": 502, } `) }) test('preserves the request error and unfinished stages', async () => { const entries: Log.Entry[] = [] const causes: Error[] = [] const api = app({ emit: (entry, cause) => { entries.push(entry) if (cause) causes.push(cause) }, }) const cause = new Error('Memoized cache-miss flight timed out after 15000ms.') api.get('/activities', (c) => { void Timing.time(c, 'transaction_activity_mpp', () => new Promise(() => {})) return Response.upstream(c, cause) }) await api.request('/activities') expect(causes[0]).toBe(cause) expect(entries[0]?.pendingTimings?.['transaction_activity_mpp']).toBeGreaterThanOrEqual(0) }) test('includes bounded funding provider attempts', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.get('/funding', (c) => { c.set('fundingProviderAttempts', [ { durationMs: 12.5, id: 'relay', operation: 'getQuote', outcome: 'available', }, { durationMs: 25, failure: 'timeout', id: 'across', operation: 'getQuote', outcome: 'failed', }, ]) return c.json({ ok: true }, 200) }) await api.request('/funding') expect(stable(entries[0]!)).toMatchInlineSnapshot(` { "fundingProviderAttempts": [ { "durationMs": 12.5, "id": "relay", "operation": "getQuote", "outcome": "available", }, { "durationMs": 25, "failure": "timeout", "id": "across", "operation": "getQuote", "outcome": "failed", }, ], "level": "info", "method": "GET", "path": "/funding", "route": "/funding", "status": 200, } `) }) test('logs thrown errors at error level', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.onError((_, c) => c.json({ error: true }, 500)) api.get('/boom', () => { throw new Error('boom') }) await api.request('/boom') expect(stable(entries[0]!)).toMatchInlineSnapshot(` { "level": "error", "method": "GET", "path": "/boom", "route": "/boom", "status": 500, } `) }) test('parses rate limit state from response headers', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) api.get('/limited', (c) => { c.header('RateLimit-Limit', '100') c.header('RateLimit-Remaining', '37') c.header('RateLimit-Reset', '1710000000') c.header('RateLimit-Scope', 'data:read') return c.json({ ok: true }, 200) }) await api.request('/limited') expect(stable(entries[0]!)).toMatchInlineSnapshot(` { "level": "info", "method": "GET", "path": "/limited", "rateLimit": { "limit": 100, "remaining": 37, "reset": 1710000000, "scope": "data:read", }, "route": "/limited", "status": 200, } `) }) test('marks edge-cache hits', async () => { const entries: Log.Entry[] = [] const api = app({ emit: (entry) => void entries.push(entry) }) // Simulate the edge-cache layer answering before routing runs. api.use('*', async (c) => { c.set('edgeCacheStatus', 'hit') return c.json({ cached: true }, 200) }) await api.request('/anything') expect(stable(entries[0]!)).toMatchInlineSnapshot(` { "cache": "hit", "level": "info", "method": "GET", "path": "/anything", "route": "/*", "status": 200, } `) }) }) describe('emit', () => { test('routes entries to the level-matched console method', () => { const error = vi.spyOn(console, 'error').mockImplementation(() => {}) const log = vi.spyOn(console, 'log').mockImplementation(() => {}) const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}) try { const base = { duration: 1, method: 'GET', path: '/', requestId: 'req', route: '/', } as const Log.emit({ ...base, level: 'info', status: 200 }) Log.emit({ ...base, level: 'warn', status: 404 }) Log.emit({ ...base, level: 'error', status: 500 }) expect(log.mock.calls.length).toMatchInlineSnapshot(`1`) expect(warn.mock.calls.length).toMatchInlineSnapshot(`1`) expect(error.mock.calls.length).toMatchInlineSnapshot(`1`) expect(log.mock.calls[0]?.[0]).toMatchObject({ level: 'info', status: 200 }) } finally { error.mockRestore() log.mockRestore() warn.mockRestore() } }) })