feat(cloud): TRANSFER-SLOW-N60 a completed owner hand-off logs how long each step took

cloud/apps/sandbox-control/src/index.ts

@@ -161,6 +161,7 @@ import { forgetShareLink, handleShareGateway } from './share-gateway'
 import { handleShareRoute, revokeSandboxShares, sharePathMode, shareSecret, shareSecrets } from './share-links'
 import { SshKeyRequestSchema, updateSshKey } from './ssh-access'
 import { createTransferNotifier, dismissNotice, listNotices, notifyPreviousOwner, type TransferNotifier } from './owner-transfer-notices'
+import { createStepTimer, ownerTransferTimingLine } from './owner-transfer-timing'
 import { createTeamMembershipCheck, type TeamMembershipCheck } from './team-membership'
 import { audit, auditSession } from './api/audit'
 import { ALL_EVENT_FAMILIES, AUTH_EVENT_FAMILIES, AuditIngestError, AuditIngestSchema, BILLING_EVENT_FAMILIES, ingestAuditEvents } from './api/audit-ingest'
@@ -2342,9 +2343,23 @@ async function workspaceRoute(request: Request, url: URL, env: Env, deps: Deps,
         }
       }
       const current = (await getSandbox(env.SANDBOX_DB, row.id)) ?? row
+      // TRANSFER-SLOW-N60: the desktop's confirmation waits for this whole request, so a completed
+      // hand-off logs how long each part took (owner-transfer-timing.ts).
+      const timer = createStepTimer(clock)
+      const confirmNewOwner = deps.teamMembership ?? createTeamMembershipCheck(env)
       let patched: Awaited<ReturnType<typeof patchWorkspace>> =
         Object.keys(rest).length > 0
-          ? await patchWorkspace(db, caller, current, rest, now, deps.teamMembership ?? createTeamMembershipCheck(env), (running) => suspendSandbox(life, running))
+          ? await timer.step('patch', () =>
+              patchWorkspace(
+                db,
+                caller,
+                current,
+                rest,
+                now,
+                (accountId, userId) => timer.step('membership', () => confirmNewOwner(accountId, userId)),
+                (running) => timer.step('suspend', () => suspendSandbox(life, running))
+              )
+            )
           : { row: current, revoke: 'none' }
       const transferred = patched.row.user_id !== current.user_id
       if (transferred) {
@@ -2352,20 +2367,24 @@ async function workspaceRoute(request: Request, url: URL, env: Env, deps: Deps,
         // together. End what acted for the previous owner: the share links, the in-VM API token,
         // and the proxy's cached copy of the keys this workspace's sessions were using.
         forgetProviderEnv(row.id)
-        await revokeSandboxShares(env.SANDBOX_DB, row.id, now)
-        await revokeWorkspaceTokens(env.SANDBOX_DB, row.id, now)
+        await timer.step('revokes', async () => {
+          await revokeSandboxShares(env.SANDBOX_DB, row.id, now)
+          await revokeWorkspaceTokens(env.SANDBOX_DB, row.id, now)
+        })
       }
       // Tell the previous owner: a notice in Orca, an email asked of auth, and an audit row saying
       // whether anything reached them. After the hand-off, and never able to fail or undo it.
       const told = transferred
-        ? await notifyPreviousOwner(
-            db,
-            { before: current, after: patched.row, actorUserId: caller.userId, now },
-            { email: deps.transferNotifier ?? createTransferNotifier(env), membership: deps.teamMembership ?? createTeamMembershipCheck(env) }
-          ).catch((error: unknown) => {
-            console.log(JSON.stringify({ event: 'owner_transfer_notify_failed', sandboxId: row.id, error: String(error).slice(0, 120) }))
-            return null
-          })
+        ? await timer.step('notify', () =>
+            notifyPreviousOwner(
+              db,
+              { before: current, after: patched.row, actorUserId: caller.userId, now },
+              { email: deps.transferNotifier ?? createTransferNotifier(env), membership: deps.teamMembership ?? createTeamMembershipCheck(env) }
+            ).catch((error: unknown) => {
+              console.log(JSON.stringify({ event: 'owner_transfer_notify_failed', sandboxId: row.id, error: String(error).slice(0, 120) }))
+              return null
+            })
+          )
         : null
       // Who can open a workspace decides who its agents act as and whose secrets it gets, so both
       // directions of a share, and a change of owner, go in the team's audit log.
@@ -2383,35 +2402,40 @@ async function workspaceRoute(request: Request, url: URL, env: Env, deps: Deps,
         )
       }
       if (transferred) {
-        await auditSession(
-          db,
-          caller,
-          { action: 'workspace.owner_changed', targetType: 'workspace', targetId: row.id, detail: { fromUserId: current.user_id, toUserId: patched.row.user_id } },
-          now
-        )
-        // Recorded as Orca's doing, a millisecond later so it reads after the change it follows.
-        await audit(
-          db,
-          { accountId: current.account_id, type: 'system', id: 'control-plane', userId: null },
-          {
-            action: 'workspace.owner_notified',
-            targetType: 'workspace',
-            targetId: row.id,
-            detail: { toUserId: current.user_id, reached: told?.reached ?? false, inApp: told?.inApp ?? false, emailed: told?.email.emailed ?? false, emailMode: told?.email.mode ?? null }
-          },
-          now + 1
-        ).catch(() => undefined)
+        await timer.step('audit', async () => {
+          await auditSession(
+            db,
+            caller,
+            { action: 'workspace.owner_changed', targetType: 'workspace', targetId: row.id, detail: { fromUserId: current.user_id, toUserId: patched.row.user_id } },
+            now
+          )
+          // Recorded as Orca's doing, a millisecond later so it reads after the change it follows.
+          await audit(
+            db,
+            { accountId: current.account_id, type: 'system', id: 'control-plane', userId: null },
+            {
+              action: 'workspace.owner_notified',
+              targetType: 'workspace',
+              targetId: row.id,
+              detail: { toUserId: current.user_id, reached: told?.reached ?? false, inApp: told?.inApp ?? false, emailed: told?.email.emailed ?? false, emailMode: told?.email.mode ?? null }
+            },
+            now + 1
+          ).catch(() => undefined)
+        })
       }
       if (archivedNow && patched.revoke === 'none') {
         // Archiving disconnects teammates' devices, as before.
         patched = { ...patched, revoke: 'non_owner' }
       }
