feat(logging): add comprehensive runtime logs across benchify batch-str-replace integration to aid debugging cloud deployment issues.

brandonkachen · codebuff-team · brandonkachen · commit 5a739696876e · 2025-09-23T15:02:12.000-07:00
This adds end-to-end logs for processing, batching, and deployment interactions to aid issue reproduction.

🤖 Generated with Codebuff
Co-Authored-By: Codebuff &lt;noreply@codebuff.com&gt;
diff --git a/backend/src/process-str-replace.ts b/backend/src/process-str-replace.ts
@@ -21,8 +21,22 @@ export async function processStrReplace(
     }
   | { tool: 'str_replace'; path: string; error: string }
 > {
+  logger.debug(
+    {
+      path,
+      replacementsCount: replacements.length,
+    },
+    'processStrReplace: Starting to process str_replace',
+  )
+
   const initialContent = await initialContentPromise
   if (initialContent === null) {
+    logger.warn(
+      {
+        path,
+      },
+      'processStrReplace: File does not exist',
+    )
     return {
       tool: 'str_replace',
       path,
@@ -31,6 +45,15 @@ export async function processStrReplace(
     }
   }
 
+  logger.debug(
+    {
+      path,
+      initialContentLength: initialContent.length,
+      hasContent: !!initialContent,
+    },
+    'processStrReplace: Successfully read initial file content',
+  )
+
   // Process each old/new string pair
   let currentContent = initialContent
   let messages: string[] = []
diff --git a/backend/src/run-agent-step.ts b/backend/src/run-agent-step.ts
@@ -289,6 +289,16 @@ export const runAgentStep = async (
 
   const stream = getStream(messagesWithSystem(agentMessages, system))
 
+  logger.info(
+    {
+      agentStepId,
+      userInputId,
+      agentType,
+      agentId: agentState.agentId,
+    },
+    'run-agent-step: About to call processStreamWithTools',
+  )
+
   const {
     toolCalls,
     toolResults: newToolResults,
@@ -313,6 +323,17 @@ export const runAgentStep = async (
     onResponseChunk,
     fullResponse,
   })
+
+  logger.info(
+    {
+      agentStepId,
+      userInputId,
+      toolCallsCount: toolCalls.length,
+      toolResultsCount: newToolResults.length,
+      toolCallTypes: toolCalls.map((tc) => tc.toolName),
+    },
+    'run-agent-step: Completed processStreamWithTools',
+  )
   toolResults.push(...newToolResults)
 
   fullResponse = fullResponseAfterStream
diff --git a/backend/src/tools/batch-str-replace.ts b/backend/src/tools/batch-str-replace.ts
@@ -33,24 +33,54 @@ function getBenchifyClient(): Benchify | null {
   if (!benchifyClient) {
     let benchifyApiKey: string | undefined
     try {
+      // Log available environment variables (partial for debugging)
+      const envKeys = Object.keys(process.env)
+        .filter((key) => key.includes('BENCHIFY') || key.includes('API'))
+        .slice(0, 10) // Limit to first 10 for safety
+
       benchifyApiKey = env.BENCHIFY_API_KEY
+      logger.info(
+        {
+          hasApiKey: !!benchifyApiKey,
+          apiKeyLength: benchifyApiKey?.length || 0,
+          apiKeyPrefix: benchifyApiKey?.substring(0, 8) || 'none',
+          availableEnvKeys: envKeys,
+          nodeEnv: process.env.NODE_ENV,
+        },
+        'getBenchifyClient: Attempting to access BENCHIFY_API_KEY from environment',
+      )
     } catch (error) {
       logger.warn(
         {
           error: error instanceof Error ? error.message : String(error),
+          nodeEnv: process.env.NODE_ENV,
         },
-        'Failed to access BENCHIFY_API_KEY from environment',
+        'getBenchifyClient: Failed to access BENCHIFY_API_KEY from environment',
       )
       return null
     }
 
     if (!benchifyApiKey) {
+      logger.warn(
+        'getBenchifyClient: No BENCHIFY_API_KEY found, returning null',
+      )
       return null
     }
 
-    benchifyClient = new Benchify({
-      apiKey: benchifyApiKey,
-    })
+    try {
+      benchifyClient = new Benchify({
+        apiKey: benchifyApiKey,
+      })
+      logger.info('getBenchifyClient: Successfully created Benchify client')
+    } catch (error) {
+      logger.error(
+        {
+          error: error instanceof Error ? error.message : String(error),
+        },
+        'getBenchifyClient: Failed to create Benchify client',
+      )
+      return null
+    }
   }
   return benchifyClient
 }
@@ -84,7 +114,20 @@ export async function executeBatchStrReplaces({
   state: Record<string, any>
   userId: string | undefined
 }) {
+  logger.info(
+    {
+      deferredCount: deferredStrReplaces.length,
+      agentStepId,
+      userInputId,
+      userId,
+    },
+    'executeBatchStrReplaces: Starting batch execution',
+  )
+
   if (deferredStrReplaces.length === 0) {
+    logger.info(
+      'executeBatchStrReplaces: No deferred str_replace operations, returning early',
+    )
     return
   }
 
@@ -281,8 +324,30 @@ export async function executeBatchStrReplaces({
   await Promise.all(batchPromises)
 
   // Call benchify with intended changes (even if str_replace operations failed)
+  logger.info(
+    {
+      intendedChangesCount: intendedChanges.length,
+      editedFilesCount: editedFiles.length,
+      intendedChangeFiles: intendedChanges.map((f) => f.path),
+      editedFilesList: editedFiles.map((f) => f.path),
+      agentStepId,
+      userInputId,
+    },
+    'executeBatchStrReplaces: Preparing to call benchify',
+  )
+
   const client = getBenchifyClient()
-  if (!client || intendedChanges.length === 0) {
+  if (!client) {
+    logger.warn(
+      'executeBatchStrReplaces: No benchify client available, skipping benchify call',
+    )
+    return
+  }
+
+  if (intendedChanges.length === 0) {
+    logger.warn(
+      'executeBatchStrReplaces: No intended changes for benchify, skipping benchify call',
+    )
     return
   }
 
@@ -340,26 +405,68 @@ async function callBenchify(
     userId: string | undefined
   },
 ): Promise<{ path: string; contents: string }[] | null> {
+  logger.info(
+    {
+      editedFilesCount: editedFiles.length,
+      editedFilesList: editedFiles.map((f) => f.path),
+      totalContentLength: editedFiles.reduce(
+        (sum, f) => sum + f.contents.length,
+        0,
+      ),
+      ...context,
+    },
+    'callBenchify: Starting benchify API call',
+  )
+
   const client = getBenchifyClient()
   if (!client) {
+    logger.error('callBenchify: No benchify client available')
     return null
   }
 
-  const response = await client.runFixer(editedFiles, {
-    fix_types: ['string_literals'],
-  })
+  try {
+    logger.info(
+      {
+        fixTypes: ['string_literals'],
+        ...context,
+      },
+      'callBenchify: Calling client.runFixer',
+    )
 
-  logger.info(
-    {
-      responseReceived: !!response,
-      responseLength: response?.length || 0,
-      responseFiles: response?.map((r) => r.path) || [],
-      ...context,
-    },
-    'Benchify runFixer API response received',
-  )
+    const response = await client.runFixer(editedFiles, {
+      fix_types: ['string_literals'],
+    })
 
-  return response
+    logger.info(
+      {
+        responseReceived: !!response,
+        responseLength: response?.length || 0,
+        responseFiles: response?.map((r) => r.path) || [],
+        responseContentLengths: response?.map((r) => r.contents.length) || [],
+        ...context,
+      },
+      'callBenchify: Benchify runFixer API response received successfully',
+    )
+
+    return response
+  } catch (error) {
+    logger.error(
+      {
+        error:
+          error instanceof Error
+            ? {
+                message: error.message,
+                stack: error.stack,
+                name: error.name,
+              }
+            : String(error),
+        editedFilesCount: editedFiles.length,
+        ...context,
+      },
+      'callBenchify: Failed to call benchify API',
+    )
+    throw error
+  }
 }
 
 /**
@@ -376,7 +483,25 @@ async function applyBenchifyResults(
     userInputId: string
   },
 ) {
+  logger.info(
+    {
+      benchifyFilesCount: benchifyFiles.length,
+      benchifyFilesList: benchifyFiles.map((f) => f.path),
+      toolCallsCount: context.toolCalls.length,
+      userInputId: context.userInputId,
+    },
+    'applyBenchifyResults: Starting to apply benchify results',
+  )
+
   for (const benchifyFile of benchifyFiles) {
+    logger.debug(
+      {
+        fileName: benchifyFile.path,
+        contentLength: benchifyFile.contents.length,
+        userInputId: context.userInputId,
+      },
+      'applyBenchifyResults: Processing benchify file',
+    )
     try {
       // Find the corresponding tool call for this file
       const relatedToolCall = context.toolCalls.find(
@@ -385,12 +510,27 @@ async function applyBenchifyResults(
 
       if (!relatedToolCall) {
         logger.warn(
-          { fileName: benchifyFile.path },
-          'No matching tool call found for benchify result',
+          {
+            fileName: benchifyFile.path,
+            availableToolCallPaths: context.toolCalls.map(
+              (tc) => tc.input.path,
+            ),
+            userInputId: context.userInputId,
+          },
+          'applyBenchifyResults: No matching tool call found for benchify result',
         )
         continue
       }
 
+      logger.debug(
+        {
+          fileName: benchifyFile.path,
+          relatedToolCallId: relatedToolCall.toolCallId,
+          userInputId: context.userInputId,
+        },
+        'applyBenchifyResults: Found matching tool call for benchify result',
+      )
+
       // Get the original file content from our stored contents
       const originalContent =
         context.state.originalContents?.[benchifyFile.path]
diff --git a/backend/src/tools/stream-parser.ts b/backend/src/tools/stream-parser.ts
@@ -129,6 +129,18 @@ export async function processStreamWithTools(options: {
 
           batchState.deferredStrReplaces.push({ toolCall })
 
+          logger.debug(
+            {
+              toolCallId,
+              filePath: input.path,
+              replacementsCount: input.replacements?.length || 0,
+              currentDeferredCount: batchState.deferredStrReplaces.length,
+              agentStepId,
+              userInputId,
+            },
+            'stream-parser: Deferring str_replace tool for batch execution',
+          )
+
           // Still emit the tool call event
           onResponseChunk({
             type: 'tool_call',
@@ -291,16 +303,27 @@ export async function processStreamWithTools(options: {
       {
         triggeringEvent: 'stream_end',
         deferredCount: batchState.deferredStrReplaces.length,
+        deferredFiles: batchState.deferredStrReplaces.map(
+          (d) => d.toolCall.input.path,
+        ),
         agentStepId,
         userInputId,
       },
-      `toolCallback: Triggering batch str_replace execution (${batchState.deferredStrReplaces.length} deferred tools) due to stream end`,
+      `stream-parser: Triggering batch str_replace execution (${batchState.deferredStrReplaces.length} deferred tools) due to stream end`,
     )
 
     batchState.strReplacePhaseComplete = true
 
     // Execute all deferred str_replace tools as a batch
     previousToolCallFinished = previousToolCallFinished.then(async () => {
+      logger.info(
+        {
+          agentStepId,
+          userInputId,
+          deferredCount: batchState.deferredStrReplaces.length,
+        },
+        'stream-parser: About to call executeBatchStrReplaces from stream end handler',
+      )
       await executeBatchStrReplaces({
         deferredStrReplaces: batchState.deferredStrReplaces,
         toolCalls,
@@ -316,6 +339,13 @@ export async function processStreamWithTools(options: {
         state,
         userId,
       })
+      logger.info(
+        {
+          agentStepId,
+          userInputId,
+        },
+        'stream-parser: Completed executeBatchStrReplaces from stream end handler',
+      )
     })
   }
 
