Fimeg/lettabot
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

fix: reduce per-event stream log noise and add regression test (#539)

Browse Source 
Co-authored-by: Letta Code <noreply@letta.com>
This commit is contained in:
Cameron
2026-03-09 16:19:11 -07:00
committed by GitHub
parent d23f0f9328
commit d038c1361a
2 changed files with 103 additions and 9 deletions
Download Patch File Download Diff File Expand all files Collapse all files

99
src/core/bot-logging.test.ts Normal file
View File

@@ -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);
});
});

13
src/core/bot.ts
View File

@@ -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