-      if (patched.revoke !== 'none') {
-        // Readers lose the sleeping copy at once, before (and regardless of) the VM-side revokes.
-        await pruneReadSnapshotToOwner(db, patched.row)
-      }
+      const revoke = patched.revoke
       const revoked =
-        patched.revoke === 'none' ? null : await revokeForAccessChange(life, patched.row, patched.revoke, caller.userId)
+        revoke === 'none'
+          ? null
+          : await timer.step('grantRevokes', async () => {
+              // Readers lose the sleeping copy at once, before (and regardless of) the VM-side revokes.
+              await pruneReadSnapshotToOwner(db, patched.row)
+              return revokeForAccessChange(life, patched.row, revoke, caller.userId)
+            })
       if (patched.row.status === 'running' && !transferred && patched.row.visibility !== current.visibility) {
         // A share changes which account (if any) the agents use (D10/D13): rebuild the env now.
         // Never for a new owner: a transferred workspace is stopped, and its env is not rebuilt for them.
@@ -2422,8 +2446,12 @@ async function workspaceRoute(request: Request, url: URL, env: Env, deps: Deps,
           await work
         }
       }
+      const workspace = await timer.step('view', () => view(patched.row))
+      if (transferred) {
+        console.log(ownerTransferTimingLine(timer.durations(), clock() - now))
+      }
       return json({
-        workspace: await view(patched.row),
+        workspace,
         ...(revoked ? { revoked } : {}),
         // For the person who made the change: whether the previous owner will hear about it.
         ...(transferred ? { previousOwner: { userId: current.user_id, notified: told?.reached ?? false, inApp: told?.inApp ?? false, emailed: told?.email.emailed ?? false } } : {})

cloud/apps/sandbox-control/src/owner-transfer-timing.ts

@@ -0,0 +1,42 @@
+// How long each part of an owner hand-off took (OWNER-TRANSFER, TRANSFER-SLOW-N60). The desktop
+// keeps its confirmation open until the whole request answers, so when that is slow this says
+// which part was: one log line per completed hand-off, step names and milliseconds only. Never an
+// id, a name or anything from the request.
+export type StepTimer = {
+  /** Runs `run` and adds its elapsed time to `name` (a step run twice is summed). */
+  step<T>(name: string, run: () => Promise<T>): Promise<T>
+  /** Milliseconds per step so far, in the order the steps first ran. */
+  durations(): Record<string, number>
+}
+
+export function createStepTimer(clock: () => number): StepTimer {
+  const elapsed = new Map<string, number>()
+  return {
+    async step(name, run) {
+      const started = clock()
+      try {
+        return await run()
+      } finally {
+        // A step that throws is still counted: a slow failure is the interesting one.
+        elapsed.set(name, (elapsed.get(name) ?? 0) + Math.max(0, clock() - started))
+      }
+    },
+    durations: () => Object.fromEntries(elapsed)
+  }
+}
+
+/**
+ * The line for one completed hand-off. `patchMs` is the whole registry edit, which contains the
+ * membership check and the stop; what is left of it is the owner write.
+ */
+export function ownerTransferTimingLine(durations: Record<string, number>, totalMs: number): string {
+  const { patch = 0, membership = 0, suspend = 0, ...rest } = durations
+  return JSON.stringify({
+    event: 'owner_transfer_timing',
+    totalMs: Math.max(0, totalMs),
+    membershipMs: membership,
+    suspendMs: suspend,
+    writeMs: Math.max(0, patch - membership - suspend),
+    ...Object.fromEntries(Object.entries(rest).map(([name, ms]) => [`${name}Ms`, ms]))
+  })
+}

cloud/apps/sandbox-control/test/owner-transfer.test.ts

@@ -13,6 +13,7 @@ import { mintApiKey, WORKSPACE_TOKEN_SCOPES } from '../src/api/keys'
 import { connectedMembers } from '../src/member-git'
 import { ENV_COMMAND, START_COMMAND } from '../src/sandbox-vm-commands'
 import { ownersForSandbox } from '../src/secrets'
+import { createStepTimer, ownerTransferTimingLine } from '../src/owner-transfer-timing'
 import { isSharedWorkspace } from '../src/shared-workspace'
 import { getSandbox } from '../src/store'
 import { createTeamMembershipCheck, membershipKey, MEMBERSHIP_KEY_PURPOSE, type MembershipAnswer } from '../src/team-membership'
@@ -703,3 +704,72 @@ describe('telling the previous owner', () => {
     expect(listed.body.workspaces.find((w: { id: string }) => w.id === t.id).ownershipTransferredAt).toBe(mark)
   })
 })
