fix(relay): commit the cell counter in one round trip; cells boot without the database (#25765)

* fix(relay): commit the cell counter in one round trip; cells boot without the DB Step 2 (option B) cell image: - One-round-trip counter commit at acquireActivity, releaseActivity and activateControl: the final counter UPDATE and COMMIT go as one simple-query message. Server errors mean COMMIT never ran (retry as today; 22012 = no row, rolled back and disambiguated outside the transaction); a lost connection is never retried. - Cells skip the schema apply and region backfill, so they listen while the database is down and turn ready on their first successful query. - G13: rehome target connection headroom folded into the existing NOWAIT UPDATE, excluding the host's own reservation by key. - fixLevel on every runtime metrics line, plus declared (not applied) cell fix-level metrics and alert. - Per-desktop drain disconnect-gap measurement from existing log lines. - Census test that fails on floating database promises; fixes two shutdown sites. Lock-wait sample keeps the combined role. * fix(relay): make the outdated-image alert creatable: one PromQL condition, 1 h lookback, fixed floor A PromQL condition must be the only condition in its policy, and alerts on log-based metrics may look back at most 25 h. Replace the 6-day/7-day design with relay_cell_min_fix_level (tfvars, raised by a targeted apply after each wave) and one query: a serving cell below the floor or reporting no level, sustained 6 h. Drops the separate without-level metric. * fix(relay): review fixes: gap-script ordering, wider promise census, fused-path guard, row-busy as scheduled - Drain gap script: sort closes by time (gcloud exports newest first) and refuse an invalid drain start. - Census: any floating promise in relay src, including callback-discarded and never-read ones, with a reviewed never-rejects list. - Test the fused counter commit through the store the server builds, so a wrapper that stops forwarding commitWithFinal fails CI. - Same-cap shadow gate: a row-busy refusal (the host's own release still holds its row) is a scheduled 503, like an own early retry. No client change. * test(relay): judge drain redials by no host refused twice, not a refusal count The row-busy count tracks how many releases are still in flight at the dial (80 of 180 every run at 1 s, against a bar of 90). What matters is that the release has finished by the next dial: assert no host is refused twice, keep the time-to-placed p95 bound. * fix(relay): cap row-busy as scheduled at the drain-return admissions; bound the gap script's window Shadow gate: a row-busy refusal of a drained host follows its drain-return lane admission, so per minute only that many (plus a rounding margin of 2) are scheduled; the rest stay non-drain, so row contention the drain does not explain still fails the budget. Gap script: --drain-ended-at excludes the new container's closes after the roll; later grants still close a gap.
2026-10-07 00:02:29 +00:00 · 2026-10-06 00:53:51 -04:00
parent fff8718c76
commit 54ded3bc18
27 changed files with 1397 additions and 37 deletions
@@ -0,0 +1,161 @@
+import { readFileSync } from 'node:fs'
+import { pathToFileURL } from 'node:url'
+
+// Per-desktop disconnect gap for one drained cell, read from log lines that already ship:
+// the source cell's `control closed` line and the director's reconnect `assignment granted`
+// line (drains send `reconnect: true`, so every drained desktop's grant carries `hinted=true`).
+// Read-only: the operator exports both logs; this file never queries anything.
+
+const CLOSE = /^\[orca-relay\] control closed host=(\S+) .*?\bsplices=(\d+) .*?\bcode=(\d+) reason=("(?:[^"\\]|\\.)*")/
+const GRANT = /^\[orca-relay\] assignment granted lane=\S+ hinted=true host=(\S+) cell=(\S+)$/
+// The cell's own drain close; a desktop closed this way had not moved yet, idle or not.
+const DRAIN_CLOSE_REASON = 'resolve configured director'
+
+function entryText(entry) {
+  if (typeof entry.textPayload === 'string') return entry.textPayload
+  if (typeof entry.jsonPayload?.message === 'string') return entry.jsonPayload.message
+  return null
+}
+
+function entryTime(entry) {
+  const at = Date.parse(entry.timestamp)
+  if (!Number.isFinite(at)) throw new Error('log entry has no timestamp')
+  return at
+}
+
+export function readDrainCloses(entries) {
+  const closes = []
+  for (const entry of entries) {
+    const match = CLOSE.exec(entryText(entry) ?? '')
+    if (!match) continue
+    closes.push({
+      host: match[1],
+      splices: Number(match[2]),
+      code: Number(match[3]),
+      reason: JSON.parse(match[4]),
+      at: entryTime(entry)
+    })
+  }
+  // gcloud exports newest first; the measurement needs each host's earliest close.
+  return closes.sort((left, right) => left.at - right.at)
+}
+
+export function readReconnectGrants(entries) {
+  const grants = []
+  for (const entry of entries) {
+    const match = GRANT.exec(entryText(entry) ?? '')
+    if (match) grants.push({ host: match[1], cellId: match[2], at: entryTime(entry) })
+  }
+  return grants.sort((left, right) => left.at - right.at)
+}
+
+function percentile(sorted, fraction) {
+  if (sorted.length === 0) return null
+  return sorted[Math.min(sorted.length - 1, Math.ceil(fraction * sorted.length) - 1)]
+}
+
+function summary(values) {
+  const sorted = [...values].sort((left, right) => left - right)
+  return {
+    count: sorted.length,
+    p50Ms: percentile(sorted, 0.5),
+    p95Ms: percentile(sorted, 0.95),
+    maxMs: sorted.at(-1) ?? null
+  }
+}
+
+// `controlsAtDrainStart` is the denominator: hosts the cell held when the drain began,
+// read from its runtime metrics line, so a desktop that never logged a close still counts.
+// `drainEndedAt` closes the window: after it the rolled cell's new container serves new sessions,
+// and their closes are not part of the drain. Grants after it still count, as the gap's far end.
+export function measureDrainDisconnectGap({
+  sourceCellId,
+  drainStartedAt,
+  drainEndedAt,
+  controlsAtDrainStart,
+  closes,
+  grants,
+  cellRegions = {}
+}) {
+  if (!Number.isFinite(drainStartedAt)) throw new Error('drain start time is invalid')
+  if (!Number.isFinite(drainEndedAt) || drainEndedAt <= drainStartedAt) {
+    throw new Error('drain end time is invalid')
+  }
+  const sourceRegion = cellRegions[sourceCellId]
+  // First close per host after the drain began; later closes are the host's new sessions.
+  const firstClose = new Map()
+  for (const close of closes) {
+    if (close.at < drainStartedAt || close.at > drainEndedAt || firstClose.has(close.host)) continue
+    firstClose.set(close.host, close)
+  }
+  const grantsByHost = new Map()
+  for (const grant of grants) {
+    if (grant.at < drainStartedAt || grant.cellId === sourceCellId) continue
+    grantsByHost.set(grant.host, [...(grantsByHost.get(grant.host) ?? []), grant])
+  }
+  const cutOffGapsMs = []
+  const counts = { movedFirst: 0, cutOff: 0, cutOffUnresolved: 0, otherClose: 0 }
+  const leftRegion = []
+  let phoneSessionsDropped = 0
+  for (const close of firstClose.values()) {
+    phoneSessionsDropped += close.splices
+    const hostGrants = grantsByHost.get(close.host) ?? []
+    const first = hostGrants[0]
+    if (first && first.at <= close.at) counts.movedFirst += 1
+    else if (close.reason === DRAIN_CLOSE_REASON) {
+      if (first) {
+        counts.cutOff += 1
+        cutOffGapsMs.push(first.at - close.at)
+      } else counts.cutOffUnresolved += 1
+    } else counts.otherClose += 1
+    if (first && sourceRegion && cellRegions[first.cellId] && cellRegions[first.cellId] !== sourceRegion) {
+      const back = hostGrants.find(
+        (grant) => grant.at > first.at && cellRegions[grant.cellId] === sourceRegion
+      )
+      leftRegion.push(back ? back.at - first.at : null)
+    }
+  }
+  const returned = leftRegion.filter((value) => value !== null)
+  return {
+    sourceCellId,
+    controlsAtDrainStart,
+    closedHosts: firstClose.size,
+    // Below 1 means some drained desktops left no close line in the export; widen it.
+    closeCoverage: controlsAtDrainStart > 0 ? firstClose.size / controlsAtDrainStart : null,
+    ...counts,
+    // Lower bound until the target cells run an image that logs control activation.
+    cutOffGap: summary(cutOffGapsMs),
+    phoneSessionsDropped,
+    leftSourceRegion: leftRegion.length,
+    leftSourceRegionStillAway: leftRegion.length - returned.length,
+    timeUntilBack: summary(returned)
+  }
+}
+
+function argument(name) {
+  const index = process.argv.indexOf(`--${name}`)
+  return index === -1 ? undefined : process.argv[index + 1]
+}
+
+function required(name) {
+  const value = argument(name)
+  if (value === undefined) throw new Error(`--${name} is required`)
+  return value
+}
+
+function main() {
+  const readJson = (path) => JSON.parse(readFileSync(path, 'utf8'))
+  const cellRegionsPath = argument('cell-regions')
+  const result = measureDrainDisconnectGap({
+    sourceCellId: required('source-cell'),
+    drainStartedAt: Date.parse(required('drain-started-at')),
+    drainEndedAt: Date.parse(required('drain-ended-at')),
+    controlsAtDrainStart: Number(required('controls')),
+    closes: readDrainCloses(readJson(required('cell-log'))),
+    grants: readReconnectGrants(readJson(required('director-log'))),
+    cellRegions: cellRegionsPath ? readJson(cellRegionsPath) : {}
+  })
+  console.log(JSON.stringify(result, null, 2))
+}
+
+if (import.meta.url === pathToFileURL(process.argv[1] ?? '').href) main()
@@ -0,0 +1,158 @@
+import assert from 'node:assert/strict'
+import { describe, it } from 'node:test'
+import {
+  measureDrainDisconnectGap,
+  readDrainCloses,
+  readReconnectGrants
+} from './measure-relay-drain-disconnect-gap.mjs'
+
+const start = Date.parse('2026-10-06T10:00:00Z')
+const at = (seconds) => new Date(start + seconds * 1000).toISOString()
+
+function close(host, seconds, reason, splices = 0) {
+  return {
+    timestamp: at(seconds),
+    jsonPayload: {
+      message:
+        `[orca-relay] control closed host=${host} gen=3 state=closed ageMs=100 app="1.4.0"` +
+        ` splices=${splices} pending=0 code=4001 reason=${JSON.stringify(reason)}`
+    }
+  }
+}
+
+function grant(host, seconds, cellId) {
+  return {
+    timestamp: at(seconds),
+    textPayload: `[orca-relay] assignment granted lane=drain-return hinted=true host=${host} cell=${cellId}`
+  }
+}
+
+describe('drain disconnect gap', () => {
+  it('splits moved-first, cut-off and unresolved desktops and sums dropped phone sessions', () => {
+    const closes = readDrainCloses([
+      close('h-moved', 30, 'migration completed', 2),
+      close('h-cut', 300, 'resolve configured director', 1),
+      close('h-idle', 310, 'resolve configured director'),
+      close('h-lost', 320, 'resolve configured director'),
+      close('h-early', -5, 'resolve configured director'),
+      // A later close of the same host is its next session, not the drain.
+      close('h-cut', 900, 'resolve configured director', 7)
+    ])
+    const grants = readReconnectGrants([
+      grant('h-moved', 20, 'c2'),
+      grant('h-cut', 304, 'c2'),
+      grant('h-idle', 330, 'c3'),
+      grant('h-other', 5, 'c2'),
+      grant('h-cut', 290, 'c1')
+    ])
+    const result = measureDrainDisconnectGap({
+      sourceCellId: 'c1',
+      drainStartedAt: start,
+      drainEndedAt: start + 1_200_000,
+      controlsAtDrainStart: 5,
+      closes,
+      grants
+    })
+    assert.equal(result.closedHosts, 4)
+    assert.equal(result.closeCoverage, 0.8)
+    assert.equal(result.movedFirst, 1)
+    assert.equal(result.cutOff, 2)
+    assert.equal(result.cutOffUnresolved, 1)
+    assert.equal(result.otherClose, 0)
+    assert.deepEqual(result.cutOffGap, { count: 2, p50Ms: 4000, p95Ms: 20000, maxMs: 20000 })
+    assert.equal(result.phoneSessionsDropped, 3)
+  })
+
+  it('times desktops that left the source region until a grant brings them back', () => {
+    const result = measureDrainDisconnectGap({
+      sourceCellId: 'a1',
+      drainStartedAt: start,
+      drainEndedAt: start + 1_200_000,
+      controlsAtDrainStart: 2,
+      closes: readDrainCloses([
+        close('h-away', 100, 'resolve configured director'),
+        close('h-stuck', 100, 'resolve configured director')
+      ]),
+      grants: readReconnectGrants([
+        grant('h-away', 101, 'u1'),
+        grant('h-away', 3701, 'a2'),
+        grant('h-stuck', 102, 'u1')
+      ]),
+      cellRegions: { a1: 'asia-east2', a2: 'asia-east2', u1: 'us-central1' }
+    })
+    assert.equal(result.leftSourceRegion, 2)
+    assert.equal(result.leftSourceRegionStillAway, 1)
+    assert.equal(result.timeUntilBack.maxMs, 3_600_000)
+  })
+
+  it('keeps each host earliest close when the export is newest first', () => {
+    const result = measureDrainDisconnectGap({
+      sourceCellId: 'c1',
+      drainStartedAt: start,
+      drainEndedAt: start + 1_200_000,
+      controlsAtDrainStart: 1,
+      closes: readDrainCloses([
+        close('h', 300, 'resolve configured director'),
+        close('h', 60, 'resolve configured director', 3)
+      ]),
+      grants: readReconnectGrants([grant('h', 120, 'c2')])
+    })
+    assert.equal(result.movedFirst, 0)
+    assert.equal(result.cutOff, 1)
+    assert.deepEqual(result.cutOffGap, { count: 1, p50Ms: 60000, p95Ms: 60000, maxMs: 60000 })
+    assert.equal(result.phoneSessionsDropped, 3)
+  })
+
+  it('refuses an invalid drain start time', () => {
+    assert.throws(
+      () =>
+        measureDrainDisconnectGap({
+          sourceCellId: 'c1',
+          drainStartedAt: Date.parse('not a time'),
+          drainEndedAt: start,
+          controlsAtDrainStart: 1,
+          closes: [],
+          grants: []
+        }),
+      /drain start time is invalid/
+    )
+  })
+
+  it('leaves out closes after the drain ended and refuses a bad end time', () => {
+    const input = {
+      sourceCellId: 'c1',
+      drainStartedAt: start,
+      drainEndedAt: start + 600_000,
+      controlsAtDrainStart: 1,
+      closes: readDrainCloses([
+        close('h-drained', 100, 'resolve configured director'),
+        // The new container's session after the roll.
+        close('h-new', 700, '', 4)
+      ]),
+      grants: readReconnectGrants([grant('h-drained', 650, 'c2')])
+    }
+    const result = measureDrainDisconnectGap(input)
+    assert.equal(result.closedHosts, 1)
+    assert.equal(result.otherClose, 0)
+    assert.equal(result.phoneSessionsDropped, 0)
+    // A grant after the window still ends that host's gap.
+    assert.equal(result.cutOffGap.maxMs, 550_000)
+    for (const drainEndedAt of [Number.NaN, start]) {
+      assert.throws(
+        () => measureDrainDisconnectGap({ ...input, drainEndedAt }),
+        /drain end time is invalid/
+      )
+    }
+  })
+
+  it('ignores lines that are not the two it reads', () => {
+    assert.deepEqual(readDrainCloses([{ timestamp: at(0), textPayload: 'unrelated' }]), [])
+    assert.deepEqual(
+      readReconnectGrants([grant('h', 0, 'c1')].map((entry) => ({
+        ...entry,
+        textPayload: entry.textPayload.replace('hinted=true', 'hinted=false')
+      }))),
+      []
+    )
+  })
+})
@@ -178,6 +178,17 @@ function ownRetries(sample) {
  )
 }

