feat: add developer-mode startup and stack hydration timing (#1619)

* feat: add developer-mode startup and stack hydration timing

Instrument boot-to-list and detail hydration with commit-aligned milestones, truthful request stages, and destination/gateway debug duration logs so performance work is guided by measurements.

* fix: redact stack names and complete hydration request stages

Stop logging stack identifiers in containers debug timing, and record state_dispatch (plus detail fetch spans) so copied reports match the advertised stage breakdown.

backend/src/routes/imageUpdates.ts

@@ -18,6 +18,7 @@ import { buildPolicyGateOptions } from '../helpers/policyGate';
 import { summarizeBlockReasons } from '../utils/policy-risk';
 import { isValidStackName } from '../utils/validation';
 import { sanitizeForLog } from '../utils/safeLog';
+import { logDebugTiming } from '../utils/requestTiming';
 import { getErrorMessage } from '../utils/errors';
 
 // Fleet aggregation cache: 2-minute TTL, shared across dashboard tabs.
@@ -41,12 +42,26 @@ imageUpdatesRouter.get('/', authMiddleware, (req: Request, res: Response): void
 // readiness view. Auth-only, matching GET /; the boolean GET / is left intact so
 // the cross-version fleet aggregation contract is unaffected.
 imageUpdatesRouter.get('/detail', authMiddleware, (req: Request, res: Response): void => {
+  const startedAt = Date.now();
+  let outcome: 'ok' | 'error' = 'ok';
+  let count = 0;
   try {
     const nodeId = req.nodeId ?? NodeRegistry.getInstance().getDefaultNodeId();
-    res.json(DatabaseService.getInstance().getStackUpdateDetail(nodeId));
+    const detail = DatabaseService.getInstance().getStackUpdateDetail(nodeId);
+    count = Object.keys(detail).length;
+    res.json(detail);
   } catch (error) {
+    outcome = 'error';
     console.error('Failed to fetch image update detail:', error);
     res.status(500).json({ error: 'Failed to fetch image update detail' });
+  } finally {
+    logDebugTiming('[ImageUpdates:debug]', {
+      route: 'GET /detail',
+      nodeId: req.nodeId,
+      count,
+      elapsedMs: Date.now() - startedAt,
+      outcome,
+    });
   }
 });
 
@@ -66,8 +81,23 @@ imageUpdatesRouter.post('/refresh', authMiddleware, (req: Request, res: Response
   }
 });
 
-imageUpdatesRouter.get('/status', authMiddleware, (_req: Request, res: Response): void => {
-  res.json(ImageUpdateService.getInstance().getStatus());
+imageUpdatesRouter.get('/status', authMiddleware, (req: Request, res: Response): void => {
+  const startedAt = Date.now();
+  let outcome: 'ok' | 'error' = 'ok';
+  try {
+    res.json(ImageUpdateService.getInstance().getStatus());
+  } catch (error) {
+    outcome = 'error';
+    console.error('Failed to fetch image update status:', error);
+    res.status(500).json({ error: 'Failed to fetch image update status' });
+  } finally {
+    logDebugTiming('[ImageUpdates:debug]', {
+      route: 'GET /status',
+      nodeId: req.nodeId,
+      elapsedMs: Date.now() - startedAt,
+      outcome,
+    });
+  }
 });
 
 /**

backend/src/routes/nodes.ts

@@ -22,6 +22,7 @@ import { getErrorMessage } from '../utils/errors';
 import { toPublicNode } from '../helpers/publicNode';
 import { isDebugEnabled } from '../utils/debug';
 import { sanitizeForLog } from '../utils/safeLog';
+import { logDebugTiming } from '../utils/requestTiming';
 
 const NODE_SCOPE_MESSAGE = 'API tokens cannot manage nodes.';
 const REMOTE_META_CACHE_TTL = 3 * 60 * 1000;
@@ -116,11 +117,25 @@ function mintPilotEnrollment(nodeId: number, req: Request): { token: string; exp
 export const nodesRouter = Router();
 
 nodesRouter.get('/', async (req: Request, res: Response) => {
+  const startedAt = Date.now();
+  let outcome: 'ok' | 'error' = 'ok';
+  let count = 0;
   try {
     const nodes = DatabaseService.getInstance().getNodes();
+    count = nodes.length;
     res.json(nodes.map(toPublicNode));
   } catch (error) {
+    outcome = 'error';
     res.status(500).json({ error: 'Failed to fetch nodes' });
+  } finally {
+    // Gateway-owned: /api/nodes is proxy-exempt, so this always runs on the
+    // control instance and gates on the gateway's developer_mode.
+    logDebugTiming('[Nodes:debug]', {
+      route: 'GET /nodes',
+      count,
+      elapsedMs: Date.now() - startedAt,
+      outcome,
+    });
   }
 });
 
@@ -577,14 +592,19 @@ nodesRouter.post('/:id/test', async (req: Request, res: Response) => {
 });
 
 nodesRouter.get('/:id/meta', authMiddleware, async (req: Request, res: Response) => {
+  const startedAt = Date.now();
+  let outcome: 'ok' | 'error' = 'ok';
+  let id = NaN;
+  let nodeType = 'unknown';
   try {
-    const id = parseInt(req.params.id as string);
+    id = parseInt(req.params.id as string);
     const node = DatabaseService.getInstance().getNode(id);
     if (!node) {
+      outcome = 'error';
       res.status(404).json({ error: 'Node not found' });
       return;
     }
-    if (isDebugEnabled()) console.log(`[Nodes:diag] meta node=${id} type=${node.type}`);
+    nodeType = node.type;
 
     if (node.type === 'local') {
       res.json({ version: getSenchoVersion(), capabilities: getActiveCapabilities() });
@@ -606,8 +626,19 @@ nodesRouter.get('/:id/meta', authMiddleware, async (req: Request, res: Response)
 
     res.json(meta);
   } catch (error: unknown) {
+    outcome = 'error';
     console.error('Failed to fetch node meta:', error);
     const message = getErrorMessage(error, 'Failed to fetch node metadata');
     res.status(500).json({ error: message });
+  } finally {
+    // Gateway-owned: the frontend fetches meta with localOnly, so this runs on
+    // the control instance and gates on the gateway's developer_mode.
+    logDebugTiming('[Nodes:debug]', {
+      route: 'GET /nodes/:id/meta',
+      node: id,
+      type: nodeType,
+      elapsedMs: Date.now() - startedAt,
+      outcome,
+    });
   }
 });

backend/src/routes/notifications.ts

@@ -16,6 +16,7 @@ import {
   syncSuppressionRuleToFleet,
 } from '../helpers/notificationSuppressionSync';
 import { isDebugEnabled } from '../utils/debug';
+import { logDebugTiming } from '../utils/requestTiming';
 import { getErrorMessage } from '../utils/errors';
 import { sanitizeForLog } from '../utils/safeLog';
 import { parseIntParam } from '../utils/parseIntParam';
@@ -183,14 +184,27 @@ function parseSuppressionRuleBody(
 export const notificationsRouter = Router();
 
 notificationsRouter.get('/', authMiddleware, async (req: Request, res: Response): Promise<void> => {
+  const startedAt = Date.now();
+  let outcome: 'ok' | 'error' = 'ok';
+  let count = 0;
   try {
     const nodeId = req.nodeId ?? 0;
     const category = typeof req.query.category === 'string' ? req.query.category : undefined;
     const history = DatabaseService.getInstance().getNotificationHistory(nodeId, 50, category);
+    count = history.length;
     res.json(history);
   } catch (error) {
+    outcome = 'error';
     console.error('Failed to fetch notifications:', error);
     res.status(500).json({ error: 'Failed to fetch notifications' });
+  } finally {
+    logDebugTiming('[Notifications:debug]', {
+      route: 'GET /',
+      nodeId: req.nodeId,
+      count,
+      elapsedMs: Date.now() - startedAt,
+      outcome,
+    });
   }
 });
 

backend/src/routes/stacks.ts

@@ -16,7 +16,7 @@ import { ComposeService, getComposeRollbackInfo } from '../services/ComposeServi
 import DockerController, { type BulkStackInfo } from '../services/DockerController';
 import { DatabaseService, type StackDossierFields } from '../services/DatabaseService';
 import { MeshService } from '../services/MeshService';
-import { CacheService } from '../services/CacheService';
+import { CacheService, type CacheFetchOutcome } from '../services/CacheService';
 import { UpdatePreviewService } from '../services/UpdatePreviewService';
 import { GitSourceService, GitSourceError, repoHost as gitRepoHost } from '../services/GitSourceService';
 import { enforcePolicyPreDeploy } from '../services/PolicyEnforcement';
@@ -47,6 +47,7 @@ import { normalizeBulkPaths, destWithinAnySource } from '../utils/bulkPaths';
 import { getErrorMessage } from '../utils/errors';
 import { isDebugEnabled } from '../utils/debug';
 import { sanitizeForLog } from '../utils/safeLog';
+import { logDebugTiming } from '../utils/requestTiming';
 import { sendGitSourceError } from '../utils/gitSourceHttp';
 import { buildPolicyGateOptions, runPolicyGate, triggerPostDeployScan, describePolicyBlock } from '../helpers/policyGate';
 import { parseComposePreview, type ComposePreview } from '../helpers/composePreview';
@@ -234,25 +235,45 @@ stacksRouter.param('stackName', (req, res, next, stackName) => {
 
 stacksRouter.get('/', async (req: Request, res: Response) => {
   if (!requirePermission(req, res, 'stack:read')) return;
+  const startedAt = Date.now();
+  let outcome: 'ok' | 'error' = 'ok';
+  let count = 0;
   try {
     const stacks = await FileSystemService.getInstance(req.nodeId).getStacks();
+    count = stacks.length;
     res.json(stacks);
   } catch (error) {
+    outcome = 'error';
     res.status(500).json({ error: 'Failed to fetch stacks' });
+  } finally {
+    logDebugTiming('[Stacks:debug]', {
+      route: 'GET /',
+      nodeId: req.nodeId,
+      count,
+      elapsedMs: Date.now() - startedAt,
+      outcome,
+    });
   }
 });
 
 stacksRouter.get('/statuses', async (req: Request, res: Response) => {
   if (!requirePermission(req, res, 'stack:read')) return;
+  const startedAt = Date.now();
+  let outcome: 'ok' | 'error' = 'ok';
+  let cacheOutcome: CacheFetchOutcome | null = null;
+  let dockerMs: number | null = null;
+  let count = 0;
   try {
-    const result = await CacheService.getInstance().getOrFetch(
+    const { value: result, outcome: fetchOutcome } = await CacheService.getInstance().getOrFetchWithMeta(
       `stack-statuses:${req.nodeId}`,
       STACK_STATUSES_CACHE_TTL_MS,
       async () => {
         const stacks = await FileSystemService.getInstance(req.nodeId).getStacks();
         const stackNames = stacks.map((s: string) => s.replace(/\.(yml|yaml)$/, ''));
         const dockerController = DockerController.getInstance(req.nodeId);
+        const dockerStartedAt = Date.now();
         const bulkInfo = await dockerController.getBulkStackStatuses(stackNames);
+        dockerMs = Date.now() - dockerStartedAt;
         const data: Record<string, BulkStackInfo> = {};
         for (const stack of stacks) {
           const name = stack.replace(/\.(yml|yaml)$/, '');
@@ -261,6 +282,8 @@ stacksRouter.get('/statuses', async (req: Request, res: Response) => {
         return data;
       },
     );
+    cacheOutcome = fetchOutcome;
+    count = Object.keys(result).length;
     // Git-source labels are computed live, outside the cache, so linking or
     // unlinking a stack's Git source is reflected immediately. The Docker
     // status portion keeps its short TTL; only the cheap source label is fresh.
@@ -285,8 +308,19 @@ stacksRouter.get('/statuses', async (req: Request, res: Response) => {
     }
     res.json(withSource);
   } catch (error) {
+    outcome = 'error';
     console.error('Failed to fetch stack statuses:', error);
     res.status(500).json({ error: 'Failed to fetch stack statuses' });
+  } finally {
+    logDebugTiming('[Stacks:debug]', {
+      route: 'GET /statuses',
+      nodeId: req.nodeId,
+      cacheOutcome,
+      count,
+      dockerMs,
+      elapsedMs: Date.now() - startedAt,
+      outcome,
+    });
   }
 });
 
@@ -1151,13 +1185,30 @@ stacksRouter.get('/:stackName/containers', async (req: Request, res: Response) =
     return;
   }
   if (!requirePermission(req, res, 'stack:read', 'stack', stackName)) return;
+  const startedAt = Date.now();
+  let outcome: 'ok' | 'error' = 'ok';
+  let dockerMs: number | null = null;
+  let count = 0;
   try {
     const dockerController = DockerController.getInstance(req.nodeId);
+    const dockerStartedAt = Date.now();
     const containers = await dockerController.getContainersByStack(stackName);
+    dockerMs = Date.now() - dockerStartedAt;
+    count = containers.length;
     res.json(containers);
   } catch (error) {
+    outcome = 'error';
     console.error('[Stacks] Failed to fetch containers for %s:', sanitizeForLog(stackName), error);
     res.status(500).json({ error: 'Failed to fetch containers' });
+  } finally {
+    logDebugTiming('[Stacks:debug]', {
+      route: 'GET /:stack/containers',
+      nodeId: req.nodeId,
+      count,
+      dockerMs,
+      elapsedMs: Date.now() - startedAt,
+      outcome,
+    });
   }
 });