+
+describe('how long a hand-off took (TRANSFER-SLOW-N60)', () => {
+  const timingLines = () => logs.filter((line) => line.includes('"owner_transfer_timing"')).map((line) => JSON.parse(line) as Record<string, unknown>)
+
+  it('logs one line per completed hand-off: step names and milliseconds, nothing else', async () => {
+    // The membership check is the slow part here: 3 s for the new owner, 3 s again for the notice.
+    const slow: { h?: Harness } = {}
+    const t = await setup({
+      teamMembership: async () => {
+        slow.h?.advance(3_000)
+        return { member: true }
+      }
+    })
+    slow.h = t.h
+    const moved = await t.transfer(t.admin, 'mia')
+    expect(moved.status).toBe(200)
+    const lines = timingLines()
+    expect(lines).toHaveLength(1)
+    const line = lines[0]!
+    expect(Object.keys(line).sort()).toEqual(
+      ['auditMs', 'event', 'grantRevokesMs', 'membershipMs', 'notifyMs', 'revokesMs', 'suspendMs', 'totalMs', 'viewMs', 'writeMs'].sort()
+    )
+    expect(line).toMatchObject({ event: 'owner_transfer_timing', membershipMs: 3_000, notifyMs: 3_000, suspendMs: 0, writeMs: 0, totalMs: 6_000 })
+    // Durations only: no workspace, person or team in it.
+    for (const [key, value] of Object.entries(line)) {
+      expect(key === 'event' || typeof value === 'number').toBe(true)
+    }
+    for (const word of [t.id, 'mia', 'mallory', 'ada', 'acme']) {
+      expect(JSON.stringify(line)).not.toContain(word)
+    }
+  })
+
+  it('answers the hand-off exactly as before', async () => {
+    const t = await setup()
+    const moved = await t.transfer(t.admin, 'mia')
+    expect(moved.status).toBe(200)
+    expect(moved.body.workspace).toMatchObject({ ownerUserId: 'mia', status: 'suspended' })
+    expect(moved.body.previousOwner).toEqual({ userId: 'mallory', notified: true, inApp: true, emailed: false })
+    expect((await t.row()).ownership_transferred_at).not.toBeNull()
+  })
+
+  it('logs nothing for a refused hand-off or for an edit that is not a hand-off', async () => {
+    const t = await setup(answers({ member: false }))
+    expect((await t.transfer(t.admin, 'mia')).status).toBe(403)
+    const renamed = await t.h.call('PATCH', `/v1/team/workspaces/${t.id}`, { bearer: t.mallory, body: { title: 'Renamed' } })
+    expect(renamed.status).toBe(200)
+    expect(timingLines()).toEqual([])
+  })
+
+  it('sums a step that runs twice and still counts one that throws', async () => {
+    let now = 0
+    const timer = createStepTimer(() => now)
+    const take = (ms: number) => async () => void (now += ms)
+    await timer.step('membership', take(40))
+    await timer.step('membership', take(60))
+    await expect(
+      timer.step('suspend', async () => {
+        now += 500
+        throw new Error('stop failed')
+      })
+    ).rejects.toThrow('stop failed')
+    expect(timer.durations()).toEqual({ membership: 100, suspend: 500 })
+  })
+
+  it('reports the owner write as what is left of the registry edit', () => {
+    const line = JSON.parse(ownerTransferTimingLine({ patch: 21_000, membership: 300, suspend: 20_500, notify: 45 }, 21_100))
+    expect(line).toEqual({ event: 'owner_transfer_timing', totalMs: 21_100, membershipMs: 300, suspendMs: 20_500, writeMs: 200, notifyMs: 45 })
+  })
+})