// Tests for ApiHandler's central dispatch logging. // Verifies that every action call emits a debug entry line, failures // fold into a warn line with stack, and unknown actions are surfaced. // Also covers the summarizeParams helper used to keep the entry log // from blowing the line width. import { afterEach, beforeEach, describe, expect, it } from 'vitest'; import { MessageElementValidationError } from '@snowluma/protocol/element-manifest'; import { OidbError } from '@snowluma/protocol/oidb-service'; import { subscribeLogs, type LogEntry } from '@snowluma/common/logger'; import { summarizeParams } from '@snowluma/common/log-summary'; import { createCompiledTestHandler, testAction } from './helpers/compiled-action-handler'; // Minimal context — isolated test ActionSpecs never call these dependencies. function emptyContext(): any { return { bridge: {}, getLoginInfo: () => ({ userId: 0, nickname: '' }), isOnline: () => true, getMessage: () => null, getMessageMeta: () => null, sendPrivateMessage: async () => ({ messageId: 0 }), sendGroupMessage: async () => ({ messageId: 0 }), deleteMessage: async () => {}, canSendImage: () => true, canSendRecord: () => true, getFriendList: async () => [], getImageInfo: async () => null, getRecordInfo: async () => null, }; } let captured: LogEntry[]; let unsub: () => void; const savedLogLevel = process.env.SNOWLUMA_LOG_LEVEL; beforeEach(() => { process.env.SNOWLUMA_LOG_LEVEL = 'debug'; captured = []; unsub = subscribeLogs((e) => captured.push(e)); }); afterEach(() => { unsub(); if (savedLogLevel === undefined) { delete process.env.SNOWLUMA_LOG_LEVEL; } else { process.env.SNOWLUMA_LOG_LEVEL = savedLogLevel; } }); describe('summarizeParams', () => { it('renders flat scalar fields as k=v pairs', () => { const out = summarizeParams({ group_id: 12345, auto_escape: false, foo: 'bar' }); expect(out).toBe('group_id=12345 auto_escape=false foo="bar"'); }); it('truncates long string values with an ellipsis', () => { const long = 'x'.repeat(80); const out = summarizeParams({ s: long }); expect(out).toMatch(/^s="x{40}\.\.\."$/); }); it('collapses arrays and nested objects rather than dumping them', () => { const out = summarizeParams({ messages: [1, 2, 3, 4], meta: { a: 1, b: 2 } }); expect(out).toBe('messages=[len=4] meta={...}'); }); it('caps the total line and tags the cut with ellipsis', () => { const params: Record = {}; for (let i = 0; i < 30; i++) { params[`field_with_some_padding_${i}`] = i; } const out = summarizeParams(params); expect(out.length).toBeLessThan(220); expect(out.endsWith('...')).toBe(true); }); it('handles null / undefined inputs gracefully', () => { expect(summarizeParams(null)).toBe('{}'); expect(summarizeParams(undefined)).toBe('{}'); }); }); describe('ApiHandler dispatch logging', () => { it('emits a debug entry under [Bridge.Action] when an action is called', async () => { const handler = createCompiledTestHandler( emptyContext(), [testAction('echo', async () => ({ status: 'ok', retcode: 0, data: null }))], 12345, ); await handler.handle('echo', { group_id: 67890, message: [1, 2, 3] }); const entry = captured.find((e) => e.scope === 'Bridge.Action' && e.level === 'debug'); expect(entry).toBeDefined(); expect(entry!.uin).toBe(12345); expect(entry!.message).toContain('echo'); expect(entry!.message).toContain('group_id=67890'); expect(entry!.message).toContain('message=[len=3]'); }); it('logs the parsed emoji-like offset without exposing its cookie cursor', async () => { const handler = createCompiledTestHandler( emptyContext(), [ testAction('fetch_emoji_like', async () => ({ status: 'ok', retcode: 0, data: null, })), ], 12345, ); await handler.handle('fetch_emoji_like', { message_id: 1, emojiId: '66', cookie: '40', }); const entry = captured.find((e) => e.scope === 'Bridge.Action' && e.level === 'debug'); expect(entry?.message).toContain('emoji_like_offset=40'); expect(entry?.message).not.toContain('cookie='); }); it('keeps malformed emoji-like cookies redacted instead of parsing prefixes', async () => { const handler = createCompiledTestHandler( emptyContext(), [ testAction('fetch_emoji_like', async () => ({ status: 'ok', retcode: 0, data: null, })), ], 12345, ); await handler.handle('fetch_emoji_like', { cookie: '123.session=secret' }); const entry = captured.find((e) => e.scope === 'Bridge.Action' && e.level === 'debug'); expect(entry?.message).toContain('cookie=***'); expect(entry?.message).not.toContain('emoji_like_offset='); expect(entry?.message).not.toContain('session=secret'); }); it('keeps cookie parameters redacted for every other action', async () => { const handler = createCompiledTestHandler( emptyContext(), [testAction('other_action', async () => ({ status: 'ok', retcode: 0, data: null }))], 12345, ); await handler.handle('other_action', { cookie: '40' }); const entry = captured.find((e) => e.scope === 'Bridge.Action' && e.level === 'debug'); expect(entry?.message).toContain('cookie=***'); expect(entry?.message).not.toContain('cookie=40'); }); it('emits a warn line with the error stack when the handler throws', async () => { const handler = createCompiledTestHandler( emptyContext(), [ testAction('boom', async () => { throw new Error('kapow'); }), ], 12345, ); const result = await handler.handle('boom', {}); expect(result.status).toBe('failed'); const warn = captured.find((e) => e.scope === 'Bridge.Action' && e.level === 'warn'); expect(warn).toBeDefined(); expect(warn!.message).toContain('boom'); expect(warn!.message).toContain('kapow'); // stack contains the test file path; just check that something stack-shaped is appended expect(warn!.message).toMatch(/at\s+/); }); // The single error seam (ADR-0006 narrow seam): any throw from a handler // maps to ONE policy here — ACTION_FAILED (100) + the error message — // instead of each action hand-rolling its own inconsistent try/catch. it('maps any handler throw to ACTION_FAILED (100) with the error message', async () => { const handler = createCompiledTestHandler( emptyContext(), [ testAction('kaboom', async () => { throw new Error('permission denied'); }), ], 12345, ); const result = await handler.handle('kaboom', {}); expect(result).toMatchObject({ status: 'failed', retcode: 100, wording: 'permission denied', }); }); it('maps typed outbound message-contract failures to BAD_REQUEST', async () => { const handler = createCompiledTestHandler( emptyContext(), [ testAction('bad_message', async () => { throw new MessageElementValidationError( 'UNKNOWN_TYPE', 'unknown message segment type: surprise', 'surprise', ); }), ], 12345, ); const result = await handler.handle('bad_message', {}); expect(result).toMatchObject({ status: 'failed', retcode: 1400, wording: 'unknown message segment type: surprise', }); }); it('surfaces the OidbError code + server message through error.message (no special-casing)', async () => { const handler = createCompiledTestHandler( emptyContext(), [ testAction('oidb_boom', async () => { throw new OidbError(34, 'no permission', 0x11ec, 2); }), ], 12345, ); const result = await handler.handle('oidb_boom', {}); expect(result).toMatchObject({ status: 'failed', retcode: 100 }); expect((result as { wording: string }).wording).toContain('34'); expect((result as { wording: string }).wording).toContain('no permission'); }); it('renders a non-Error throw via String()', async () => { const handler = createCompiledTestHandler( emptyContext(), [ testAction('weird', async () => { throw 'just a string'; }), ], 12345, ); const result = await handler.handle('weird', {}); expect(result).toMatchObject({ status: 'failed', retcode: 100, wording: 'just a string' }); }); it('logs unknown actions at debug level', async () => { const handler = createCompiledTestHandler(emptyContext(), [], 99); await handler.handle('not_a_real_action', {}); const entry = captured.find( (e) => e.scope === 'Bridge.Action' && e.message.includes('unknown action'), ); expect(entry).toBeDefined(); expect(entry!.level).toBe('debug'); }); it('falls back to the module-level logger (no uin slot) when uin is omitted', async () => { const handler = createCompiledTestHandler(emptyContext(), [ testAction('ping', async () => ({ status: 'ok', retcode: 0, data: null })), ]); await handler.handle('ping', {}); const entry = captured.find((e) => e.scope === 'Bridge.Action' && e.level === 'debug'); expect(entry).toBeDefined(); expect(entry!.uin).toBeUndefined(); }); });