Add backend request and workspace logging

foundry/CLAUDE.md

@@ -44,6 +44,7 @@ Use `pnpm` workspaces and Turborepo.
 - Tail compose logs: `just foundry-dev-logs`
 - Stop the preview stack: `just foundry-preview-down`
 - Tail preview logs: `just foundry-preview-logs`
+- Production deploys should go through `git push` to the deployment branch/workflow. Do not use `railway up` for Foundry deploys.
 
 ## Railway Logs
 
@@ -117,6 +118,8 @@ For all Rivet/RivetKit implementation:
 - Every actor key must be prefixed with workspace namespace (`["ws", workspaceId, ...]`).
 - CLI/TUI/GUI must use `@sandbox-agent/foundry-client` (`packages/client`) for backend access; `rivetkit/client` imports are only allowed inside `packages/client`.
 - Do not add custom backend REST endpoints (no `/v1/*` shim layer).
+- Do not build blocking flows that wait on external systems to become ready or complete. Prefer push-based progression driven by actor messages, events, webhooks, or queue/workflow state changes.
+- Do not rely on retries for correctness or normal control flow. If a queue/workflow/external dependency is not ready yet, model that explicitly and resume from a push/event, instead of polling or retry loops.
 - We own the sandbox-agent project; treat sandbox-agent defects as first-party bugs and fix them instead of working around them.
 - Keep strict single-writer ownership: each table/row has exactly one actor writer.
 - Parent actors (`workspace`, `project`, `task`, `history`, `sandbox-instance`) use command-only loops with no timeout.

foundry/packages/backend/src/actors/index.ts

@@ -7,6 +7,7 @@ import { projectPrSync } from "./project-pr-sync/index.js";
 import { project } from "./project/index.js";
 import { sandboxInstance } from "./sandbox-instance/index.js";
 import { workspace } from "./workspace/index.js";
