feat: Enhanced logging and SDK prompt improvements (#94)
* Initial plan * Initial analysis: Found root cause of double entries bug Co-authored-by: thedotmack <683968+thedotmack@users.noreply.github.com> * Fix double entries by assigning generatorPromise in handleSessionInit Co-authored-by: thedotmack <683968+thedotmack@users.noreply.github.com> * feat(logging): Enhance HTTP request logging and session management - Added middleware for logging HTTP requests and responses, excluding static assets and health checks. - Introduced a method to summarize request bodies for specific endpoints. - Improved logging for user prompt synchronization with Chroma, including duration tracking. - Enhanced session initialization logging to include additional session details. - Updated observation and summary logging to provide more context and error handling during Chroma synchronization. - Refactored tool name formatting for logging in the SessionManager. - Expanded logger component types to include 'HTTP', 'SESSION', and 'CHROMA'. * Refactor SDK prompts and logging for improved clarity and functionality - Updated buildInitPrompt to clarify the observer's role and what to record. - Enhanced buildSummaryPrompt with clearer instructions for summarizing ongoing sessions. - Improved buildContinuationPrompt to emphasize the focus on deliverables and capabilities. - Refactored WorkerService to utilize a centralized tool formatting function for logging. - Added truncation for logged responses and observations to improve readability. - Updated SessionManager to log the queuing of summarize actions with session details. - Enhanced App and Sidebar components to support refreshing stats on sidebar open. - Refactored useStats hook to allow manual refreshing of stats while maintaining automatic loading on mount. --------- Co-authored-by: copilot-swe-agent[bot] <198982749+Copilot@users.noreply.github.com> Co-authored-by: thedotmack <683968+thedotmack@users.noreply.github.com>
This commit is contained in:
Alex Newman
@@ -66,12 +66,64 @@ export class WorkerService {
|
||||
this.app.use(express.json({ limit: '50mb' }));
|
||||
this.app.use(cors());
|
||||
|
||||
// HTTP request/response logging middleware
|
||||
this.app.use((req, res, next) => {
|
||||
// Skip logging for static assets and health checks
|
||||
if (req.path.startsWith('/health') || req.path === '/' || req.path.includes('.')) {
|
||||
return next();
|
||||
}
|
||||
|
||||
const start = Date.now();
|
||||
const requestId = `${req.method}-${Date.now()}`;
|
||||
|
||||
// Log incoming request with body summary
|
||||
const bodySummary = this.summarizeRequestBody(req.method, req.path, req.body);
|
||||
logger.info('HTTP', `→ ${req.method} ${req.path}`, { requestId }, bodySummary);
|
||||
|
||||
// Capture response
|
||||
const originalSend = res.send.bind(res);
|
||||
res.send = function(body: any) {
|
||||
const duration = Date.now() - start;
|
||||
logger.info('HTTP', `← ${res.statusCode} ${req.path}`, { requestId, duration: `${duration}ms` });
|
||||
return originalSend(body);
|
||||
};
|
||||
|
||||
next();
|
||||
});
|
||||
|
||||
// Serve static files for web UI (viewer-bundle.js, logos, fonts, etc.)
|
||||
const packageRoot = getPackageRoot();
|
||||
const uiDir = path.join(packageRoot, 'plugin', 'ui');
|
||||
this.app.use(express.static(uiDir));
|
||||
}
|
||||
|
||||
/**
|
||||
* Summarize request body for logging
|
||||
*/
|
||||
private summarizeRequestBody(method: string, path: string, body: any): string {
|
||||
if (!body || Object.keys(body).length === 0) return '';
|
||||
|
||||
// Session init
|
||||
if (path.includes('/init')) {
|
||||
return '';
|
||||
}
|
||||
|
||||
// Observations
|
||||
if (path.includes('/observations')) {
|
||||
const toolName = body.tool_name || '?';
|
||||
const toolInput = body.tool_input;
|
||||
const toolSummary = logger.formatTool(toolName, toolInput);
|
||||
return `tool=${toolSummary}`;
|
||||
}
|
||||
|
||||
// Summarize request
|
||||
if (path.includes('/summarize')) {
|
||||
return 'requesting summary';
|
||||
}
|
||||
|
||||
return '';
|
||||
}
|
||||
|
||||
/**
|
||||
* Setup HTTP routes
|
||||
*/
|
||||
@@ -245,16 +297,31 @@ export class WorkerService {
|
||||
}
|
||||
});
|
||||
|
||||
// Sync user prompt to Chroma (fire-and-forget)
|
||||
// Sync user prompt to Chroma with error logging
|
||||
const chromaStart = Date.now();
|
||||
const promptText = latestPrompt.prompt_text;
|
||||
this.dbManager.getChromaSync().syncUserPrompt(
|
||||
latestPrompt.id,
|
||||
latestPrompt.sdk_session_id,
|
||||
latestPrompt.project,
|
||||
latestPrompt.prompt_text,
|
||||
promptText,
|
||||
latestPrompt.prompt_number,
|
||||
latestPrompt.created_at_epoch
|
||||
).catch(err => {
|
||||
logger.error('WORKER', 'Failed to sync user_prompt to Chroma', { promptId: latestPrompt.id }, err);
|
||||
).then(() => {
|
||||
const chromaDuration = Date.now() - chromaStart;
|
||||
const truncatedPrompt = promptText.length > 60
|
||||
? promptText.substring(0, 60) + '...'
|
||||
: promptText;
|
||||
logger.debug('CHROMA', 'User prompt synced', {
|
||||
promptId: latestPrompt.id,
|
||||
duration: `${chromaDuration}ms`,
|
||||
prompt: truncatedPrompt
|
||||
});
|
||||
}).catch(err => {
|
||||
logger.error('CHROMA', 'Failed to sync user_prompt', {
|
||||
promptId: latestPrompt.id,
|
||||
sessionId: sessionDbId
|
||||
}, err);
|
||||
});
|
||||
}
|
||||
|
||||
@@ -262,8 +329,14 @@ export class WorkerService {
|
||||
this.broadcastProcessingStatus(true);
|
||||
|
||||
// Start SDK agent in background (pass worker ref for spinner control)
|
||||
logger.info('SESSION', 'Generator starting', {
|
||||
sessionId: sessionDbId,
|
||||
project: session.project,
|
||||
promptNum: session.lastPromptNumber
|
||||
});
|
||||
|
||||
session.generatorPromise = this.sdkAgent.startSession(session, this).catch(err => {
|
||||
logger.failure('WORKER', 'SDK agent error', { sessionId: sessionDbId }, err);
|
||||
logger.failure('SDK', 'SDK agent error', { sessionId: sessionDbId }, err);
|
||||
});
|
||||
|
||||
// Broadcast SSE event
|
||||
@@ -300,8 +373,13 @@ export class WorkerService {
|
||||
// CRITICAL: Ensure SDK agent is running to consume the queue
|
||||
const session = this.sessionManager.getSession(sessionDbId);
|
||||
if (session && !session.generatorPromise) {
|
||||
logger.info('SESSION', 'Generator auto-starting (observation)', {
|
||||
sessionId: sessionDbId,
|
||||
queueDepth: session.pendingMessages.length
|
||||
});
|
||||
|
||||
session.generatorPromise = this.sdkAgent.startSession(session, this).catch(err => {
|
||||
logger.failure('WORKER', 'SDK agent error', { sessionId: sessionDbId }, err);
|
||||
logger.failure('SDK', 'SDK agent error', { sessionId: sessionDbId }, err);
|
||||
});
|
||||
}
|
||||
|
||||
@@ -330,8 +408,13 @@ export class WorkerService {
|
||||
// CRITICAL: Ensure SDK agent is running to consume the queue
|
||||
const session = this.sessionManager.getSession(sessionDbId);
|
||||
if (session && !session.generatorPromise) {
|
||||
logger.info('SESSION', 'Generator auto-starting (summarize)', {
|
||||
sessionId: sessionDbId,
|
||||
queueDepth: session.pendingMessages.length
|
||||
});
|
||||
|
||||
session.generatorPromise = this.sdkAgent.startSession(session, this).catch(err => {
|
||||
logger.failure('WORKER', 'SDK agent error', { sessionId: sessionDbId }, err);
|
||||
logger.failure('SDK', 'SDK agent error', { sessionId: sessionDbId }, err);
|
||||
});
|
||||
}
|
||||
|
||||
|
||||
@@ -69,13 +69,20 @@ export class SDKAgent {
|
||||
: typeof content === 'string' ? content : '';
|
||||
|
||||
const responseSize = textContent.length;
|
||||
logger.dataOut('SDK', `Response received (${responseSize} chars)`, {
|
||||
sessionId: session.sessionDbId,
|
||||
promptNumber: session.lastPromptNumber
|
||||
});
|
||||
|
||||
// Parse and process response
|
||||
await this.processSDKResponse(session, textContent, worker);
|
||||
// Only log non-empty responses (filter out noise)
|
||||
if (responseSize > 0) {
|
||||
const truncatedResponse = responseSize > 100
|
||||
? textContent.substring(0, 100) + '...'
|
||||
: textContent;
|
||||
logger.dataOut('SDK', `Response received (${responseSize} chars)`, {
|
||||
sessionId: session.sessionDbId,
|
||||
promptNumber: session.lastPromptNumber
|
||||
}, truncatedResponse);
|
||||
|
||||
// Parse and process response
|
||||
await this.processSDKResponse(session, textContent, worker);
|
||||
}
|
||||
}
|
||||
|
||||
// Log result messages
|
||||
@@ -185,7 +192,20 @@ export class SDKAgent {
|
||||
session.lastPromptNumber
|
||||
);
|
||||
|
||||
// Sync to Chroma (fire-and-forget)
|
||||
// Log observation details
|
||||
logger.info('SDK', 'Observation saved', {
|
||||
sessionId: session.sessionDbId,
|
||||
obsId,
|
||||
type: obs.type,
|
||||
title: obs.title.substring(0, 60) + (obs.title.length > 60 ? '...' : ''),
|
||||
files: obs.files?.length || 0,
|
||||
concepts: obs.concepts?.length || 0
|
||||
});
|
||||
|
||||
// Sync to Chroma with error logging
|
||||
const chromaStart = Date.now();
|
||||
const obsType = obs.type;
|
||||
const obsTitle = obs.title;
|
||||
this.dbManager.getChromaSync().syncObservation(
|
||||
obsId,
|
||||
session.claudeSessionId,
|
||||
@@ -193,7 +213,25 @@ export class SDKAgent {
|
||||
obs,
|
||||
session.lastPromptNumber,
|
||||
createdAtEpoch
|
||||
).catch(() => {});
|
||||
).then(() => {
|
||||
const chromaDuration = Date.now() - chromaStart;
|
||||
const truncatedTitle = obsTitle.length > 50
|
||||
? obsTitle.substring(0, 50) + '...'
|
||||
: obsTitle;
|
||||
logger.debug('CHROMA', 'Observation synced', {
|
||||
obsId,
|
||||
duration: `${chromaDuration}ms`,
|
||||
type: obsType,
|
||||
title: truncatedTitle
|
||||
});
|
||||
}).catch(err => {
|
||||
logger.error('CHROMA', 'Failed to sync observation', {
|
||||
obsId,
|
||||
sessionId: session.sessionDbId,
|
||||
type: obsType,
|
||||
title: obsTitle.substring(0, 50)
|
||||
}, err);
|
||||
});
|
||||
|
||||
// Broadcast to SSE clients (for web UI)
|
||||
if (worker && worker.sseBroadcaster) {
|
||||
@@ -218,8 +256,6 @@ export class SDKAgent {
|
||||
}
|
||||
});
|
||||
}
|
||||
|
||||
logger.info('SDK', 'Observation saved', { obsId, type: obs.type });
|
||||
}
|
||||
|
||||
// Parse summary
|
||||
@@ -234,7 +270,18 @@ export class SDKAgent {
|
||||
session.lastPromptNumber
|
||||
);
|
||||
|
||||
// Sync to Chroma (fire-and-forget)
|
||||
// Log summary details
|
||||
logger.info('SDK', 'Summary saved', {
|
||||
sessionId: session.sessionDbId,
|
||||
summaryId,
|
||||
request: summary.request.substring(0, 60) + (summary.request.length > 60 ? '...' : ''),
|
||||
hasCompleted: !!summary.completed,
|
||||
hasNextSteps: !!summary.next_steps
|
||||
});
|
||||
|
||||
// Sync to Chroma with error logging
|
||||
const chromaStart = Date.now();
|
||||
const summaryRequest = summary.request;
|
||||
this.dbManager.getChromaSync().syncSummary(
|
||||
summaryId,
|
||||
session.claudeSessionId,
|
||||
@@ -242,7 +289,23 @@ export class SDKAgent {
|
||||
summary,
|
||||
session.lastPromptNumber,
|
||||
createdAtEpoch
|
||||
).catch(() => {});
|
||||
).then(() => {
|
||||
const chromaDuration = Date.now() - chromaStart;
|
||||
const truncatedRequest = summaryRequest.length > 50
|
||||
? summaryRequest.substring(0, 50) + '...'
|
||||
: summaryRequest;
|
||||
logger.debug('CHROMA', 'Summary synced', {
|
||||
summaryId,
|
||||
duration: `${chromaDuration}ms`,
|
||||
request: truncatedRequest
|
||||
});
|
||||
}).catch(err => {
|
||||
logger.error('CHROMA', 'Failed to sync summary', {
|
||||
summaryId,
|
||||
sessionId: session.sessionDbId,
|
||||
request: summaryRequest.substring(0, 50)
|
||||
}, err);
|
||||
});
|
||||
|
||||
// Broadcast to SSE clients (for web UI)
|
||||
if (worker && worker.sseBroadcaster) {
|
||||
@@ -263,8 +326,6 @@ export class SDKAgent {
|
||||
}
|
||||
});
|
||||
}
|
||||
|
||||
logger.info('SDK', 'Summary saved', { summaryId });
|
||||
}
|
||||
|
||||
// Check and stop spinner after processing (debounced)
|
||||
|
||||
@@ -55,7 +55,13 @@ export class SessionManager {
|
||||
const emitter = new EventEmitter();
|
||||
this.sessionQueues.set(sessionDbId, emitter);
|
||||
|
||||
logger.info('WORKER', 'Session initialized', { sessionDbId, project: session.project });
|
||||
logger.info('SESSION', 'Session initialized', {
|
||||
sessionId: sessionDbId,
|
||||
project: session.project,
|
||||
claudeSessionId: session.claudeSessionId,
|
||||
queueDepth: 0,
|
||||
hasGenerator: false
|
||||
});
|
||||
|
||||
return session;
|
||||
}
|
||||
@@ -78,6 +84,8 @@ export class SessionManager {
|
||||
session = this.initializeSession(sessionDbId);
|
||||
}
|
||||
|
||||
const beforeDepth = session.pendingMessages.length;
|
||||
|
||||
session.pendingMessages.push({
|
||||
type: 'observation',
|
||||
tool_name: data.tool_name,
|
||||
@@ -87,13 +95,19 @@ export class SessionManager {
|
||||
cwd: data.cwd
|
||||
});
|
||||
|
||||
const afterDepth = session.pendingMessages.length;
|
||||
|
||||
// Notify generator immediately (zero latency)
|
||||
const emitter = this.sessionQueues.get(sessionDbId);
|
||||
emitter?.emit('message');
|
||||
|
||||
logger.debug('WORKER', 'Observation queued', {
|
||||
sessionDbId,
|
||||
queueLength: session.pendingMessages.length
|
||||
// Format tool name for logging
|
||||
const toolSummary = logger.formatTool(data.tool_name, data.tool_input);
|
||||
|
||||
logger.info('SESSION', `Observation queued (${beforeDepth}→${afterDepth})`, {
|
||||
sessionId: sessionDbId,
|
||||
tool: toolSummary,
|
||||
hasGenerator: !!session.generatorPromise
|
||||
});
|
||||
}
|
||||
|
||||
@@ -108,12 +122,19 @@ export class SessionManager {
|
||||
session = this.initializeSession(sessionDbId);
|
||||
}
|
||||
|
||||
const beforeDepth = session.pendingMessages.length;
|
||||
|
||||
session.pendingMessages.push({ type: 'summarize' });
|
||||
|
||||
const afterDepth = session.pendingMessages.length;
|
||||
|
||||
const emitter = this.sessionQueues.get(sessionDbId);
|
||||
emitter?.emit('message');
|
||||
|
||||
logger.debug('WORKER', 'Summarize queued', { sessionDbId });
|
||||
logger.info('SESSION', `Summarize queued (${beforeDepth}→${afterDepth})`, {
|
||||
sessionId: sessionDbId,
|
||||
hasGenerator: !!session.generatorPromise
|
||||
});
|
||||
}
|
||||
|
||||
/**
|
||||
@@ -125,6 +146,8 @@ export class SessionManager {
|
||||
return; // Already deleted
|
||||
}
|
||||
|
||||
const sessionDuration = Date.now() - session.startTime;
|
||||
|
||||
// Abort the SDK agent
|
||||
session.abortController.abort();
|
||||
|
||||
@@ -137,7 +160,11 @@ export class SessionManager {
|
||||
this.sessions.delete(sessionDbId);
|
||||
this.sessionQueues.delete(sessionDbId);
|
||||
|
||||
logger.info('WORKER', 'Session deleted', { sessionDbId });
|
||||
logger.info('SESSION', 'Session deleted', {
|
||||
sessionId: sessionDbId,
|
||||
duration: `${(sessionDuration / 1000).toFixed(1)}s`,
|
||||
project: session.project
|
||||
});
|
||||
}
|
||||
|
||||
/**
|
||||
|
||||
Reference in New Issue
Block a user