logging

agents-api/src/domains/run/agents/tools/function-tools.ts

@@ -24,6 +24,7 @@ export async function getFunctionTools(
   const functionTools: ToolSet = {};
   const project = ctx.executionContext.project;
   try {
+    const withRefStart = Date.now();
     const functionToolsForAgent = await withRef(
       manageDbPool,
       ctx.executionContext.resolvedRef,
@@ -38,6 +39,13 @@ export async function getFunctionTools(
         });
       }
     );
+    const withRefMs = Date.now() - withRefStart;
+    if (withRefMs > 5_000) {
+      logger.info(
+        { ref: ctx.executionContext.resolvedRef.name, withRefMs, subAgentId: ctx.config.id },
+        'Slow withRef in getFunctionTools'
+      );
+    }
 
     const functionToolsData = functionToolsForAgent.data ?? [];
 

agents-api/src/domains/run/services/TriggerService.ts

@@ -546,6 +546,10 @@ export async function dispatchExecution(params: {
   // Wrap agent execution in a single promise protected by waitUntil
   // The trigger.message_received span is created inside executeAgentAsync
   const dispatchedAt = Date.now();
+  logger.info(
+    { tenantId, projectId, agentId, triggerId, invocationId, conversationId, dispatchedAt },
+    'Trigger execution dispatched and starting execution'
+  );
   const executionPromise = executeAgentAsync({
     tenantId,
     projectId,
@@ -653,7 +657,10 @@ export async function executeAgentAsync(
     forwardedHeaders,
     invocationType = 'trigger',
   } = params;
-
+  logger.info(
+    { tenantId, projectId, agentId, triggerId, invocationId },
+    'executeAgentAsync: starting'
+  );
   let userMessage: string;
   let messageParts: Part[];
 
@@ -695,14 +702,16 @@ export async function executeAgentAsync(
   }
 
   // Load project FIRST to get agent name
+  const loadProjectStart = Date.now();
   const project = await withRef(manageDbPool, resolvedRef, async (db) => {
     return await getFullProjectWithRelationIds(db)({
       scopes: { tenantId, projectId },
     });
   });
+  const loadProjectMs = Date.now() - loadProjectStart;
 
   logger.info(
-    { tenantId, projectId, agentId, triggerId, invocationId, hasProject: !!project },
+    { tenantId, projectId, agentId, triggerId, invocationId, hasProject: !!project, loadProjectMs },
     'executeAgentAsync: project loaded'
   );
 
@@ -884,6 +893,7 @@ export async function executeAgentAsync(
 
       try {
         // Create conversation and set active agent
+        const convStart = Date.now();
         await createOrGetConversation(runDbClient)({
           id: conversationId,
           tenantId,
@@ -900,6 +910,12 @@ export async function executeAgentAsync(
           agentId,
           ref: resolvedRef,
         });
+        const convMs = Date.now() - convStart;
+
+        logger.info(
+          { invocationId, conversationId, convMs },
+          'executeAgentAsync: conversation created'
+        );
 
         if (messages && messages.length > 0) {
           for (const msg of messages) {

agents-api/src/middleware/branchScopedDb.ts

@@ -70,7 +70,12 @@ export const branchScopedDbMiddleware = async (c: Context, next: Next) => {
   }
 
   // Get a dedicated connection from the pool
+  const mwStartTime = Date.now();
   const connection: PoolClient = await pool.connect();
+  const connectMs = Date.now() - mwStartTime;
+  if (connectMs > 5_000) {
+    logger.info({ ref: resolvedRef.name, connectMs }, 'Slow pool.connect in branchScopedDb');
+  }
   let tempBranch: string | null = null;
 
   try {
@@ -79,7 +84,12 @@ export const branchScopedDbMiddleware = async (c: Context, next: Next) => {
 
     if (resolvedRef.type === 'branch') {
       logger.debug({ branch: resolvedRef.name }, 'Checking out branch');
+      const checkoutStart = Date.now();
       await checkoutBranch(requestDb)({ branchName: resolvedRef.name, autoCommitPending: true });
+      const checkoutMs = Date.now() - checkoutStart;
+      if (checkoutMs > 5_000) {
+        logger.info({ ref: resolvedRef.name, checkoutMs }, 'Slow checkoutBranch in branchScopedDb');
+      }
     } else {
       // For tags/commits, create temporary branch (needed for reads)
       tempBranch = `temp_${resolvedRef.type}_${resolvedRef.hash}_${generateId()}`;
@@ -139,15 +149,31 @@ export const branchScopedDbMiddleware = async (c: Context, next: Next) => {
     }
   } finally {
     // Always cleanup: checkout main and release connection
+    const cleanupStart = Date.now();
     try {
       await connection.query(`SELECT DOLT_CHECKOUT('main')`);
 
       if (tempBranch) {
         await connection.query(`SELECT DOLT_BRANCH('-D', $1)`, [tempBranch]);
       }
     } catch (cleanupError) {
+      logger.info(
+        {
+          ref: resolvedRef.name,
+          cleanupMs: Date.now() - cleanupStart,
+          error: cleanupError instanceof Error ? cleanupError.message : String(cleanupError),
+        },
+        'branchScopedDb cleanup failed'
+      );
       logger.error({ error: cleanupError }, 'Error during connection cleanup');
     } finally {
+      const totalMs = Date.now() - mwStartTime;
+      if (totalMs > 5_000) {
+        logger.info(
+          { ref: resolvedRef.name, totalMs, connectMs },
+          'Slow branchScopedDb middleware total duration'
+        );
+      }
       connection.release();
     }
   }

agents-api/src/middleware/ref.ts

@@ -229,8 +229,20 @@ async function resolveProjectRef(
 
   let refResult: Awaited<ReturnType<ReturnType<typeof resolveRef>>> = null;
   try {
+    const resolveStart = Date.now();
     refResult = await resolveRef(db)(projectMain);
+    const resolveMs = Date.now() - resolveStart;
+    if (resolveMs > 5_000) {
+      logger.info(
+        { projectMain, resolveMs, found: !!refResult },
+        'Slow resolveRef in ref middleware'
+      );
+    }
   } catch (error) {
+    logger.info(
+      { projectMain, error: error instanceof Error ? error.message : String(error) },
+      'resolveRef threw in ref middleware'
+    );
     logger.warn({ error, projectMain }, 'Failed to resolve project main branch');
     refResult = null;
   }

packages/agents-core/src/dolt/ref-helpers.ts

@@ -25,6 +25,8 @@ export const getTenantScopedRef = (tenantId: string, ref: string): string => {
 export const resolveRef =
   (db: AgentsManageDatabaseClient) =>
   async (ref: string): Promise<ResolvedRef | null> => {
+    const startTime = Date.now();
+
     if (isValidCommitHash(ref)) {
       return {
         type: 'commit',
@@ -43,8 +45,25 @@ export const resolveRef =
       };
     }
 
+    const branchQueryStart = Date.now();
     const branches = await doltListBranches(db)();
+    const branchQueryMs = Date.now() - branchQueryStart;
     const branch = branches.find((b) => b.name === ref);
+
+    if (!branch) {
+      const totalMs = Date.now() - startTime;
+      logger.info(
+        {
+          ref,
+          branchCount: branches.length,
+          branchQueryMs,
+          totalMs,
+          branchNames: branches.map((b) => b.name),
+        },
+        'resolveRef: branch not found in dolt_branches result'
+      );
+    }
+
     if (branch) {
       return {
         type: 'branch',

packages/agents-core/src/dolt/ref-scope.ts

@@ -147,15 +147,29 @@ export async function withRef<T>(
     'Acquiring connection for ref scope'
   );
 
+  const connectStart = Date.now();
   const connection: PoolClient = await pool.connect();
+  const connectMs = Date.now() - connectStart;
+  if (connectMs > 5_000) {
+    logger.info({ ref: resolvedRef.name, connectMs, connectionId }, 'Slow pool.connect in withRef');
+  }
+
   let tempBranch: string | null = null;
 
   try {
     const db = drizzle(connection, { schema }) as unknown as AgentsManageDatabaseClient;
 
     if (resolvedRef.type === 'branch') {
       logger.debug({ branch: resolvedRef.name, connectionId }, 'Checking out branch');
+      const checkoutStart = Date.now();
       await checkoutBranch(db)({ branchName: resolvedRef.name, syncSchema: false });
+      const checkoutMs = Date.now() - checkoutStart;
+      if (checkoutMs > 5_000) {
+        logger.info(
+          { ref: resolvedRef.name, checkoutMs, connectionId },
+          'Slow checkoutBranch in withRef'
+        );
+      }
     } else {
       // For tags/commits, create temporary branch from the hash
       // Include timestamp for easier cleanup of orphaned branches
@@ -237,6 +251,7 @@ export async function withRef<T>(
     throw error;
   } finally {
     // Cleanup: checkout main, delete temp branch, release connection
+    const cleanupStart = Date.now();
     try {
       await connection.query(`SELECT DOLT_CHECKOUT('main')`);
 
@@ -245,14 +260,30 @@ export async function withRef<T>(
         await connection.query(`SELECT DOLT_BRANCH('-D', $1)`, [tempBranch]);
       }
     } catch (cleanupError) {
+      logger.info(
+        {
+          ref: resolvedRef.name,
+          connectionId,
+          cleanupMs: Date.now() - cleanupStart,
+          error: cleanupError instanceof Error ? cleanupError.message : String(cleanupError),
+        },
+        'withRef cleanup failed'
+      );
       logger.error(
         { error: cleanupError, tempBranch, connectionId },
         'Error during ref scope cleanup'
       );
     } finally {
+      const totalMs = Date.now() - startTime;
+      if (totalMs > 5_000) {
+        logger.info(
+          { ref: resolvedRef.name, totalMs, connectMs, connectionId },
+          'Slow withRef total duration'
+        );
+      }
       connection.release();
       logger.debug(
-        { ref: resolvedRef.name, duration: Date.now() - startTime, connectionId },
+        { ref: resolvedRef.name, duration: totalMs, connectionId },
         'Connection released'
       );
     }