+import { logger } from "../logging.js";
 
 export const registry = setup({
   serverless: {
@@ -15,6 +16,9 @@ export const registry = setup({
   runner: {
     version: Date.now(),
   },
+  logging: {
+    baseLogger: logger,
+  },
   use: {
     workspace,
     project,

foundry/packages/backend/src/actors/logging.ts

@@ -1,3 +1,5 @@
+import { logger } from "../logging.js";
+
 export function resolveErrorMessage(error: unknown): string {
   if (error instanceof Error) {
     return error.message;
@@ -17,11 +19,11 @@ export function resolveErrorStack(error: unknown): string | undefined {
 }
 
 export function logActorWarning(scope: string, message: string, context?: Record<string, unknown>): void {
-  const payload = {
+  logger.warn(
-    scope,
+    {
+      scope,
+      ...(context ?? {}),
+    },
     message,
-    ...(context ?? {}),
+  );
-  };
-  // eslint-disable-next-line no-console
-  console.warn("[foundry][actor:warn]", payload);
 }

foundry/packages/backend/src/index.ts

@@ -1,5 +1,6 @@
 import { Hono } from "hono";
 import { cors } from "hono/cors";
+import { randomUUID } from "node:crypto";
 import { initActorRuntimeContext } from "./actors/context.js";
 import { registry } from "./actors/index.js";
 import { workspaceKey } from "./actors/keys.js";
@@ -11,12 +12,21 @@ import { createClient } from "rivetkit/client";
 import type { FoundryBillingPlanId } from "@sandbox-agent/foundry-shared";
 import { createDefaultAppShellServices } from "./services/app-shell-runtime.js";
 import { APP_SHELL_WORKSPACE_ID } from "./actors/workspace/app-shell.js";
+import { logger } from "./logging.js";
 
 export interface BackendStartOptions {
   host?: string;
   port?: number;
 }
 
+interface AppWorkspaceLogContext {
+  action?: string;
+  method?: string;
+  path?: string;
+  requestId?: string;
+  sessionId?: string;
+}
+
 function isRivetRequest(request: Request): boolean {
   const { pathname } = new URL(request.url);
   return pathname === "/v1/rivet" || pathname.startsWith("/v1/rivet/");
@@ -79,7 +89,7 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
   }) as any;
 
   // Serve custom Foundry HTTP APIs alongside the RivetKit registry.
-  const app = new Hono();
+  const app = new Hono<{ Variables: { requestId: string } }>();
   const allowHeaders = [
     "Content-Type",
     "Authorization",
@@ -117,36 +127,108 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
       exposeHeaders,
     }),
   );
+  app.use("*", async (c, next) => {
+    const requestId = c.req.header("x-request-id")?.trim() || randomUUID();
+    const start = performance.now();
+    c.set("requestId", requestId);
+    c.header("x-request-id", requestId);
+
+    try {
+      await next();
+    } catch (error) {
+      logger.error(
+        {
+          requestId,
+          method: c.req.method,
+          path: c.req.path,
+          errorMessage: error instanceof Error ? error.message : String(error),
+          errorStack: error instanceof Error ? error.stack : undefined,
+        },
+        "http_request_failed",
+      );
+      throw error;
+    }
+
+    logger.info(
+      {
+        requestId,
+        method: c.req.method,
+        path: c.req.path,
+        status: c.res.status,
+        durationMs: Math.round((performance.now() - start) * 100) / 100,
+      },
+      "http_request",
+    );
+  });
 
   let cachedAppWorkspace: any | null = null;
 
-  const appWorkspace = async () => {
+  const appWorkspace = async (context: AppWorkspaceLogContext = {}) => {
     if (cachedAppWorkspace) return cachedAppWorkspace;
-    const handle = await withRetries(
+
-      async () =>
+    const start = performance.now();
-        await actorClient.workspace.getOrCreate(workspaceKey(APP_SHELL_WORKSPACE_ID), {
+    try {
-          createWithInput: APP_SHELL_WORKSPACE_ID,
+      const handle = await withRetries(
-        }),
+        async () =>
-    );
+          await actorClient.workspace.getOrCreate(workspaceKey(APP_SHELL_WORKSPACE_ID), {
-    cachedAppWorkspace = handle;
+            createWithInput: APP_SHELL_WORKSPACE_ID,
-    return handle;
+          }),
+      );
+      cachedAppWorkspace = handle;
+      logger.info(
+        {
+          ...context,
+          cache: "miss",
+          durationMs: Math.round((performance.now() - start) * 100) / 100,
+        },
+        "app_workspace_resolve",
+      );
+      return handle;
+    } catch (error) {
+      logger.error(
+        {
+          ...context,
+          cache: "miss",
+          durationMs: Math.round((performance.now() - start) * 100) / 100,
+          errorMessage: error instanceof Error ? error.message : String(error),
+          errorStack: error instanceof Error ? error.stack : undefined,
+        },
+        "app_workspace_resolve_failed",
+      );
+      throw error;
+    }
   };
 
-  const appWorkspaceAction = async <T>(run: (workspace: any) => Promise<T>): Promise<T> =>
+  const appWorkspaceAction = async <T>(action: string, run: (workspace: any) => Promise<T>, context: AppWorkspaceLogContext = {}): Promise<T> => {
-    await withRetries(async () => {
+    try {
-      try {
+      return await run(await appWorkspace({ ...context, action }));
-        return await run(await appWorkspace());
+    } catch (error) {
-      } catch (error) {
+      logger.error(
-        // Invalidate cache on connection/actor errors so next retry re-resolves
+        {
-        cachedAppWorkspace = null;
+          ...context,
-        throw error;
+          action,
-      }
+          errorMessage: error instanceof Error ? error.message : String(error),
-    });
+          errorStack: error instanceof Error ? error.stack : undefined,
+        },
+        "app_workspace_action_failed",
+      );
+      throw error;
+    }
+  };
+
+  const requestLogContext = (c: any, sessionId?: string): AppWorkspaceLogContext => ({
+    method: c.req.method,
+    path: c.req.path,
+    requestId: c.get("requestId"),
+    sessionId,
+  });
 
   const resolveSessionId = async (c: any): Promise<string> => {
     const requested = c.req.header("x-foundry-session");
     const { sessionId } = await appWorkspaceAction(
+      "ensureAppSession",
       async (workspace) => await workspace.ensureAppSession(requested && requested.trim().length > 0 ? { requestedSessionId: requested } : {}),
+      requestLogContext(c),
     );
     c.header("x-foundry-session", sessionId);
     return sessionId;
@@ -154,12 +236,18 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
 
   app.get("/v1/app/snapshot", async (c) => {
     const sessionId = await resolveSessionId(c);
-    return c.json(await appWorkspaceAction(async (workspace) => await workspace.getAppSnapshot({ sessionId })));
+    return c.json(
+      await appWorkspaceAction("getAppSnapshot", async (workspace) => await workspace.getAppSnapshot({ sessionId }), requestLogContext(c, sessionId)),
+    );
   });
 
   app.get("/v1/auth/github/start", async (c) => {
     const sessionId = await resolveSessionId(c);
-    const result = await appWorkspaceAction(async (workspace) => await workspace.startAppGithubAuth({ sessionId }));
+    const result = await appWorkspaceAction(
+      "startAppGithubAuth",
+      async (workspace) => await workspace.startAppGithubAuth({ sessionId }),
+      requestLogContext(c, sessionId),
+    );
     return Response.redirect(result.url, 302);
   });
 
@@ -169,11 +257,11 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
     if (!code || !state) {
       return c.text("Missing GitHub OAuth callback parameters", 400);
     }
-    // Do not use appWorkspaceAction here — OAuth codes are single-use,
+    const result = await appWorkspaceAction(
-    // so retrying with the same code after a partial failure will always
+      "completeAppGithubAuth",
-    // produce "bad_verification_code".
+      async (workspace) => await workspace.completeAppGithubAuth({ code, state }),
-    const workspace = await appWorkspace();
+      requestLogContext(c),
-    const result = await workspace.completeAppGithubAuth({ code, state });
+    );
     c.header("x-foundry-session", result.sessionId);
     return Response.redirect(result.redirectTo, 302);
   };
@@ -183,23 +271,27 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
 
   app.post("/v1/app/sign-out", async (c) => {
     const sessionId = await resolveSessionId(c);
-    return c.json(await appWorkspaceAction(async (workspace) => await workspace.signOutApp({ sessionId })));
+    return c.json(await appWorkspaceAction("signOutApp", async (workspace) => await workspace.signOutApp({ sessionId }), requestLogContext(c, sessionId)));
   });
 
   app.post("/v1/app/onboarding/starter-repo/skip", async (c) => {
     const sessionId = await resolveSessionId(c);
-    return c.json(await appWorkspaceAction(async (workspace) => await workspace.skipAppStarterRepo({ sessionId })));
+    return c.json(
+      await appWorkspaceAction("skipAppStarterRepo", async (workspace) => await workspace.skipAppStarterRepo({ sessionId }), requestLogContext(c, sessionId)),
+    );
   });
 
   app.post("/v1/app/organizations/:organizationId/starter-repo/star", async (c) => {
     const sessionId = await resolveSessionId(c);
     return c.json(
       await appWorkspaceAction(
+        "starAppStarterRepo",
         async (workspace) =>
           await workspace.starAppStarterRepo({
             sessionId,
             organizationId: c.req.param("organizationId"),
           }),
+        requestLogContext(c, sessionId),
       ),
     );
   });
@@ -208,11 +300,13 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
     const sessionId = await resolveSessionId(c);
     return c.json(
       await appWorkspaceAction(
+        "selectAppOrganization",
         async (workspace) =>
           await workspace.selectAppOrganization({
             sessionId,
             organizationId: c.req.param("organizationId"),
           }),
+        requestLogContext(c, sessionId),
       ),
     );
   });
@@ -222,6 +316,7 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
     const body = await c.req.json();
     return c.json(
       await appWorkspaceAction(
+        "updateAppOrganizationProfile",
         async (workspace) =>
           await workspace.updateAppOrganizationProfile({
             sessionId,
@@ -230,6 +325,7 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
             slug: typeof body?.slug === "string" ? body.slug : "",
             primaryDomain: typeof body?.primaryDomain === "string" ? body.primaryDomain : "",
           }),
+        requestLogContext(c, sessionId),
       ),
     );
   });
@@ -238,11 +334,13 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
     const sessionId = await resolveSessionId(c);
     return c.json(
       await appWorkspaceAction(
+        "triggerAppRepoImport",
         async (workspace) =>
           await workspace.triggerAppRepoImport({
             sessionId,
             organizationId: c.req.param("organizationId"),
           }),
+        requestLogContext(c, sessionId),
       ),
     );
   });