+// A drained host whose redial beats its own release meets its own row. That host was admitted to
+// the drain-return lane first (the admission is counted before the assign that is refused), so
+// row-busy refusals up to that minute's drain-return admissions are scheduled. Anything beyond is
+// row contention the drain does not explain, and stays in the budget. The margin absorbs rounding
+// from splitting each 30 s sample across clock minutes.
+const ROW_BUSY_MARGIN_PER_MINUTE = 2
+
+function rowBusy(sample) {
+  return sample.assign503sByCauseDelta?.relay_assignment_row_busy ?? 0
+}
+
 /**
 * The director's scheduled 503s per clock minute, from its runtime-metrics samples: drain-return
 * deferrals and answers to a host's own early retry, plus the re-placements. Each sample's count is
@@ -187,6 +198,7 @@ function ownRetries(sample) {
 export function drainReturnByMinute(reads, limit) {
  const deferrals = new Map()
  const retries = new Map()
+  const busy = new Map()
  const assignments = new Map()
  let retryAfterSecondsMax = 0
  let truncated = false
@@ -209,6 +221,7 @@ export function drainReturnByMinute(reads, limit) {
      const endedAt = Date.parse(sample.timestamp)
      charge(deferrals, endedAt, sample.drainReturnDeferralsDelta ?? 0)
      charge(retries, endedAt, ownRetries(sample))
+      charge(busy, endedAt, rowBusy(sample))
      charge(assignments, endedAt, sample.drainReturnAssignmentsDelta ?? 0)
      retryAfterSecondsMax = Math.max(
        retryAfterSecondsMax,
@@ -217,6 +230,12 @@ export function drainReturnByMinute(reads, limit) {
    }
  }
  const sum = (map) => Math.round([...map.values()].reduce((total, count) => total + count, 0))
+  let rowBusyBeyondDrain = 0
+  for (const [minute, count] of busy) {
+    const scheduled = Math.min(count, (assignments.get(minute) ?? 0) + ROW_BUSY_MARGIN_PER_MINUTE)
+    rowBusyBeyondDrain += count - scheduled
+    retries.set(minute, (retries.get(minute) ?? 0) + scheduled)
+  }
  return {
    deferralsPerMinute: Object.fromEntries(deferrals),
    ownRetriesPerMinute: Object.fromEntries(retries),
@@ -224,6 +243,7 @@ export function drainReturnByMinute(reads, limit) {
    deferralsPeakPerMinute: Math.round(Math.max(0, ...deferrals.values())),
    assignmentsTotal: sum(assignments),
    assignmentsPeakPerMinute: Math.round(Math.max(0, ...assignments.values())),
+    rowBusyBeyondDrainTotal: Math.round(rowBusyBeyondDrain),
    retryAfterSecondsMax,
    truncated
  }
@@ -199,7 +199,8 @@ const DIRECTOR_DRAIN_FIELDS = [
  'placementRejectionsByReasonDelta',
  'drainReturnDeferralsDelta',
  'drainReturnAssignmentsDelta',
-  'drainReturnRetryAfterSecondsMax'
+  'drainReturnRetryAfterSecondsMax',
+  'assign503sByCauseDelta'
 ]

 // Five instances at one sample per 30 s is ~100 per 10-min sub-window; this many is truncation.
@@ -611,6 +611,44 @@ function director503s(minute, count) {
  return [{ minute503: minute, count }]
 }

+test('row-busy 503s are scheduled only up to the drain-return admissions they ride on', () => {
+  const drain = drainReturnByMinute([{
+    failed: false,
+    samples: [{
+      timestamp: '2026-10-05T20:01:00Z',
+      drainReturnAssignmentsDelta: 10,
+      assign503sByCauseDelta: { relay_assignment_row_busy: 8, 'placement-lane': 5 }
+    }]
+  }], 1000)
+  assert.deepEqual(drain.ownRetriesPerMinute, { '2026-10-05T20:00': 8 })
+  assert.equal(drain.rowBusyBeyondDrainTotal, 0)
+  const split = withoutDrainDeferrals(
+    { perMinute: { '2026-10-05T20:00': 13 } },
+    drain,
+    ['2026-10-05T20:00']
+  )
+  // The placement-lane refusals stay: only the row-busy ones were scheduled.
+  assert.deepEqual(split.series, [5])
+})
+
+test('row-busy 503s beyond the drain stay in the non-drain budget and fail it', () => {
+  const minutes = Array.from({ length: 10 }, (_, index) => `2026-10-05T20:0${index}`)
+  // No drain in the background, and 3 drain-return admissions a minute in the window against 60
+  // row-busy refusals: row contention the drain does not explain.
+  const samples = minutes.map((minute, index) => ({
+    timestamp: new Date(Date.parse(`${minute}:30Z`) + 30_000).toISOString(),
+    drainReturnAssignmentsDelta: index < 5 ? 0 : 3,
+    assign503sByCauseDelta: { relay_assignment_row_busy: index < 5 ? 0 : 60 }
+  }))
+  const drain = drainReturnByMinute([{ failed: false, samples }], 1000)
+  assert.equal(drain.rowBusyBeyondDrainTotal, 5 * (60 - 3 - 2))
+  const perMinute = Object.fromEntries(minutes.map((minute, index) => [minute, index < 5 ? 2 : 60]))
+  const background = backgroundOf(withoutDrainDeferrals({ perMinute }, drain, minutes.slice(0, 5)))
+  const observed = withoutDrainDeferrals({ perMinute }, drain, minutes.slice(5))
+  assert.deepEqual(observed.series, [55, 55, 55, 55, 55])
+  assert.equal(judgeNonDrain503Budget({ observed, background }).status, 'would-block')
+})
+
 test('scheduled 503s come out of the count, split across the minutes they cover', () => {
  const drain = drainReturnByMinute([{
    failed: false,