From d038c1361ab018e11e45f9d54a12f162f2c2eb0b Mon Sep 17 00:00:00 2001 From: Cameron Date: Mon, 9 Mar 2026 16:19:11 -0700 Subject: [PATCH] fix: reduce per-event stream log noise and add regression test (#539) Co-authored-by: Letta Code --- src/core/bot-logging.test.ts | 99 ++++++++++++++++++++++++++++++++++++ src/core/bot.ts | 13 ++--- 2 files changed, 103 insertions(+), 9 deletions(-) create mode 100644 src/core/bot-logging.test.ts diff --git a/src/core/bot-logging.test.ts b/src/core/bot-logging.test.ts new file mode 100644 index 0000000..1cf2a73 --- /dev/null +++ b/src/core/bot-logging.test.ts @@ -0,0 +1,99 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import { mkdtempSync, rmSync } from 'node:fs'; +import { join } from 'node:path'; +import { tmpdir } from 'node:os'; + +const loggerSpies = vi.hoisted(() => ({ + fatal: vi.fn(), + error: vi.fn(), + warn: vi.fn(), + info: vi.fn(), + debug: vi.fn(), + trace: vi.fn(), +})); + +vi.mock('../logger.js', () => ({ + createLogger: () => ({ + ...loggerSpies, + pino: {}, + }), +})); + +import { LettaBot } from './bot.js'; +import type { InboundMessage, OutboundMessage } from './types.js'; + +describe('stream logging levels', () => { + let workDir: string; + + beforeEach(() => { + workDir = mkdtempSync(join(tmpdir(), 'lettabot-bot-logging-')); + Object.values(loggerSpies).forEach((spy) => spy.mockClear()); + }); + + afterEach(() => { + rmSync(workDir, { recursive: true, force: true }); + }); + + it('keeps per-event non-foreground and raw preview logging at trace level', async () => { + const bot = new LettaBot({ + workingDir: workDir, + allowedTools: [], + display: { showReasoning: true, showToolCalls: true }, + }); + + const adapter = { + id: 'mock', + name: 'Mock', + start: vi.fn(async () => {}), + stop: vi.fn(async () => {}), + isRunning: vi.fn(() => true), + sendMessage: vi.fn(async (_msg: OutboundMessage) => ({ messageId: 'msg-1' })), + editMessage: vi.fn(async () => {}), + sendTypingIndicator: vi.fn(async () => {}), + stopTypingIndicator: vi.fn(async () => {}), + supportsEditing: vi.fn(() => false), + sendFile: vi.fn(async () => ({ messageId: 'file-1' })), + }; + + (bot as any).sessionManager.runSession = vi.fn(async () => ({ + session: { abort: vi.fn(async () => {}) }, + stream: async function* () { + yield { type: 'reasoning', content: 'bg-think', runId: 'run-bg' }; + yield { type: 'tool_call', toolCallId: 'tc-bg', toolName: 'Bash', toolInput: { command: 'echo bg' }, runId: 'run-bg' }; + yield { type: 'assistant', content: 'main reply', runId: 'run-main' }; + yield { type: 'reasoning', content: 'bg-post-foreground', runId: 'run-bg' }; + yield { type: 'tool_call', toolCallId: 'tc-main', toolName: 'Bash', toolInput: { command: 'echo main' }, runId: 'run-main' }; + yield { type: 'tool_result', content: 'ok', toolCallId: 'tc-main', runId: 'run-main', isError: false }; + yield { type: 'result', success: true, result: 'main reply', runIds: ['run-main'] }; + }, + })); + + const msg: InboundMessage = { + channel: 'discord', + chatId: 'chat-1', + userId: 'user-1', + text: 'hello', + timestamp: new Date(), + }; + + await (bot as any).processMessage(msg, adapter); + + const debugMessages = loggerSpies.debug.mock.calls.map(([message]) => String(message)); + const infoMessages = loggerSpies.info.mock.calls.map(([message]) => String(message)); + const traceMessages = loggerSpies.trace.mock.calls.map(([message]) => String(message)); + + expect(debugMessages.some((m) => m.includes('Buffering run-scoped pre-foreground display event'))).toBe(false); + expect(debugMessages.some((m) => m.includes('Deferring run-scoped pre-foreground event'))).toBe(false); + expect(debugMessages.some((m) => m.includes('Skipping non-foreground stream event'))).toBe(false); + + expect(infoMessages.some((m) => m.includes('type=tool_call'))).toBe(false); + expect(infoMessages.some((m) => m.includes('type=tool_result'))).toBe(false); + + expect(traceMessages.some((m) => m.includes('Buffering run-scoped pre-foreground display event'))).toBe(true); + expect(traceMessages.some((m) => m.includes('Skipping non-foreground stream event'))).toBe(true); + expect(traceMessages.some((m) => m.includes('type=tool_call'))).toBe(true); + expect(traceMessages.some((m) => m.includes('type=tool_result'))).toBe(true); + + expect(infoMessages.some((m) => m.includes('Filtered') && m.includes('non-foreground event(s)'))).toBe(true); + }); +}); \ No newline at end of file diff --git a/src/core/bot.ts b/src/core/bot.ts index 50e2e85..f94f9a9 100644 --- a/src/core/bot.ts +++ b/src/core/bot.ts @@ -1365,11 +1365,11 @@ export class LettaBot implements AgentSession { if (runId && (streamMsg.type === 'reasoning' || streamMsg.type === 'tool_call')) { bufferRunScopedDisplayEvent(runId, streamMsg); filteredRunEventCount++; - log.debug(`Buffering run-scoped pre-foreground display event (seq=${seq}, key=${convKey}, type=${streamMsg.type}, runId=${runId})`); + log.trace(`Buffering run-scoped pre-foreground display event (seq=${seq}, key=${convKey}, type=${streamMsg.type}, runId=${runId})`); continue; } filteredRunEventCount++; - log.debug(`Deferring run-scoped pre-foreground event (seq=${seq}, key=${convKey}, type=${streamMsg.type}, runIds=${eventRunIds.join(',')})`); + log.trace(`Deferring run-scoped pre-foreground event (seq=${seq}, key=${convKey}, type=${streamMsg.type}, runIds=${eventRunIds.join(',')})`); continue; } } else if (expectedForegroundRunId && eventRunIds.length > 0 && !eventRunIds.includes(expectedForegroundRunId)) { @@ -1380,7 +1380,7 @@ export class LettaBot implements AgentSession { ignoredNonForegroundResultCount++; log.warn(`Ignoring non-foreground result event (seq=${seq}, key=${convKey}, runIds=${eventRunIds.join(',')}, expected=${expectedForegroundRunId}, source=${expectedForegroundRunSource || 'unknown'})`); } else { - log.debug(`Skipping non-foreground stream event (seq=${seq}, key=${convKey}, type=${streamMsg.type}, runIds=${eventRunIds.join(',')}, expected=${expectedForegroundRunId})`); + log.trace(`Skipping non-foreground stream event (seq=${seq}, key=${convKey}, type=${streamMsg.type}, runIds=${eventRunIds.join(',')}, expected=${expectedForegroundRunId})`); } continue; } @@ -1388,12 +1388,7 @@ export class LettaBot implements AgentSession { receivedAnyData = true; msgTypeCounts[streamMsg.type] = (msgTypeCounts[streamMsg.type] || 0) + 1; - const preview = JSON.stringify(streamMsg).slice(0, 300); - if (streamMsg.type === 'reasoning' || streamMsg.type === 'assistant') { - log.debug(`type=${streamMsg.type} ${preview}`); - } else { - log.info(`type=${streamMsg.type} ${preview}`); - } + log.trace(`type=${streamMsg.type} ${JSON.stringify(streamMsg).slice(0, 300)}`); // stream_event is a low-level streaming primitive (partial deltas), not a // semantic type change. Skip it for type-transition logic so it doesn't