DrSmoothl
15e4e261c5
Debugging from user-supplied logs was impossible: a successful action left one terse, over-summarized debug line and nothing about what it sent QQ or what QQ returned. Add full-chain tracing that stays off disk so it scales to hundreds of groups. common: - New `trace` level (below debug). Never written to file — it lives only in an in-memory ring + the WebUI stream, so the high-volume full chain costs no disk. `emit` early-returns for trace before format/render (and before any lazy producer) when trace isn't active → ~free at the default level. - Dedicated O(1) circular ring for trace (default 5000, SNOWLUMA_TRACE_BUFFER), separate from the normal 1000-entry buffer (also switched off array .shift); getRecentLogs merges both by id. - request-context.ts: AsyncLocalStorage request id. The logger auto-stamps `[req#N]` on every line in a request's async chain — across packages, zero signature threading — and records it on the entry. - log-summary.renderParamsVerbose: deep render of params (nested structure, per-string cap, total budget, token/password/secret redaction). chokepoints (auto-cover every action without touching 100+ handlers): - onebot api-handler: wrap each action in a request id (only when trace is live); trace the full params on entry and status+elapsed on exit; the terse debug breadcrumb still persists to file, failures still warn. - core bridge.sendRawPacket: trace on success (cmd, sizes, elapsed); warn on errorCode!=0 / no response (cmd, code, message) so disk keeps real problems. - protocol highway: fold the bare console.log lines into the logger (trace). webui: trace as the lowest filterable level; render the `[req#N]` tag and let search match it. Server needs no change — LOG_LEVELS, getRecentLogs and the SSE stream carry it through.
107 lines
3.5 KiB
TypeScript
107 lines
3.5 KiB
TypeScript
import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest';
|
|
import {
|
|
createLogger,
|
|
currentRequestId,
|
|
getLogLevel,
|
|
getRecentLogs,
|
|
runWithRequestId,
|
|
setLogLevel,
|
|
} from '@snowluma/common/logger';
|
|
import { renderParamsVerbose } from '@snowluma/common/log-summary';
|
|
|
|
describe('renderParamsVerbose', () => {
|
|
it('shows the full nested structure (message segments), unlike the shallow summary', () => {
|
|
const out = renderParamsVerbose({
|
|
group_id: 123,
|
|
message: [{ type: 'text', data: { text: 'hello' } }, { type: 'at', data: { qq: '456' } }],
|
|
});
|
|
expect(out).toContain('group_id:123');
|
|
expect(out).toContain('text');
|
|
expect(out).toContain('"hello"');
|
|
expect(out).toContain('"456"');
|
|
});
|
|
|
|
it('truncates long strings (e.g. base64) with a size marker', () => {
|
|
const big = 'A'.repeat(5000);
|
|
const out = renderParamsVerbose({ file: `base64://${big}` });
|
|
expect(out).toContain('base64://');
|
|
expect(out).toContain('…<'); // truncation marker
|
|
expect(out).toContain('B>');
|
|
expect(out.length).toBeLessThan(2000); // bounded by the total budget
|
|
});
|
|
|
|
it('redacts sensitive keys at any depth', () => {
|
|
const out = renderParamsVerbose({
|
|
access_token: 'super-secret-value',
|
|
nested: { password: 'hunter2', SECRET: 'x', ok: 'visible' },
|
|
});
|
|
expect(out).not.toContain('super-secret-value');
|
|
expect(out).not.toContain('hunter2');
|
|
expect(out).toContain('"***"');
|
|
expect(out).toContain('"visible"'); // non-sensitive keys still rendered
|
|
});
|
|
|
|
it('handles circular references without throwing', () => {
|
|
const a: Record<string, unknown> = { name: 'a' };
|
|
a.self = a;
|
|
expect(() => renderParamsVerbose(a)).not.toThrow();
|
|
expect(renderParamsVerbose(a)).toContain('[circular]');
|
|
});
|
|
});
|
|
|
|
describe('logger trace level + request correlation', () => {
|
|
let prevLevel: string;
|
|
|
|
beforeEach(() => {
|
|
prevLevel = getLogLevel();
|
|
});
|
|
afterEach(() => {
|
|
setLogLevel(prevLevel);
|
|
});
|
|
|
|
it('captures trace into the in-memory buffer only when the level is trace', () => {
|
|
const log = createLogger('Test.Trace');
|
|
const marker = `trace-marker-${Math.trunc(performance.now())}-${getRecentLogs(1).length}`;
|
|
|
|
setLogLevel('info');
|
|
log.trace('off %s', marker);
|
|
expect(getRecentLogs(2000).some((e) => e.message.includes(marker))).toBe(false);
|
|
|
|
setLogLevel('trace');
|
|
log.trace('on %s', marker);
|
|
const hit = getRecentLogs(2000).find((e) => e.message.includes(marker));
|
|
expect(hit).toBeDefined();
|
|
expect(hit?.level).toBe('trace');
|
|
});
|
|
|
|
it('does NOT evaluate a lazy producer when trace is off (the efficiency guarantee)', () => {
|
|
const log = createLogger('Test.Lazy');
|
|
const produce = vi.fn(() => ['lazy payload']);
|
|
|
|
setLogLevel('info');
|
|
log.trace(produce);
|
|
expect(produce).not.toHaveBeenCalled();
|
|
|
|
setLogLevel('trace');
|
|
log.trace(produce);
|
|
expect(produce).toHaveBeenCalledTimes(1);
|
|
});
|
|
|
|
it('stamps the ambient request id onto entries emitted inside runWithRequestId', () => {
|
|
const log = createLogger('Test.Req');
|
|
setLogLevel('trace');
|
|
const marker = `req-marker-${Math.trunc(performance.now())}`;
|
|
|
|
expect(currentRequestId()).toBeUndefined();
|
|
runWithRequestId(4242, () => {
|
|
expect(currentRequestId()).toBe(4242);
|
|
log.trace('inside %s', marker);
|
|
});
|
|
expect(currentRequestId()).toBeUndefined();
|
|
|
|
const hit = getRecentLogs(2000).find((e) => e.message.includes(marker));
|
|
expect(hit?.req).toBe(4242);
|
|
expect(hit?.line).toContain('[req#4242]');
|
|
});
|
|
});
|