@@ -251,11 +349,13 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
     const sessionId = await resolveSessionId(c);
     return c.json(
       await appWorkspaceAction(
+        "beginAppGithubInstall",
         async (workspace) =>
           await workspace.beginAppGithubInstall({
             sessionId,
             organizationId: c.req.param("organizationId"),
           }),
+        requestLogContext(c, sessionId),
       ),
     );
   });
@@ -265,7 +365,7 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
     const body = await c.req.json().catch(() => ({}));
     const planId = body?.planId === "free" || body?.planId === "team" ? (body.planId as FoundryBillingPlanId) : "team";
     return c.json(
-      await (await appWorkspace()).createAppCheckoutSession({
+      await (await appWorkspace(requestLogContext(c, sessionId))).createAppCheckoutSession({
         sessionId,
         organizationId: c.req.param("organizationId"),
         planId,
@@ -280,7 +380,7 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
     if (!organizationId || !sessionId || !checkoutSessionId) {
       return c.text("Missing Stripe checkout completion parameters", 400);
     }
-    const result = await (await appWorkspace()).finalizeAppCheckoutSession({
+    const result = await (await appWorkspace(requestLogContext(c, sessionId))).finalizeAppCheckoutSession({
       organizationId,
       sessionId,
       checkoutSessionId,
@@ -291,7 +391,7 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
   app.post("/v1/app/organizations/:organizationId/billing/portal", async (c) => {
     const sessionId = await resolveSessionId(c);
     return c.json(
-      await (await appWorkspace()).createAppBillingPortalSession({
+      await (await appWorkspace(requestLogContext(c, sessionId))).createAppBillingPortalSession({
         sessionId,
         organizationId: c.req.param("organizationId"),
       }),
@@ -301,7 +401,7 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
   app.post("/v1/app/organizations/:organizationId/billing/cancel", async (c) => {
     const sessionId = await resolveSessionId(c);
     return c.json(
-      await (await appWorkspace()).cancelAppScheduledRenewal({
+      await (await appWorkspace(requestLogContext(c, sessionId))).cancelAppScheduledRenewal({
         sessionId,
         organizationId: c.req.param("organizationId"),
       }),
@@ -311,7 +411,7 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
   app.post("/v1/app/organizations/:organizationId/billing/resume", async (c) => {
     const sessionId = await resolveSessionId(c);
     return c.json(
-      await (await appWorkspace()).resumeAppSubscription({
+      await (await appWorkspace(requestLogContext(c, sessionId))).resumeAppSubscription({
         sessionId,
         organizationId: c.req.param("organizationId"),
       }),
@@ -321,7 +421,7 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
   app.post("/v1/app/workspaces/:workspaceId/seat-usage", async (c) => {
     const sessionId = await resolveSessionId(c);
     return c.json(
-      await (await appWorkspace()).recordAppSeatUsage({
+      await (await appWorkspace(requestLogContext(c, sessionId))).recordAppSeatUsage({
         sessionId,
         workspaceId: c.req.param("workspaceId"),
       }),
@@ -330,7 +430,7 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
 
   const handleStripeWebhook = async (c: any) => {
     const payload = await c.req.text();
-    await (await appWorkspace()).handleAppStripeWebhook({
+    await (await appWorkspace(requestLogContext(c))).handleAppStripeWebhook({
       payload,
       signatureHeader: c.req.header("stripe-signature") ?? null,
     });
@@ -341,7 +441,7 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
 
   app.post("/v1/webhooks/github", async (c) => {
     const payload = await c.req.text();
-    await (await appWorkspace()).handleAppGithubWebhook({
+    await (await appWorkspace(requestLogContext(c))).handleAppGithubWebhook({
       payload,
       signatureHeader: c.req.header("x-hub-signature-256") ?? null,
       eventHeader: c.req.header("x-github-event") ?? null,
@@ -360,6 +460,14 @@ export async function startBackend(options: BackendStartOptions = {}): Promise<v
     port: config.backend.port,
   });
 
+  logger.info(
+    {
+      host: config.backend.host,
+      port: config.backend.port,
+    },
+    "backend_started",
+  );
+
   process.on("SIGINT", async () => {
     server.stop();
     process.exit(0);
@@ -407,8 +515,13 @@ async function main(): Promise<void> {
 
 if (import.meta.url === `file://${process.argv[1]}`) {
   main().catch((err: unknown) => {
-    const message = err instanceof Error ? (err.stack ?? err.message) : String(err);
+    logger.fatal(
-    console.error(message);
+      {
+        errorMessage: err instanceof Error ? err.message : String(err),
+        errorStack: err instanceof Error ? err.stack : undefined,
+      },
+      "backend_start_failed",
+    );
     process.exit(1);
   });
 }

foundry/packages/backend/src/logging.ts

@@ -0,0 +1,11 @@
+import { pino } from "pino";
+
+const level = process.env.FOUNDRY_LOG_LEVEL ?? process.env.LOG_LEVEL ?? process.env.RIVET_LOG_LEVEL ?? "info";
+
+export const logger = pino({
+  level,
+  base: {
+    service: "foundry-backend",
+  },
+  timestamp: pino.stdTimeFunctions.isoTime,
+});