Skip to content

Add logging to agent processing #174

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
yuusoft-bot wants to merge 1 commit into
base: main
Choose a base branch
from
Open

Add logging to agent processing #174

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
111 changes: 95 additions & 16 deletions src/commands/agent.js
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,44 +1,71 @@
import { query } from "@anthropic-ai/claude-agent-sdk";
import { setupWorktree } from "../utils/git.js";

// Helper function for consistent timestamp logging
const log = (sessionId, ...args) => {
const timestamp = new Date().toISOString();
console.log(`[${timestamp}] [session:${sessionId || 'global'}]`, ...args);
};

const logWarn = (sessionId, ...args) => {
const timestamp = new Date().toISOString();
console.warn(`[${timestamp}] [session:${sessionId || 'global'}] [WARN]`, ...args);
};

const logError = (sessionId, ...args) => {
const timestamp = new Date().toISOString();
console.error(`[${timestamp}] [session:${sessionId || 'global'}] [ERROR]`, ...args);
};

export const agent = async (deps) => {
const { sessionService, configService, discordService } = deps;

log(null, "Fetching sessions with status 'ready'...");
const readySessions = await sessionService.getSessionsByStatus({ status: "ready" });

if (readySessions.length === 0) {
console.log("No sessions with status 'ready' found");
log(null, "No sessions with status 'ready' found");
return;
}

console.log(`Found ${readySessions.length} ready sessions`);
log(null, `Found ${readySessions.length} ready sessions`);

// Process all ready sessions
for (const session of readySessions) {
console.log(`\nRunning agent for session: ${session.sessionId}`);
console.log(`Messages count: ${session.messages.length}`);
const startTime = Date.now();
log(session.sessionId, `Starting agent processing`);
log(session.sessionId, `Messages count: ${session.messages.length}`);

try {
log(session.sessionId, `Updating status to 'in-progress'...`);
await sessionService.updateSessionStatus({
sessionId: session.sessionId,
status: "in-progress"
});
log(session.sessionId, `Status updated to 'in-progress'`);

// Get project repository
log(session.sessionId, `Getting project info for: ${session.project}`);
const project = sessionService.getProjectById({ projectId: session.project });
if (!project || !project.gitRepository) {
throw new Error(`No repository found for project ${session.project} in config file.`);
}
log(session.sessionId, `Project found, repository: ${project.gitRepository}`);

// Setup git worktree using project repository
log(session.sessionId, `Setting up git worktree...`);
const worktreePath = await setupWorktree(session.sessionId, project.gitRepository);
console.log(`\nWorktree ready at: ${worktreePath}\n`);
log(session.sessionId, `Worktree ready at: ${worktreePath}`);

log(session.sessionId, `Fetching Claude session ID...`);
let claudeSessionId = await sessionService.getClaudeSessionIdBySessionId({
sessionId: session.sessionId
});
log(session.sessionId, `Claude session ID: ${claudeSessionId || '(new session)'}`);

const lastMessage = session.messages[session.messages.length - 1];
const userPrompt = `${lastMessage.content}`;
log(session.sessionId, `User prompt length: ${userPrompt.length} chars`);

const queryOptions = {
model: "opus",
Expand Down Expand Up @@ -77,43 +104,70 @@ export const agent = async (deps) => {
);
}
queryOptions.systemPrompt = systemPrompt;
console.log(`Using system prompt preset: ${promptPresetName}`);
log(session.sessionId, `Using system prompt preset: ${promptPresetName}`);

}
else {
console.warn(`Prompt preset '${promptPresetName}' not found in config. Using default.`,);
logWarn(session.sessionId, `Prompt preset '${promptPresetName}' not found in config. Using default.`);
}

if (claudeSessionId) {
queryOptions.resume = claudeSessionId;
log(session.sessionId, `Resuming existing Claude session: ${claudeSessionId}`);
}

try {
log(session.sessionId, `Calling Claude Agent SDK query()...`);
const queryStartTime = Date.now();
const result = query({
prompt: userPrompt,
options: queryOptions,
});
log(session.sessionId, `Query object created, starting async iteration...`);

//const assistantContent = [];
let messageCount = 0;
let lastMessageTime = Date.now();
let lastMessageType = null;

for await (const message of result) {
messageCount++;
const now = Date.now();
const timeSinceLastMessage = now - lastMessageTime;
lastMessageTime = now;

// Log detailed message info
const messageInfo = {
count: messageCount,
type: message.type,
subtype: message.subtype || null,
hasContent: !!message.message?.content,
contentLength: message.message?.content ? JSON.stringify(message.message.content).length : 0,
timeSinceLastMs: timeSinceLastMessage,
};
log(session.sessionId, `Message received:`, JSON.stringify(messageInfo));
lastMessageType = message.type;

// Check for interruption
log(session.sessionId, `Checking session status for interruption...`);
const currentSessionState = await sessionService.getViewBySessionId({ sessionId: session.sessionId });
if (currentSessionState.status !== "in-progress") {
console.warn(`Interruption detected for session ${session.sessionId}.`);
logWarn(session.sessionId, `Interruption detected! Current status: ${currentSessionState.status}`);
break;
}

if (!claudeSessionId && message.type === 'system' && message.subtype === 'init' && message.session_id) {
claudeSessionId = message.session_id;
log(session.sessionId, `Saving Claude session ID: ${message.session_id}`);
await sessionService.addClaudeSessionRecord({
sessionId: session.sessionId,
claudeSessionId: message.session_id,
});
console.log(`Claude session started and saved for ${session.sessionId}`);
log(session.sessionId, `Claude session ID saved successfully`);
}

// Collect all content from the streaming response
if (message.message?.content) {
log(session.sessionId, `Appending assistant message to session...`);
await sessionService.appendSessionMessages({
sessionId: session.sessionId,
messages: [{
Expand All @@ -123,38 +177,63 @@ export const agent = async (deps) => {
timestamp: Date.now()
}]
});
log(session.sessionId, `Assistant message appended`);
}
}

const queryDuration = Date.now() - queryStartTime;
log(session.sessionId, `Async iteration completed. Total messages: ${messageCount}, Duration: ${queryDuration}ms, Last message type: ${lastMessageType}`);

} catch (error) {
console.warn(`Error processing session ${session.sessionId}:`, error);
logError(session.sessionId, `Error during Claude query processing:`, error.message);
logError(session.sessionId, `Error stack:`, error.stack);
}

log(session.sessionId, `Checking final session status before moving to review...`);
const currentSessionState = await sessionService.getViewBySessionId({ sessionId: session.sessionId });
if (currentSessionState.status !== "in-progress") {
console.warn(`Work on session ${session.sessionId} was interrupted by user. Discarding results.`);
logWarn(session.sessionId, `Work was interrupted by user. Current status: ${currentSessionState.status}. Discarding results.`);
continue;
}

log(session.sessionId, `Updating session status to 'review'...`);
await sessionService.updateSessionStatus({
sessionId: session.sessionId,
status: "review"
});

console.log(`\nSession ${session.sessionId} moved to review`);
const totalDuration = Date.now() - startTime;
log(session.sessionId, `Session processing completed. Status: review. Total duration: ${totalDuration}ms`);

} catch (error) {
console.warn(`Failed to process session ${session.sessionId}:`, error);
logError(session.sessionId, `Failed to process session:`, error.message);
logError(session.sessionId, `Error stack:`, error.stack);
// Continue to next session
}
}

console.log(`\nAll ${readySessions.length} sessions processed`);
log(null, `All ${readySessions.length} sessions processed`);
}

export const agentStart = async (deps) => {
let loopCount = 0;
log(null, `Agent loop starting...`);

while (true) {
await agent(deps);
loopCount++;
log(null, `Agent loop iteration #${loopCount} starting...`);
const loopStartTime = Date.now();

try {
await agent(deps);
} catch (error) {
logError(null, `Unexpected error in agent loop iteration #${loopCount}:`, error.message);
logError(null, `Error stack:`, error.stack);
}

const loopDuration = Date.now() - loopStartTime;
log(null, `Agent loop iteration #${loopCount} completed in ${loopDuration}ms. Waiting 5 seconds...`);

// Wait 5 seconds before next run
await new Promise(resolve => setTimeout(resolve, 5000));
}
Expand Down