Skip to content

Commit 3b5c176

Browse files
devartifexCopilot
devartifex
and
Copilot
committed
refactor: suppress noisy SDK events and clean up server logging
- Add SUPPRESSED_EVENT_TYPES set for high-frequency SDK-internal events (pending_messages.modified, streaming_delta, hook.start/end, etc.) so they no longer flood the catch-all logger - Create src/lib/server/logger.ts with dev-only debug() helper - Convert verbose [DEBUG ...] console.log calls to debug() — silent in production, visible in development - Remove [QUOTA] raw JSON dump that logged on every usage event - Standardize log prefixes: [LIST_SESSIONS], [SESSION_DETAIL], etc. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
1 parent bb9daa8 commit 3b5c176

6 files changed

Lines changed: 55 additions & 38 deletions

File tree

‎src/lib/server/logger.ts‎

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,10 @@
1+
import { config } from './config.js';
2+
3+
/**
4+
* Dev-only debug logger — calls are no-ops in production.
5+
* Avoids noisy `[DEBUG …]` lines flooding container logs.
6+
*/
7+
export const debug: (...args: unknown[]) => void =
8+
config.isDev
9+
? (...args: unknown[]) => console.log(...args)
10+
: () => {};

‎src/lib/server/ws/handler.ts‎

Lines changed: 13 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@ import {
1414
import { VALID_MESSAGE_TYPES, HEARTBEAT_INTERVAL, MAX_MISSED_PINGS, RATE_LIMITED_TYPES, WS_RATE_LIMIT_MAX, WS_RATE_LIMIT_WINDOW_MS } from './constants.js';
1515
import { messageHandlers } from './message-handlers/index.js';
1616
import { chatStateStore } from '../chat-state-singleton.js';
17+
import { debug } from '../logger.js';
1718
import type { SessionMiddleware, MessageContext } from './types.js';
1819

1920
export { cleanupAllSessions, cleanupUserSessions } from './session-pool.js';
@@ -40,7 +41,7 @@ export function setupWebSocket(
4041
wss.on('close', () => clearInterval(heartbeat));
4142

4243
wss.on('connection', async (ws: WebSocket, req: IncomingMessage) => {
43-
console.log('[WS-SERVER] New connection attempt from', req.socket.remoteAddress);
44+
console.log('[WS-SERVER] New connection from', req.socket.remoteAddress);
4445
(ws as any).missedPings = 0;
4546
ws.on('pong', () => { (ws as any).missedPings = 0; });
4647

@@ -61,7 +62,7 @@ export function setupWebSocket(
6162
});
6263

6364
const session = (req as any).session;
64-
console.log('[WS-SERVER] Session extracted:', !!session, 'token:', !!session?.githubToken, 'user:', session?.githubUser?.login);
65+
debug('[WS-SERVER] Session extracted:', !!session, 'token:', !!session?.githubToken, 'user:', session?.githubUser?.login);
6566

6667
// Restore auth from encrypted cookie when session file is missing (e.g. after EmptyDir wipe)
6768
if (session && !session.githubToken) {
@@ -73,13 +74,13 @@ export function setupWebSocket(
7374
session.githubUser = data.githubUser;
7475
session.githubAuthTime = data.githubAuthTime;
7576
session.save(() => {});
76-
console.log(`[WS-SERVER] Restored auth from cookie for user=${data.githubUser.login}`);
77+
debug(`[WS-SERVER] Restored auth from cookie for user=${data.githubUser.login}`);
7778
}
7879
}
7980
}
8081

8182
const auth = checkAuth(session);
82-
console.log('[WS-SERVER] Auth check result:', auth.authenticated, auth.error || 'ok');
83+
debug('[WS-SERVER] Auth check:', auth.authenticated, auth.error || 'ok');
8384
if (!auth.authenticated) {
8485
logSecurity('warn', 'ws_unauthorized', {
8586
ip: req.socket.remoteAddress,
@@ -110,11 +111,11 @@ export function setupWebSocket(
110111
const tabId = isValidTabId(rawTabId) ? rawTabId : 'default';
111112
const lastSeq = parseInt(reqUrl.searchParams.get('lastSeq') || '-1', 10);
112113
const poolKey = `${userLogin}:${tabId}`;
113-
console.log('[WS-SERVER] Authenticated user:', userLogin, 'tab:', tabId, 'lastSeq:', lastSeq, 'checking pool...');
114+
console.log('[WS-SERVER] Authenticated:', userLogin, 'tab:', tabId);
114115
let entry = sessionPool.get(poolKey);
115116

116117
if (entry) {
117-
console.log('[WS-SERVER] Existing pool entry found for', poolKey);
118+
debug('[WS-SERVER] Existing pool entry for', poolKey);
118119
// Reattach to existing pool entry
119120
if (entry.ws && entry.ws !== ws && entry.ws.readyState === WebSocket.OPEN) {
120121
entry.ws.close(4002, 'Replaced by new connection');
@@ -136,7 +137,7 @@ export function setupWebSocket(
136137
}
137138
}
138139

139-
console.log('[WS-SERVER] Sending session_reconnected to', poolKey, 'hasSession:', !!entry.session);
140+
debug('[WS-SERVER] Sending session_reconnected to', poolKey, 'hasSession:', !!entry.session);
140141
poolSend(entry, {
141142
type: 'session_reconnected',
142143
user: userLogin,
@@ -170,10 +171,10 @@ export function setupWebSocket(
170171
} else {
171172
// Create new pool entry — enforce per-user session cap
172173
if (countUserSessions(userLogin) >= config.maxSessionsPerUser) {
173-
console.log('[WS-SERVER] Session cap reached for', userLogin, '— evicting oldest');
174+
debug('[WS-SERVER] Session cap reached for', userLogin, '— evicting oldest');
174175
await evictOldestUserSession(userLogin);
175176
}
176-
console.log('[WS-SERVER] Creating new pool entry for', poolKey);
177+
debug('[WS-SERVER] New pool entry for', poolKey);
177178
const client = createCopilotClient(githubToken, config.copilotConfigDir);
178179
entry = createPoolEntry(client, ws);
179180
sessionPool.set(poolKey, entry);
@@ -189,7 +190,7 @@ export function setupWebSocket(
189190
}
190191

191192
const hasPersistedState = !!(persistedState && persistedState.messages.length > 0);
192-
console.log('[WS-SERVER] Sending connected to', poolKey, 'persisted:', hasPersistedState);
193+
debug('[WS-SERVER] Sending connected to', poolKey, 'persisted:', hasPersistedState);
193194
poolSend(entry, {
194195
type: 'connected',
195196
user: userLogin,
@@ -213,7 +214,7 @@ export function setupWebSocket(
213214
const connectionEntry = entry;
214215

215216
ws.on('close', (code: number, reason: Buffer) => {
216-
console.log('[WS-SERVER] Client disconnected:', poolKey, 'code:', code, 'reason:', reason?.toString());
217+
console.log('[WS-SERVER] Disconnected:', poolKey, 'code:', code);
217218
if (connectionEntry.ws === ws) {
218219
connectionEntry.ws = null;
219220
connectionEntry.ttlTimer = setTimeout(async () => {
@@ -231,7 +232,7 @@ export function setupWebSocket(
231232
ws.on('message', async (raw) => {
232233
try {
233234
const msg = JSON.parse(raw.toString());
234-
console.log('[WS-SERVER] Message from', userLogin, ':', msg.type);
235+
debug('[WS-SERVER] Message from', userLogin, ':', msg.type);
235236

236237
if (!msg.type || !VALID_MESSAGE_TYPES.has(msg.type)) {
237238
poolSend(connectionEntry, { type: 'error', message: 'Unknown message type' });

‎src/lib/server/ws/message-handlers/resume-session.ts‎

Lines changed: 6 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@ import { config } from '../../config.js';
88
import { poolSend } from '../session-pool.js';
99
import { VALID_MODES } from '../constants.js';
1010
import { wireSessionEvents, createCatchAllHandler, HANDLED_EVENT_TYPES } from '../session-events.js';
11+
import { debug } from '../../logger.js';
1112
import { makeUserInputHandler, makePermissionHandler } from '../permissions.js';
1213
import type { MessageContext } from '../types.js';
1314

@@ -72,12 +73,12 @@ export async function handleResumeSession(msg: any, ctx: MessageContext): Promis
7273
});
7374
resumed = true;
7475
} catch (resumeErr: any) {
75-
console.log(`[RESUME] SDK resumeSession failed for ${sessionId}: ${resumeErr.message}`);
76+
debug(`[RESUME] SDK resumeSession failed for ${sessionId}: ${resumeErr.message}`);
7677
}
7778

7879
// Fallback: create a new session with context from the filesystem session
7980
if (!resumed) {
80-
console.log(`[RESUME] Attempting context-based fallback for ${sessionId}…`);
81+
debug(`[RESUME] Attempting context-based fallback for ${sessionId}…`);
8182
const context = await buildSessionContext(sessionId);
8283
if (!context) {
8384
throw new Error(`Session not found: ${sessionId}`);
@@ -91,7 +92,7 @@ export async function handleResumeSession(msg: any, ctx: MessageContext): Promis
9192
onEvent,
9293
onHookEvent: (message) => poolSend(connectionEntry, message),
9394
});
94-
console.log(`[RESUME] Fallback session created for ${sessionId} with context injection`);
95+
debug(`[RESUME] Fallback session created for ${sessionId} with context injection`);
9596
}
9697

9798
wireSessionEvents(connectionEntry.session, connectionEntry, sessionId, ctx.userLogin, ctx.poolKey.split(':').slice(1).join(':'));
@@ -118,7 +119,7 @@ export async function handleResumeSession(msg: any, ctx: MessageContext): Promis
118119
if (detail?.plan) {
119120
try {
120121
await connectionEntry.session.rpc.plan.update({ content: detail.plan });
121-
console.log(`[RESUME] Plan restored into SDK for session ${sessionId}`);
122+
debug(`[RESUME] Plan restored into SDK for session ${sessionId}`);
122123
} catch (planErr: any) {
123124
console.warn(`[RESUME] Failed to restore plan into SDK: ${planErr.message}`);
124125
}
@@ -138,7 +139,7 @@ export async function handleResumeSession(msg: any, ctx: MessageContext): Promis
138139
try {
139140
const turns = loadSessionTurns(sessionId);
140141
if (turns.length > 0) {
141-
console.log(`[RESUME] Loaded ${turns.length} messages from session-store.db for ${sessionId}`);
142+
debug(`[RESUME] Loaded ${turns.length} messages from session-store.db for ${sessionId}`);
142143
const resolvedModel = msg.model || 'gpt-4.1';
143144
poolSend(connectionEntry, {
144145
type: 'cold_resume',

‎src/lib/server/ws/message-handlers/session-management.ts‎

Lines changed: 10 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -1,19 +1,17 @@
11
import { getAvailableModels } from '../../copilot/session.js';
22
import { enrichSessionMetadata, getSessionDetail, listSessionsFromFilesystem, deleteSessionFromFilesystem, isValidSessionId } from '../../copilot/session-metadata.js';
33
import { poolSend } from '../session-pool.js';
4+
import { debug } from '../../logger.js';
45
import type { MessageContext } from '../types.js';
56

67
export async function handleListSessions(msg: any, ctx: MessageContext): Promise<void> {
78
const { connectionEntry } = ctx;
89

910
try {
10-
// start() is idempotent — no-op if already connected
11-
console.log('[DEBUG list_sessions] Starting client…');
1211
await connectionEntry.client.start();
13-
console.log('[DEBUG list_sessions] client.listSessions()…');
1412
const sessions = await connectionEntry.client.listSessions();
1513
const rawList = Array.isArray(sessions) ? sessions : [];
16-
console.log('[DEBUG list_sessions] SDK returned', rawList.length, 'sessions');
14+
debug('[LIST_SESSIONS] SDK returned', rawList.length, 'sessions');
1715

1816
// Enrich each session with filesystem metadata in parallel
1917
const sdkSessions = await Promise.all(
@@ -36,9 +34,9 @@ export async function handleListSessions(msg: any, ctx: MessageContext): Promise
3634

3735
// Merge with filesystem sessions the SDK may not know about
3836
// (e.g. bundled sessions copied into a fresh container)
39-
console.log('[DEBUG list_sessions] Scanning filesystem…');
37+
debug('[LIST_SESSIONS] Scanning filesystem…');
4038
const fsSessions = await listSessionsFromFilesystem();
41-
console.log('[DEBUG list_sessions] Filesystem found', fsSessions.length, 'sessions');
39+
debug('[LIST_SESSIONS] Filesystem found', fsSessions.length, 'sessions');
4240
const sdkIds = new Set(sdkSessions.map((s) => s.id));
4341
const extraSessions = fsSessions.filter((s) => !sdkIds.has(s.id)).map((s) => ({ ...s, source: 'filesystem' as const }));
4442
const allSessions = [...sdkSessions, ...extraSessions];
@@ -49,18 +47,18 @@ export async function handleListSessions(msg: any, ctx: MessageContext): Promise
4947
const list = allSessions.filter((s) =>
5048
s.title || s.checkpointCount > 0 || s.hasPlan,
5149
);
52-
console.log('[DEBUG list_sessions] Sending', list.length, 'total (SDK:', sdkSessions.length, '+ FS extra:', extraSessions.length, ', filtered out:', allSessions.length - list.length, ')');
50+
debug('[LIST_SESSIONS] Sending', list.length, 'total (SDK:', sdkSessions.length, '+ FS extra:', extraSessions.length, ', filtered out:', allSessions.length - list.length, ')');
5351

5452
poolSend(connectionEntry, { type: 'sessions', sessions: list });
5553
} catch (err: any) {
56-
console.error('[DEBUG list_sessions] SDK error:', err.message);
54+
console.error('[LIST_SESSIONS] SDK error:', err.message);
5755
// SDK failed — fall back to filesystem-only listing
5856
try {
5957
const fsSessions = await listSessionsFromFilesystem();
60-
console.log('[DEBUG list_sessions] Fallback: filesystem found', fsSessions.length, 'sessions');
58+
debug('[LIST_SESSIONS] Fallback: filesystem found', fsSessions.length, 'sessions');
6159
poolSend(connectionEntry, { type: 'sessions', sessions: fsSessions.map((s) => ({ ...s, source: 'filesystem' as const })) });
6260
} catch (fsErr: any) {
63-
console.error('[DEBUG list_sessions] Filesystem fallback also failed:', fsErr.message);
61+
console.error('[LIST_SESSIONS] Filesystem fallback also failed:', fsErr.message);
6462
poolSend(connectionEntry, { type: 'sessions', sessions: [] });
6563
}
6664
}
@@ -109,9 +107,7 @@ export async function handleGetSessionDetail(msg: any, ctx: MessageContext): Pro
109107
const { connectionEntry } = ctx;
110108

111109
const detailId = typeof msg.sessionId === 'string' ? msg.sessionId.trim() : '';
112-
console.log('[DEBUG get_session_detail] Requested:', JSON.stringify(detailId));
113110
if (!detailId) {
114-
console.log('[DEBUG get_session_detail] Empty ID, sending error');
115111
poolSend(connectionEntry, { type: 'error', message: 'Session ID is required' });
116112
return;
117113
}
@@ -121,17 +117,15 @@ export async function handleGetSessionDetail(msg: any, ctx: MessageContext): Pro
121117
}
122118

123119
try {
124-
console.log('[DEBUG get_session_detail] Calling getSessionDetail…');
125120
const detail = await getSessionDetail(detailId);
126-
console.log('[DEBUG get_session_detail] Result:', detail ? `found (id=${detail.id})` : 'null');
121+
debug('[SESSION_DETAIL] Result:', detail ? `found (id=${detail.id})` : 'null');
127122
if (!detail) {
128123
poolSend(connectionEntry, { type: 'error', message: 'Session not found' });
129124
return;
130125
}
131126
poolSend(connectionEntry, { type: 'session_detail', detail });
132-
console.log('[DEBUG get_session_detail] Sent session_detail response');
133127
} catch (err: any) {
134-
console.error('[DEBUG get_session_detail] Error:', err.message, err.stack);
128+
console.error('[SESSION_DETAIL] Error:', err.message);
135129
poolSend(connectionEntry, { type: 'error', message: `Failed to get session detail: ${err.message}` });
136130
}
137131
}

‎src/lib/server/ws/quota.ts‎

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,6 @@
11
/** Normalize SDK quota snapshots: convert remainingPercentage from 0.0–1.0 to 0–100 and add percentageUsed */
22
export function normalizeQuotaSnapshots(raw: Record<string, any> | undefined): Record<string, any> | undefined {
33
if (!raw) return raw;
4-
console.log('[QUOTA] raw SDK snapshots:', JSON.stringify(raw));
54
const result: Record<string, any> = {};
65
for (const [key, snap] of Object.entries(raw)) {
76
const remaining = snap.remainingPercentage;

‎src/lib/server/ws/session-events.ts‎

Lines changed: 16 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
import { join } from 'node:path';
22
import { writeFile } from 'node:fs/promises';
3+
import { debug } from '../logger.js';
34
import { poolSend, isClientUnreachable, type PoolEntry } from './session-pool.js';
45
import { normalizeQuotaSnapshots } from './quota.js';
56
import { getSessionStateDir } from '../copilot/session-metadata.js';
@@ -25,9 +26,20 @@ export const HANDLED_EVENT_TYPES = new Set([
2526
'system.notification',
2627
]);
2728

29+
// High-frequency or SDK-internal events safe to silently ignore
30+
const SUPPRESSED_EVENT_TYPES = new Set([
31+
'pending_messages.modified',
32+
'assistant.streaming_delta',
33+
'user.message',
34+
'hook.start',
35+
'hook.end',
36+
'session.mcp_servers_loaded',
37+
'session.tools_updated',
38+
]);
39+
2840
export function createCatchAllHandler(entry: PoolEntry, handledTypes: Set<string>): (event: any) => void {
2941
return (event: any) => {
30-
if (!handledTypes.has(event.type)) {
42+
if (!handledTypes.has(event.type) && !SUPPRESSED_EVENT_TYPES.has(event.type)) {
3143
console.log('[EVENT] unhandled SDK event:', event.type, JSON.stringify(event.data ?? {}).slice(0, 200));
3244
}
3345
};
@@ -83,15 +95,15 @@ export function wireSessionEvents(
8395
pendingAssistantContent = '';
8496
});
8597
session.on('tool.execution_start', (event: any) => {
86-
console.log('[TOOL] execution_start:', event.data.toolName, 'mcp:', event.data.mcpServerName, '/', event.data.mcpToolName);
98+
debug('[TOOL] execution_start:', event.data.toolName, 'mcp:', event.data.mcpServerName, '/', event.data.mcpToolName);
8799
poolSend(entry, { type: 'tool_start', toolCallId: event.data.toolCallId, toolName: event.data.toolName, mcpServerName: event.data.mcpServerName, mcpToolName: event.data.mcpToolName });
88100
});
89101
session.on('tool.execution_complete', (event: any) => {
90-
console.log('[TOOL] execution_complete:', event.data.toolCallId);
102+
debug('[TOOL] execution_complete:', event.data.toolCallId);
91103
poolSend(entry, { type: 'tool_end', toolCallId: event.data.toolCallId });
92104
});
93105
session.on('tool.execution_progress', (event: any) => {
94-
console.log('[TOOL] execution_progress:', event.data.toolCallId, event.data.message);
106+
debug('[TOOL] execution_progress:', event.data.toolCallId, event.data.message);
95107
poolSend(entry, { type: 'tool_progress', toolCallId: event.data.toolCallId, message: event.data.message });
96108
});
97109
session.on('session.mode_changed', (event: any) => {

0 commit comments

Comments
 (0)