diff --git a/cloud/apps/sandbox-control/src/index.ts b/cloud/apps/sandbox-control/src/index.ts index bba7a78b106..1e9c1e5ac8c 100644 --- a/cloud/apps/sandbox-control/src/index.ts +++ b/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> = 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 } } : {}) diff --git a/cloud/apps/sandbox-control/src/owner-transfer-timing.ts b/cloud/apps/sandbox-control/src/owner-transfer-timing.ts new file mode 100644 index 00000000000..530bba8b0a9 --- /dev/null +++ b/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(name: string, run: () => Promise): Promise + /** Milliseconds per step so far, in the order the steps first ran. */ + durations(): Record +} + +export function createStepTimer(clock: () => number): StepTimer { + const elapsed = new Map() + 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, 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])) + }) +} diff --git a/cloud/apps/sandbox-control/test/owner-transfer.test.ts b/cloud/apps/sandbox-control/test/owner-transfer.test.ts index 54d6dcc5d89..23506f674ea 100644 --- a/cloud/apps/sandbox-control/test/owner-transfer.test.ts +++ b/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) + + 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 }) + }) +})