mirror of
https://github.com/stablyai/orca.git
synced 2026-10-30 16:47:34 +00:00
fix(relay-ops): make each reserve-watch sample one Cloud Logging read (#31619)
* fix(relay-ops): make each reserve-watch sample one Cloud Logging read The project allows 60 ListLogEntries a minute shared by every watch and tool. Each watch sample made four to six reads (two director runtime-metrics sub-windows, the ledger summaries, the seat-behind-row lines, the cell's phone metrics, and since #31484 the 503 request log), so on 10-21 18:39Z twelve watches drew 429s until c21 and c22 tripped unverifiable. A sample now sends its queries as one OR filter and splits the lines back client-side. The per-instance 503 split counts each director's own logged /v1/assign 503s from the runtime metrics it already reads, with the rest of the fleet's count as one unattributed instance, instead of reading the request log. * fix(relay-ops): judge unattributed 503s on their 3-minute sum against the whole fleet line * docs(relay-ops): state that an instance that stops logging trips the unattributed rule
This commit is contained in:
Jinwoo Hong
@@ -0,0 +1,151 @@
|
||||
{
|
||||
"comment": "Production 2026-10-21 07:44-07:58Z, read-only: Cloud Run director 503s per minute (request_count, code 503) and every director runtime-metrics line, instance ids replaced. d5 stalled on its database 07:55-07:57.",
|
||||
"fleet503PerMinute": {"2026-10-21T07:44":6,"2026-10-21T07:45":7,"2026-10-21T07:46":5,"2026-10-21T07:47":55,"2026-10-21T07:48":11,"2026-10-21T07:49":10,"2026-10-21T07:50":12,"2026-10-21T07:51":4,"2026-10-21T07:52":6,"2026-10-21T07:53":8,"2026-10-21T07:54":6,"2026-10-21T07:55":57,"2026-10-21T07:56":173,"2026-10-21T07:57":45},
|
||||
"directorMetricsLines": [
|
||||
{"timestamp":"2026-10-21T07:44:05.179655Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:44:08.062180Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-in-flight":1,"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":3}},
|
||||
{"timestamp":"2026-10-21T07:44:13.822472Z","instance":"d3","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"relay_assignment_row_busy":1}},
|
||||
{"timestamp":"2026-10-21T07:44:14.159472Z","instance":"d4","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:44:25.765825Z","instance":"d5","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:44:35.181579Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:44:38.060162Z","instance":"d2","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:44:43.823368Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:44:44.158999Z","instance":"d4","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:44:55.766172Z","instance":"d5","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:45:05.180654Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:45:08.060467Z","instance":"d2","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:45:13.824498Z","instance":"d3","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:45:14.159451Z","instance":"d4","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:45:25.764958Z","instance":"d5","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"placementRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:45:35.181560Z","instance":"d1","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:45:38.062560Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:45:43.831975Z","instance":"d3","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:45:44.160118Z","instance":"d4","placementRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:45:55.767508Z","instance":"d5","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:46:05.181410Z","instance":"d1","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:46:08.061944Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":3},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":3}},
|
||||
{"timestamp":"2026-10-21T07:46:13.824904Z","instance":"d3","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:46:14.160287Z","instance":"d4","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:46:25.766494Z","instance":"d5","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:46:35.180987Z","instance":"d1","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:46:38.061343Z","instance":"d2","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:46:43.824785Z","instance":"d3","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:46:44.161722Z","instance":"d4","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:46:55.768452Z","instance":"d5","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:47:05.182855Z","instance":"d1","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:47:08.066053Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:47:13.825495Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":3},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":3}},
|
||||
{"timestamp":"2026-10-21T07:47:14.161928Z","instance":"d4","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"relay_assignment_row_busy":1,"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:47:25.767488Z","instance":"d5","stickyRejectionsByReasonDelta":{"host-rate-limited":4},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":4}},
|
||||
{"timestamp":"2026-10-21T07:47:35.183676Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:47:38.064515Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:47:43.827753Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-in-flight":1,"host-rate-limited":1,"wait-timeout":9},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":11}},
|
||||
{"timestamp":"2026-10-21T07:47:44.161502Z","instance":"d4","stickyRejectionsByReasonDelta":{"host-in-flight":1,"wait-timeout":7},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":8}},
|
||||
{"timestamp":"2026-10-21T07:47:55.769396Z","instance":"d5","stickyRejectionsByReasonDelta":{"wait-timeout":9},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":9}},
|
||||
{"timestamp":"2026-10-21T07:48:05.184152Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":1,"wait-timeout":10},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":11}},
|
||||
{"timestamp":"2026-10-21T07:48:08.069122Z","instance":"d2","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:48:13.826317Z","instance":"d3","stickyRejectionsByReasonDelta":{"wait-timeout":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:48:14.162388Z","instance":"d4","stickyRejectionsByReasonDelta":{"host-rate-limited":1,"wait-timeout":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:48:25.770092Z","instance":"d5","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:48:35.183997Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:48:38.072360Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:48:43.826028Z","instance":"d3","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:48:44.162106Z","instance":"d4","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:48:55.769497Z","instance":"d5","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:49:05.183794Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:49:08.070369Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:49:13.826477Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:49:14.162921Z","instance":"d4","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"relay_assignment_row_busy":1,"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:49:25.771495Z","instance":"d5","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:49:35.183472Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:49:38.072836Z","instance":"d2","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:49:43.826252Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:49:44.163115Z","instance":"d4","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:49:55.769846Z","instance":"d5","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:50:05.184917Z","instance":"d1","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:50:08.072488Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:50:13.827130Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":3},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":3}},
|
||||
{"timestamp":"2026-10-21T07:50:14.163400Z","instance":"d4","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:50:25.769945Z","instance":"d5","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:50:35.184832Z","instance":"d1","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:50:38.075017Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:50:43.827931Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:50:44.164604Z","instance":"d4","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:50:55.772344Z","instance":"d5","stickyRejectionsByReasonDelta":{"host-rate-limited":3},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":3}},
|
||||
{"timestamp":"2026-10-21T07:51:05.184087Z","instance":"d1","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"relay_assignment_row_busy":1}},
|
||||
{"timestamp":"2026-10-21T07:51:08.074651Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:51:13.829283Z","instance":"d3","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:51:14.165434Z","instance":"d4","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:51:25.769048Z","instance":"d5","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:51:35.183654Z","instance":"d1","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:51:38.073759Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:51:43.829359Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:51:44.166698Z","instance":"d4","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:51:55.770350Z","instance":"d5","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:52:05.184492Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:52:08.076738Z","instance":"d2","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:52:13.830929Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:52:14.167578Z","instance":"d4","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:52:25.770188Z","instance":"d5","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:52:35.185557Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:52:38.073056Z","instance":"d2","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:52:43.830612Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:52:44.170744Z","instance":"d4","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:52:55.770072Z","instance":"d5","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:53:05.185184Z","instance":"d1","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:53:08.073799Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:53:13.831126Z","instance":"d3","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:53:14.168954Z","instance":"d4","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:53:25.771642Z","instance":"d5","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:53:35.185375Z","instance":"d1","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:53:38.073871Z","instance":"d2","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:53:43.832470Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:53:44.169801Z","instance":"d4","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:53:55.772778Z","instance":"d5","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:54:05.184779Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:54:08.075259Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:54:13.831013Z","instance":"d3","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:54:14.170568Z","instance":"d4","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:54:25.772879Z","instance":"d5","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:54:35.185747Z","instance":"d1","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:54:38.074242Z","instance":"d2","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:54:43.832593Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:54:44.170223Z","instance":"d4","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:54:55.772796Z","instance":"d5","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:55:05.186732Z","instance":"d1","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:55:08.074506Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:55:13.832282Z","instance":"d3","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:55:14.170168Z","instance":"d4","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:55:25.773007Z","instance":"d5","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:55:35.186844Z","instance":"d1","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:55:38.073584Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"placementRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:55:43.832666Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:55:44.171703Z","instance":"d4","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:55:55.774228Z","instance":"d5","stickyRejectionsByReasonDelta":{"wait-timeout":21},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":21}},
|
||||
{"timestamp":"2026-10-21T07:56:05.186316Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":4},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":4}},
|
||||
{"timestamp":"2026-10-21T07:56:08.074683Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:56:13.836910Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:56:14.171278Z","instance":"d4","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:56:25.774220Z","instance":"d5","stickyRejectionsByReasonDelta":{"wait-timeout":132},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":132}},
|
||||
{"timestamp":"2026-10-21T07:56:35.187168Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:56:38.075749Z","instance":"d2","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:56:43.834101Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":4},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":4}},
|
||||
{"timestamp":"2026-10-21T07:56:44.171918Z","instance":"d4","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:56:55.775731Z","instance":"d5","stickyRejectionsByReasonDelta":{"host-rate-limited":1,"wait-timeout":56},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":57}},
|
||||
{"timestamp":"2026-10-21T07:57:05.187236Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:57:08.074119Z","instance":"d2","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:57:13.833738Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:57:14.171816Z","instance":"d4","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:57:25.775798Z","instance":"d5","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:57:35.187493Z","instance":"d1","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}},
|
||||
{"timestamp":"2026-10-21T07:57:38.075303Z","instance":"d2","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:57:43.833226Z","instance":"d3","stickyRejectionsByReasonDelta":{"host-rate-limited":2},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":2}},
|
||||
{"timestamp":"2026-10-21T07:57:44.170780Z","instance":"d4","drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0},
|
||||
{"timestamp":"2026-10-21T07:57:55.775393Z","instance":"d5","stickyRejectionsByReasonDelta":{"wait-timeout":5},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":5}},
|
||||
{"timestamp":"2026-10-21T07:58:05.187113Z","instance":"d1","stickyRejectionsByReasonDelta":{"wait-timeout":9},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":9}},
|
||||
{"timestamp":"2026-10-21T07:58:08.073793Z","instance":"d2","stickyRejectionsByReasonDelta":{"host-rate-limited":1,"wait-timeout":3},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":4}},
|
||||
{"timestamp":"2026-10-21T07:58:13.849059Z","instance":"d3","stickyRejectionsByReasonDelta":{"wait-timeout":11},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":11}},
|
||||
{"timestamp":"2026-10-21T07:58:14.171116Z","instance":"d4","stickyRejectionsByReasonDelta":{"wait-timeout":13},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":13}},
|
||||
{"timestamp":"2026-10-21T07:58:25.776011Z","instance":"d5","stickyRejectionsByReasonDelta":{"host-rate-limited":1},"drainReturnDeferralsDelta":0,"drainReturnAssignmentsDelta":0,"assign503sByCauseDelta":{"sticky-lane":1}}
|
||||
]
|
||||
}
|
||||
@@ -39,6 +39,14 @@ export const RESERVE_WATCH_RULES = {
|
||||
reserveApplyWaitMs: 10 * MINUTE_MS
|
||||
}
|
||||
|
||||
// The fleet's non-drain 503s no instance's own lines account for. Unclamped per minute: the fleet
|
||||
// buckets by request minute and an instance's lines by 30 s, so a minute carries that skew and
|
||||
// only the sum over the judged minutes is judged, against the whole fleet line: no one
|
||||
// instance's stall explains it then. Its largest 3-minute sum in 10-20/21 was 38, against 90. An
|
||||
// instance answering 503s without logging its lines lands here and trips on purpose: a director
|
||||
// that stops logging is not the database stall the split lets through (10-21 07:55Z kept logging).
|
||||
export const UNATTRIBUTED_503S = 'unattributed'
|
||||
|
||||
// Precedence: the first tripped rule names the verdict, so exact signals come before proxies. The
|
||||
// sample line's `rules` keys follow this order too.
|
||||
export const RULE_NAMES = ['deadMan', 'overrun', 'director503', 'duplicateSeat', 'hostDrop', 'ledgerDrift']
|
||||
@@ -238,10 +246,15 @@ function judgeDirector503(read, state, at) {
|
||||
const directors = Math.min(...recent.map((minute) => read.instances.directors?.[minute]))
|
||||
if (!Number.isInteger(directors)) return unverifiable(`no director instance count for ${recent.join(', ')}`)
|
||||
const instanceAbove = above / Math.max(directors, instances.minOver)
|
||||
const over = Object.entries(read.instances.perMinute)
|
||||
const { [UNATTRIBUTED_503S]: rest = {}, ...byInstance } = read.instances.perMinute
|
||||
const unattributed = recent.reduce((sum, minute) => sum + (rest[minute] ?? 0), 0)
|
||||
const over = Object.entries(byInstance)
|
||||
.filter(([, byMinute]) => recent.every((minute) => (byMinute[minute] ?? 0) > instanceAbove))
|
||||
.map(([instance]) => instance)
|
||||
const split = { ...detail, instanceAbove, instancesOver: over.length }
|
||||
const split = { ...detail, instanceAbove, instancesOver: over.length, unattributed }
|
||||
if (unattributed > above * recent.length) {
|
||||
return trip(`director 503s above ${above}/min ${sustained}, ${unattributed} of them no director instance logged`, split)
|
||||
}
|
||||
if (over.length >= instances.minOver) {
|
||||
return trip(`director 503s above ${above}/min ${sustained}, ${over.length} instances each above ${instanceAbove}/min`, split)
|
||||
}
|
||||
|
||||
@@ -202,6 +202,7 @@ export function drainReturnByMinute(reads, limit) {
|
||||
const retries = new Map()
|
||||
const busy = new Map()
|
||||
const assignments = new Map()
|
||||
const assign503s = new Map()
|
||||
let retryAfterSecondsMax = 0
|
||||
let truncated = false
|
||||
const charge = (map, endedAt, count) => {
|
||||
@@ -225,6 +226,7 @@ export function drainReturnByMinute(reads, limit) {
|
||||
charge(retries, endedAt, ownRetries(sample))
|
||||
charge(busy, endedAt, rowBusy(sample))
|
||||
charge(assignments, endedAt, sample.drainReturnAssignmentsDelta ?? 0)
|
||||
charge(assign503s, endedAt, Object.values(sample.assign503sByCauseDelta ?? {}).reduce((sum, count) => sum + count, 0))
|
||||
retryAfterSecondsMax = Math.max(
|
||||
retryAfterSecondsMax,
|
||||
sample.drainReturnRetryAfterSecondsMax ?? 0
|
||||
@@ -241,6 +243,8 @@ export function drainReturnByMinute(reads, limit) {
|
||||
return {
|
||||
deferralsPerMinute: Object.fromEntries(deferrals),
|
||||
ownRetriesPerMinute: Object.fromEntries(retries),
|
||||
// Every /v1/assign 503 the director logged, scheduled or not: the same count by instance.
|
||||
assign503sPerMinute: Object.fromEntries(assign503s),
|
||||
deferralsTotal: sum(deferrals),
|
||||
deferralsPeakPerMinute: Math.round(Math.max(0, ...deferrals.values())),
|
||||
assignmentsTotal: sum(assignments),
|
||||
|
||||
@@ -222,7 +222,7 @@ export async function readDirectorRequestsByCodePerMinute(reader, { config, span
|
||||
// textPayload filter matches nothing here and returns zero without saying so.
|
||||
const CELL_LOG_SCOPE = 'resource.type="gce_instance" AND logName:"cos_containers"'
|
||||
|
||||
const DIRECTOR_DRAIN_FIELDS = [
|
||||
export const DIRECTOR_DRAIN_FIELDS = [
|
||||
'stickyRejectionsByReasonDelta',
|
||||
'placementRejectionsByReasonDelta',
|
||||
'drainReturnDeferralsDelta',
|
||||
@@ -234,6 +234,12 @@ const DIRECTOR_DRAIN_FIELDS = [
|
||||
// Five instances at one sample per 30 s is ~100 per 10-min sub-window; this many is truncation.
|
||||
export const DIRECTOR_METRICS_LIMIT = 1000
|
||||
|
||||
export const directorMetricsSample = (entry) => ({
|
||||
timestamp: entry.timestamp,
|
||||
instanceId: entry.labels?.instanceId,
|
||||
...entry.jsonPayload
|
||||
})
|
||||
|
||||
export async function readDirectorDrainReturn(reader, { config, window }) {
|
||||
const projection = `json(timestamp,labels.instanceId,${DIRECTOR_DRAIN_FIELDS
|
||||
.map((field) => `jsonPayload.${field}`)
|
||||
@@ -250,11 +256,7 @@ export async function readDirectorDrainReturn(reader, { config, window }) {
|
||||
})
|
||||
reads.push({
|
||||
failed: read.failed,
|
||||
samples: read.entries.map((entry) => ({
|
||||
timestamp: entry.timestamp,
|
||||
instanceId: entry.labels?.instanceId,
|
||||
...entry.jsonPayload
|
||||
})),
|
||||
samples: read.entries.map(directorMetricsSample),
|
||||
minSamples: Math.floor(
|
||||
(subWindow.endedAt.getTime() - subWindow.startedAt.getTime()) / DIRECTOR_METRICS_INTERVAL_MS
|
||||
)
|
||||
|
||||
@@ -22,7 +22,9 @@ import {
|
||||
WRITE_CONFIRMATION
|
||||
} from './operate-relay-cell-flags.mjs'
|
||||
import {
|
||||
DIRECTOR_DRAIN_FIELDS,
|
||||
DIRECTOR_METRICS_LIMIT,
|
||||
directorMetricsSample,
|
||||
readDirectorDrainReturn,
|
||||
readDirectorRequestsByCodePerMinute,
|
||||
readLogEntries
|
||||
@@ -43,7 +45,8 @@ import {
|
||||
measuredPhoneBackground,
|
||||
phoneSinceOf,
|
||||
PHONE_WATCH_RULES,
|
||||
RESERVE_WATCH_RULES
|
||||
RESERVE_WATCH_RULES,
|
||||
UNATTRIBUTED_503S
|
||||
} from './relay-reserve-watch-rules.mjs'
|
||||
|
||||
const execFileAsync = promisify(execFile)
|
||||
@@ -161,7 +164,7 @@ const failed503Read = (error) => ({ ok: false, error, perMinute: {}, minutes: []
|
||||
// point for (the director always serves something, so no front at all is no evidence); a minute
|
||||
// with no metrics line from any instance is `unmetered`, since subtracting nothing there is a guess.
|
||||
// Coverage is any instance, not each: one instance's missing lines under-subtract, biased to a trip.
|
||||
export async function readDirector503Minutes(reader, { projectId, directorService, endedAt, minutes }) {
|
||||
export async function readDirector503Minutes(reader, { projectId, directorService, endedAt, minutes, metrics: logged }) {
|
||||
const span = { startedAt: new Date(endedAt - minutes * MINUTE_MS), endedAt: new Date(endedAt) }
|
||||
const config = { projectId, directorService }
|
||||
let read
|
||||
@@ -172,11 +175,10 @@ export async function readDirector503Minutes(reader, { projectId, directorServic
|
||||
return failed503Read(`director 503 metric unreadable: ${error instanceof Error ? error.message : error}`)
|
||||
}
|
||||
if (read.failed) return failed503Read('director 503 metric read failed')
|
||||
// A line covers the 30 s before it, so the last minute's tail is in the next minute's lines.
|
||||
const metrics = await readDirectorDrainReturn(reader, {
|
||||
config,
|
||||
window: { startedAt: span.startedAt, endedAt: new Date(endedAt + DIRECTOR_METRICS_INTERVAL_MS) }
|
||||
})
|
||||
// The sample's combined log read passes these in; a background read takes its own.
|
||||
const metrics = logged ?? (await readDirectorDrainReturn(reader, { config, window: directorMetricsWindow(endedAt, minutes) }))
|
||||
const failedPart = metrics.find((part) => part.failed && part.error)
|
||||
if (failedPart) return failed503Read(`director runtime metrics read failed: ${failedPart.error}`)
|
||||
const lineTimes = metrics.flatMap((part) => part.samples.map((sample) => Date.parse(sample.timestamp)))
|
||||
if (lineTimes.some((at) => !Number.isFinite(at))) return failed503Read('director runtime metrics line with an unparseable timestamp')
|
||||
const scheduled = drainReturnByMinute(metrics, DIRECTOR_METRICS_LIMIT)
|
||||
@@ -191,55 +193,35 @@ export async function readDirector503Minutes(reader, { projectId, directorServic
|
||||
minutes: keys,
|
||||
publishedThrough: published.at(-1) ?? null,
|
||||
unmetered: keys.filter((minute) => !metered.has(minute)),
|
||||
instances: await readDirector503ByInstance(reader, { projectId, directorService, span, metrics, keys })
|
||||
instances: director503ByInstance(metrics, keys, nonDrain.series)
|
||||
}
|
||||
}
|
||||
|
||||
// Raw 503 request-log lines in one 10-minute read; 10-20/21 peaked at 1,681. Past it only a
|
||||
// brownout over the broad line, which needs no split.
|
||||
export const DIRECTOR_503_LOG_LIMIT = 5_000
|
||||
// Platform 503s answered by no instance (none in 10-20/21) count as one instance of their own.
|
||||
const NO_INSTANCE = 'no-instance'
|
||||
// A line covers the 30 s before it, so the last minute's tail is in the next minute's lines.
|
||||
const directorMetricsWindow = (endedAt, minutes) => ({
|
||||
startedAt: new Date(endedAt - minutes * MINUTE_MS),
|
||||
endedAt: new Date(endedAt + DIRECTOR_METRICS_INTERVAL_MS)
|
||||
})
|
||||
|
||||
// The same non-drain measure per director instance: the metric names no instance, so the 503s
|
||||
// come from Cloud Run's request log, less each instance's own scheduled 503s. `directors` is, per
|
||||
// minute, how many instances logged a runtime-metrics line ending in it.
|
||||
async function readDirector503ByInstance(reader, { projectId, directorService, span, metrics, keys }) {
|
||||
const read = await readLogEntries(reader, {
|
||||
filter: [
|
||||
'resource.type="cloud_run_revision"',
|
||||
`resource.labels.service_name="${directorService}"`,
|
||||
`logName="projects/${projectId}/logs/run.googleapis.com%2Frequests"`,
|
||||
'httpRequest.status=503',
|
||||
`timestamp>="${span.startedAt.toISOString()}"`,
|
||||
`timestamp<"${span.endedAt.toISOString()}"`
|
||||
].join(' AND '),
|
||||
projection: 'json(timestamp,labels.instanceId)',
|
||||
limit: DIRECTOR_503_LOG_LIMIT
|
||||
})
|
||||
if (read.failed) return failedRead(`director 503 request log read failed: ${read.error}`)
|
||||
if (read.entries.length >= DIRECTOR_503_LOG_LIMIT) return failedRead('director 503 request log read truncated')
|
||||
const raw = new Map()
|
||||
for (const entry of read.entries) {
|
||||
const at = Date.parse(entry.timestamp)
|
||||
if (!Number.isFinite(at)) return failedRead('director 503 request log line with an unparseable timestamp')
|
||||
const instance = entry.labels?.instanceId || NO_INSTANCE
|
||||
const perMinute = raw.get(instance) ?? {}
|
||||
perMinute[minuteKey(at)] = (perMinute[minuteKey(at)] ?? 0) + 1
|
||||
raw.set(instance, perMinute)
|
||||
}
|
||||
// The same non-drain measure per director instance, from each instance's own runtime-metrics
|
||||
// counts of the /v1/assign 503s it answered, less its own scheduled ones. 10-21 07:55Z read 40,
|
||||
// 169, 5 on the stalled instance this way, against 54, 155, 5 in Cloud Run's request log.
|
||||
// `directors` is, per minute, how many instances logged a line ending in it.
|
||||
function director503ByInstance(metrics, keys, fleet) {
|
||||
const samples = metrics.flatMap((part) => part.samples)
|
||||
const perInstance = {}
|
||||
for (const [instance, perMinute] of raw) {
|
||||
// Coverage is checked fleet-wide above; an instance with no lines under-subtracts, toward a trip.
|
||||
const own = drainReturnByMinute(
|
||||
metrics.map((part) => ({ samples: part.samples.filter((sample) => sample.instanceId === instance) })),
|
||||
DIRECTOR_METRICS_LIMIT
|
||||
)
|
||||
const { series } = withoutDrainDeferrals({ perMinute }, own, keys)
|
||||
for (const instance of new Set(samples.map((sample) => sample.instanceId).filter(Boolean))) {
|
||||
const own = drainReturnByMinute([{ samples: samples.filter((sample) => sample.instanceId === instance) }], DIRECTOR_METRICS_LIMIT)
|
||||
const { series } = withoutDrainDeferrals({ perMinute: own.assign503sPerMinute }, own, keys)
|
||||
perInstance[instance] = Object.fromEntries(keys.map((minute, index) => [minute, series[index]]))
|
||||
}
|
||||
// Cloud Run's own 503s, or a route the director does not count; an instance that stopped logging
|
||||
// lands here too.
|
||||
perInstance[UNATTRIBUTED_503S] = Object.fromEntries(
|
||||
keys.map((minute, index) => [minute, fleet[index] - Object.values(perInstance).reduce((sum, byMinute) => sum + (byMinute[minute] ?? 0), 0)])
|
||||
)
|
||||
const logged = new Map(keys.map((minute) => [minute, new Set()]))
|
||||
for (const sample of metrics.flatMap((part) => part.samples)) {
|
||||
for (const sample of samples) {
|
||||
if (sample.instanceId) logged.get(minuteKey(Date.parse(sample.timestamp) - 1))?.add(sample.instanceId)
|
||||
}
|
||||
const directors = Object.fromEntries([...logged].map(([minute, instances]) => [minute, instances.size]))
|
||||
@@ -253,22 +235,28 @@ const sumOf = (counts) => Object.values(counts ?? {}).reduce((sum, count) => sum
|
||||
// The cell's own runtime metrics lines (one per 30 s) for the `minutes` whole minutes ending at
|
||||
// `endedAt`, per minute: what the phone rules judge. A line counts toward the minute it ends in;
|
||||
// a minute no line covers is `unmetered`, never zero.
|
||||
export async function readCellPhoneMinutes(reader, { cellId, endedAt, minutes }) {
|
||||
const span = { startedAt: new Date(endedAt - minutes * MINUTE_MS), endedAt: new Date(endedAt) }
|
||||
const read = await readLogEntries(reader, {
|
||||
function cellPhoneQuery({ cellId, endedAt, minutes }) {
|
||||
return {
|
||||
filter: [
|
||||
'resource.type="gce_instance"',
|
||||
`jsonPayload.event="${CELL_METRICS_EVENT}"`,
|
||||
`jsonPayload.cellId="${cellId}"`,
|
||||
`timestamp>="${span.startedAt.toISOString()}"`,
|
||||
`timestamp<"${new Date(endedAt + DIRECTOR_METRICS_INTERVAL_MS).toISOString()}"`
|
||||
...timestampClauses(endedAt - minutes * MINUTE_MS, endedAt + DIRECTOR_METRICS_INTERVAL_MS)
|
||||
].join(' AND '),
|
||||
projection:
|
||||
'json(timestamp,jsonPayload.phoneRejectionsByCodeDelta,jsonPayload.resumeConfirmFailuresByCodeDelta,' +
|
||||
'jsonPayload.phoneAttachDeadlinesDelta,jsonPayload.phoneAcceptDatabaseErrorsDelta,jsonPayload.resumeRenewalFailuresDelta,' +
|
||||
'jsonPayload.clientAcceptCompletedDelta)',
|
||||
limit: LOG_ENTRY_LIMIT
|
||||
})
|
||||
fields: [
|
||||
'jsonPayload.phoneRejectionsByCodeDelta', 'jsonPayload.resumeConfirmFailuresByCodeDelta', 'jsonPayload.phoneAttachDeadlinesDelta',
|
||||
'jsonPayload.phoneAcceptDatabaseErrorsDelta', 'jsonPayload.resumeRenewalFailuresDelta', 'jsonPayload.clientAcceptCompletedDelta'
|
||||
],
|
||||
match: (entry) => entry.resource?.type === 'gce_instance'
|
||||
}
|
||||
}
|
||||
|
||||
export async function readCellPhoneMinutes(reader, request) {
|
||||
return parseCellPhoneMinutes(await readQuery(reader, cellPhoneQuery(request)), request)
|
||||
}
|
||||
|
||||
function parseCellPhoneMinutes(read, { endedAt, minutes }) {
|
||||
const span = { startedAt: new Date(endedAt - minutes * MINUTE_MS), endedAt: new Date(endedAt) }
|
||||
if (read.failed) return failedRead(read.error)
|
||||
if (read.entries.length >= LOG_ENTRY_LIMIT) return failedRead('cell runtime metrics read truncated')
|
||||
const keys = minutesOf(span)
|
||||
@@ -306,13 +294,24 @@ function directorLogFilter(directorService, eventClause, sinceAt) {
|
||||
].join(' AND ')
|
||||
}
|
||||
|
||||
const atOrAfter = (entry, sinceAt) => Date.parse(entry.timestamp) >= sinceAt
|
||||
const isEvent = (entry, event) => entry.resource?.type === 'cloud_run_revision' && entry.jsonPayload?.event === event
|
||||
|
||||
function ledgerQuery({ directorService, at }) {
|
||||
const sinceAt = at - RESERVE_WATCH_RULES.ledgerSummaryMaxAgeMs
|
||||
return {
|
||||
filter: directorLogFilter(directorService, `jsonPayload.event="${LEDGER_SUMMARY_EVENT}"`, sinceAt),
|
||||
fields: ['jsonPayload.pending', 'jsonPayload.dropped'],
|
||||
match: (entry) => isEvent(entry, LEDGER_SUMMARY_EVENT) && atOrAfter(entry, sinceAt)
|
||||
}
|
||||
}
|
||||
|
||||
export async function readLedgerSample(reader, request) {
|
||||
return parseLedgerSample(await readQuery(reader, ledgerQuery(request)))
|
||||
}
|
||||
|
||||
// Newest summary per director instance; queued plus dropped rows are the ones not in Postgres.
|
||||
export async function readLedgerSample(reader, { directorService, at }) {
|
||||
const read = await readLogEntries(reader, {
|
||||
filter: directorLogFilter(directorService, `jsonPayload.event="${LEDGER_SUMMARY_EVENT}"`, at - RESERVE_WATCH_RULES.ledgerSummaryMaxAgeMs),
|
||||
projection: 'json(timestamp,labels.instanceId,jsonPayload.pending,jsonPayload.dropped)',
|
||||
limit: LOG_ENTRY_LIMIT
|
||||
})
|
||||
function parseLedgerSample(read) {
|
||||
if (read.failed) return failedRead(read.error)
|
||||
if (read.entries.length >= LOG_ENTRY_LIMIT) return failedRead('ledger summary read truncated')
|
||||
if (read.entries.length === 0) return failedRead('no placing director logged a ledger summary')
|
||||
@@ -337,16 +336,26 @@ export async function readLedgerSample(reader, { directorService, at }) {
|
||||
|
||||
// The same read also takes the ledger summary every placing director logs each minute, as a
|
||||
// positive control: with no fresh summary in it, no seat-behind-row line is blindness, not zero.
|
||||
export async function readSeatBehindRowSample(reader, { directorService, cellId, at }) {
|
||||
const read = await readLogEntries(reader, {
|
||||
function seatBehindRowQuery({ directorService, cellId, at }) {
|
||||
const sinceAt = at - RESERVE_WATCH_RULES.duplicateSeat.lookbackMs
|
||||
return {
|
||||
filter: directorLogFilter(
|
||||
directorService,
|
||||
`((jsonPayload.event="${SEAT_BEHIND_ROW_EVENT}" AND jsonPayload.cellId="${cellId}") OR jsonPayload.event="${LEDGER_SUMMARY_EVENT}")`,
|
||||
at - RESERVE_WATCH_RULES.duplicateSeat.lookbackMs
|
||||
sinceAt
|
||||
),
|
||||
projection: 'json(timestamp,labels.instanceId,jsonPayload.event,jsonPayload.epoch,jsonPayload.rowEpoch)',
|
||||
limit: LOG_ENTRY_LIMIT
|
||||
})
|
||||
fields: ['jsonPayload.epoch', 'jsonPayload.rowEpoch'],
|
||||
match: (entry) =>
|
||||
atOrAfter(entry, sinceAt) &&
|
||||
((isEvent(entry, SEAT_BEHIND_ROW_EVENT) && entry.jsonPayload?.cellId === cellId) || isEvent(entry, LEDGER_SUMMARY_EVENT))
|
||||
}
|
||||
}
|
||||
|
||||
export async function readSeatBehindRowSample(reader, request) {
|
||||
return parseSeatBehindRowSample(await readQuery(reader, seatBehindRowQuery(request)), request)
|
||||
}
|
||||
|
||||
function parseSeatBehindRowSample(read, { cellId, at }) {
|
||||
if (read.failed) return failedRead(read.error)
|
||||
if (read.entries.length >= LOG_ENTRY_LIMIT) return failedRead('seat-behind-row read truncated')
|
||||
const reports = []
|
||||
@@ -368,6 +377,60 @@ export async function readSeatBehindRowSample(reader, { directorService, cellId,
|
||||
return { ok: true, reports }
|
||||
}
|
||||
|
||||
const timestampClauses = (startedAt, endedAt) => [
|
||||
`timestamp>="${new Date(startedAt).toISOString()}"`,
|
||||
`timestamp<"${new Date(endedAt).toISOString()}"`
|
||||
]
|
||||
const projectionOf = (queries) =>
|
||||
`json(${[...new Set(['timestamp', 'resource.type', 'labels.instanceId', 'jsonPayload.event', 'jsonPayload.cellId', ...queries.flatMap((query) => query.fields)])].join(',')})`
|
||||
const readQuery = (reader, query) => readLogEntries(reader, { filter: query.filter, projection: projectionOf([query]), limit: LOG_ENTRY_LIMIT })
|
||||
|
||||
function directorMetricsQuery({ directorService, endedAt, minutes }) {
|
||||
const window = directorMetricsWindow(endedAt, minutes)
|
||||
return {
|
||||
filter: [
|
||||
'resource.type="cloud_run_revision"',
|
||||
`resource.labels.service_name="${directorService}"`,
|
||||
`jsonPayload.event="${CELL_METRICS_EVENT}"`,
|
||||
...timestampClauses(window.startedAt, window.endedAt)
|
||||
].join(' AND '),
|
||||
fields: DIRECTOR_DRAIN_FIELDS.map((field) => `jsonPayload.${field}`),
|
||||
match: (entry) => isEvent(entry, CELL_METRICS_EVENT),
|
||||
minSamples: Math.floor((window.endedAt - window.startedAt) / DIRECTOR_METRICS_INTERVAL_MS)
|
||||
}
|
||||
}
|
||||
|
||||
// The queries one sample sends; `phoneRequest` is false while the phone path is not watched.
|
||||
export const sampleLogQueries = ({ phoneRequest, director, seatRequest }) => ({
|
||||
phone: phoneRequest && cellPhoneQuery(phoneRequest),
|
||||
directorMetrics: directorMetricsQuery(director),
|
||||
ledger: ledgerQuery({ directorService: director.directorService, at: seatRequest.at }),
|
||||
seatBehindRow: seatBehindRowQuery(seatRequest)
|
||||
})
|
||||
|
||||
// Every Cloud Logging query a sample needs, as one read: the project allows 60 reads a minute
|
||||
// across every watch and tool, and on 10-21 18:39Z twelve watches at five reads a sample drew 429s
|
||||
// until c21 and c22 tripped unverifiable. Each query keeps its own filter and takes back the lines
|
||||
// that are its own; the combined read truncated or failed fails every one of them.
|
||||
export async function readSampleLogs(reader, queries) {
|
||||
const named = Object.entries(queries).filter(([, query]) => query)
|
||||
const read = await readLogEntries(reader, {
|
||||
filter: named.map(([, query]) => `(${query.filter})`).join(' OR '),
|
||||
projection: projectionOf(named.map(([, query]) => query)),
|
||||
limit: LOG_ENTRY_LIMIT
|
||||
})
|
||||
const failure = read.failed
|
||||
? read.error
|
||||
: read.entries.length >= LOG_ENTRY_LIMIT
|
||||
? 'sample log read truncated'
|
||||
: read.entries.some((entry) => !Number.isFinite(Date.parse(entry.timestamp)))
|
||||
? 'sample log line with an unparseable timestamp'
|
||||
: null
|
||||
return Object.fromEntries(
|
||||
named.map(([name, query]) => [name, failure ? { failed: true, error: failure, entries: [] } : { failed: false, entries: read.entries.filter(query.match) }])
|
||||
)
|
||||
}
|
||||
|
||||
function createReader(dependencies, projectId) {
|
||||
const now = dependencies.now
|
||||
return {
|
||||
@@ -511,27 +574,26 @@ export async function watchSegment(config, dependencies) {
|
||||
}
|
||||
state = { ...state, phoneBackground: measuredPhoneBackground(read) }
|
||||
}
|
||||
// Complete minutes only, held back past the publishing delay.
|
||||
const endedAt = minuteFloor(at - METRIC_DELAY_MS)
|
||||
const phoneRequest = { cellId: request.cellId, endedAt, minutes: PHONE_WATCH_RULES.readMinutes }
|
||||
const director = { directorService, endedAt, minutes: RESERVE_WATCH_RULES.director503.readMinutes }
|
||||
const seatRequest = { directorService, cellId: request.cellId, at }
|
||||
const queries = sampleLogQueries({ phoneRequest: phoneWatched && phoneRequest, director, seatRequest })
|
||||
const logs = await readSampleLogs(reader, queries)
|
||||
const directorMetrics = {
|
||||
failed: logs.directorMetrics.failed,
|
||||
error: logs.directorMetrics.error,
|
||||
samples: logs.directorMetrics.entries.map(directorMetricsSample),
|
||||
minSamples: queries.directorMetrics.minSamples
|
||||
}
|
||||
const sample = {
|
||||
at,
|
||||
cell,
|
||||
...(phoneWatched
|
||||
? {
|
||||
phone: await readCellPhoneMinutes(reader, {
|
||||
cellId: request.cellId,
|
||||
endedAt: minuteFloor(at - METRIC_DELAY_MS),
|
||||
minutes: PHONE_WATCH_RULES.readMinutes
|
||||
})
|
||||
}
|
||||
: {}),
|
||||
director503: await readDirector503Minutes(reader, {
|
||||
projectId: request.projectId,
|
||||
directorService,
|
||||
// Complete minutes only, held back past the publishing delay.
|
||||
endedAt: minuteFloor(at - METRIC_DELAY_MS),
|
||||
minutes: RESERVE_WATCH_RULES.director503.readMinutes
|
||||
}),
|
||||
ledger: await readLedgerSample(reader, { directorService, at }),
|
||||
seatBehindRow: await readSeatBehindRowSample(reader, { directorService, cellId: request.cellId, at })
|
||||
...(phoneWatched ? { phone: parseCellPhoneMinutes(logs.phone, phoneRequest) } : {}),
|
||||
director503: await readDirector503Minutes(reader, { projectId: request.projectId, ...director, metrics: [directorMetrics] }),
|
||||
ledger: parseLedgerSample(logs.ledger),
|
||||
seatBehindRow: parseSeatBehindRowSample(logs.seatBehindRow, seatRequest)
|
||||
}
|
||||
const result = evaluateWatchSample(state, sample, { unverifiableLimit: config.unverifiableLimit })
|
||||
state = result.state
|
||||
|
||||
@@ -25,7 +25,9 @@ import {
|
||||
raiseAlarm,
|
||||
readCellPhoneMinutes,
|
||||
readDirector503Minutes,
|
||||
readSampleLogs,
|
||||
readSeatBehindRowSample,
|
||||
sampleLogQueries,
|
||||
recordOutcome,
|
||||
rolloutLeaseRefusal,
|
||||
watchSegment
|
||||
@@ -198,9 +200,14 @@ test('one stalled director instance does not trip the 503 rule; two instances or
|
||||
assert.equal(blind.rules.director503.status, 'unverifiable')
|
||||
assert.match(blind.rules.director503.reason, /truncated/)
|
||||
assert.equal(blind.state.unverifiableStreak, 1)
|
||||
// Platform 503s no instance answered count as an instance of their own.
|
||||
const platform = judge(read([37, 37, 37], { 'no-instance': [16, 16, 16], d2: [16, 16, 16] }))
|
||||
// 503s no director logged, over the whole fleet line by themselves, are no one instance's stall.
|
||||
const platform = judge(read([37, 37, 37], { unattributed: [31, 31, 31], d2: [6, 6, 6] }))
|
||||
assert.equal(platform.state.state, 'tripped')
|
||||
assert.match(platform.state.verdict, /93 of them no director instance logged$/)
|
||||
// A stalled instance's 30 s lines skew against the fleet's minutes; that remainder is not a second instance.
|
||||
const skewed = judge(read([60, 170, 60], { sick: [52, 162, 52], unattributed: [8, 8, 8], d2: [0, 0, 0] }))
|
||||
assert.equal(skewed.state.state, 'watching')
|
||||
assert.equal(skewed.rules.director503.unattributed, 24)
|
||||
// The share follows the directors that logged: eight make it 30/8, so an even 45 trips.
|
||||
const eight = read([45, 45, 45], Object.fromEntries(Array.from({ length: 8 }, (_, index) => [`d${index}`, [5.6, 5.6, 5.6]])))
|
||||
eight.instances.directors = byMinute([8, 8, 8])
|
||||
@@ -225,27 +232,65 @@ test('one stalled director instance does not trip the 503 rule; two instances or
|
||||
assert.equal(calm.rules.director503.status, 'pass')
|
||||
})
|
||||
|
||||
test('per-instance 503s come from the request log, less each instance\'s own re-dials', async () => {
|
||||
// 20 a minute split 10/10 over a and b; a alone answered 10 of its own re-dials a minute.
|
||||
const sources = fakeSources({ per503: () => 20, metrics: () => [rateLimited(5), {}] })
|
||||
test('per-instance 503s are each director\'s own logged 503s less its re-dials, and the rest is unattributed', async () => {
|
||||
// Fleet 30 a minute. a logged 20 (10 its own re-dials), b logged 6: 10 nobody accounts for.
|
||||
const lineOf = (count, own) => ({
|
||||
placementRejectionsByReasonDelta: { 'host-rate-limited': own },
|
||||
assign503sByCauseDelta: { 'placement-lane': count }
|
||||
})
|
||||
const sources = fakeSources({ per503: () => 30, metrics: () => [lineOf(10, 5), lineOf(3, 0)] })
|
||||
const read = await readDirector503Minutes(
|
||||
{ ...fakeReader(), fetch: sources.fetchImpl, runGcloud: sources.runGcloud },
|
||||
{ projectId: 'onorca-cloud', directorService: 'orca-cloud-relay', endedAt: START, minutes: 3 }
|
||||
)
|
||||
assert.equal(read.ok, true)
|
||||
assert.deepEqual(Object.values(read.perMinute), [10, 10, 10])
|
||||
assert.deepEqual(Object.keys(read.instances.perMinute).sort(), ['a', 'b'])
|
||||
assert.deepEqual(Object.values(read.instances.perMinute.a), [0, 0, 0])
|
||||
assert.deepEqual(Object.values(read.instances.perMinute.b), [10, 10, 10])
|
||||
assert.deepEqual(Object.values(read.perMinute), [20, 20, 20])
|
||||
assert.deepEqual(Object.keys(read.instances.perMinute).sort(), ['a', 'b', 'unattributed'])
|
||||
assert.deepEqual(Object.values(read.instances.perMinute.a), [10, 10, 10])
|
||||
assert.deepEqual(Object.values(read.instances.perMinute.b), [6, 6, 6])
|
||||
assert.deepEqual(Object.values(read.instances.perMinute.unattributed), [4, 4, 4])
|
||||
assert.deepEqual(Object.values(read.instances.directors), [2, 2, 2])
|
||||
// A full read is truncated, not every 503.
|
||||
const flood = fakeSources({ per503: () => 2_000 })
|
||||
const truncated = await readDirector503Minutes(
|
||||
{ ...fakeReader(), fetch: flood.fetchImpl, runGcloud: flood.runGcloud },
|
||||
{ projectId: 'onorca-cloud', directorService: 'orca-cloud-relay', endedAt: START, minutes: 3 }
|
||||
})
|
||||
|
||||
test('the recorded 10-21 07:55Z director stall reads as one instance and does not trip', async () => {
|
||||
const recorded = JSON.parse(readFileSync(new URL('../fixtures/relay-reserve-watch/2026-10-21-director-stall.json', import.meta.url), 'utf8'))
|
||||
const series = (code, perMinute) => ({
|
||||
metric: { labels: { response_code: code } },
|
||||
points: Object.entries(perMinute).map(([minute, count]) => ({
|
||||
interval: { endTime: new Date(Date.parse(`${minute}Z`) + MINUTE).toISOString() },
|
||||
value: { int64Value: String(count) }
|
||||
}))
|
||||
})
|
||||
const ok = Object.fromEntries(Object.keys(recorded.fleet503PerMinute).map((minute) => [minute, 1_000]))
|
||||
const lines = recorded.directorMetricsLines.map(({ timestamp, instance, ...deltas }) => ({
|
||||
timestamp,
|
||||
labels: { instanceId: instance },
|
||||
resource: { type: 'cloud_run_revision' },
|
||||
jsonPayload: { event: METRICS_EVENT, ...deltas }
|
||||
}))
|
||||
const read = await readDirector503Minutes(
|
||||
{
|
||||
...fakeReader(),
|
||||
fetch: async () => new Response(JSON.stringify({ timeSeries: [series('200', ok), series('503', recorded.fleet503PerMinute)] })),
|
||||
runGcloud: async (args) => {
|
||||
if (args[0] === 'auth') return { stdout: 'token' }
|
||||
const [, from, to] = args[2].match(/timestamp>="([^"]+)" AND timestamp<"([^"]+)"/)
|
||||
return { stdout: JSON.stringify(lines.filter(({ timestamp }) => timestamp >= from && timestamp < to)) }
|
||||
}
|
||||
},
|
||||
{ projectId: 'onorca-cloud', directorService: 'orca-cloud-relay', endedAt: Date.parse('2026-10-21T07:58:00Z'), minutes: 10 }
|
||||
)
|
||||
assert.equal(truncated.ok, true)
|
||||
assert.deepEqual(truncated.instances, { ok: false, error: 'director 503 request log read truncated' })
|
||||
const judged = evaluateWatchSample(
|
||||
freshState({ background: { medianPerMinute: 10, source: 'input' } }),
|
||||
sampleAt(START, { director503: read }),
|
||||
LIMIT
|
||||
)
|
||||
// The fleet alone was over 30 all three minutes, which is what tripped all four watches.
|
||||
assert.deepEqual(Object.values(judged.rules.director503.recent), [45, 164, 40])
|
||||
assert.equal(judged.rules.director503.status, 'pass')
|
||||
// Not even the stalled instance held its share of 6 a minute: it fell to 5 in the third minute.
|
||||
assert.equal(judged.rules.director503.instancesOver, 0)
|
||||
assert.deepEqual(['07:55', '07:56', '07:57'].map((minute) => read.instances.perMinute.d5[`2026-10-21T${minute}`]), [40, 169, 5])
|
||||
})
|
||||
|
||||
const SEAT_EVENT = 'orca_relay_reserve_ledger_seat_behind_row'
|
||||
@@ -510,19 +555,8 @@ function metricsLines(filter, metrics) {
|
||||
return lines.reverse()
|
||||
}
|
||||
|
||||
// The `metrics` lines' instances in order; each minute's 503s are split between the first two.
|
||||
// The `metrics` lines' instances, in order.
|
||||
const FAKE_DIRECTORS = ['a', 'b', 'c', 'd', 'e']
|
||||
function requestLines(filter, per503) {
|
||||
const [, from, to] = filter.match(/timestamp>="([^"]+)" AND timestamp<"([^"]+)"/)
|
||||
const lines = []
|
||||
for (let minute = Date.parse(from); minute < Date.parse(to); minute += MINUTE) {
|
||||
const count = per503(minute)
|
||||
for (let index = 0; index < count; index += 1) {
|
||||
lines.push({ timestamp: new Date(minute + 1_000).toISOString(), labels: { instanceId: FAKE_DIRECTORS[index % 2] } })
|
||||
}
|
||||
}
|
||||
return lines.reverse()
|
||||
}
|
||||
|
||||
function fakeSources({
|
||||
cell = () => ({}),
|
||||
@@ -534,7 +568,9 @@ function fakeSources({
|
||||
seatControl = true,
|
||||
rolloutLease = null,
|
||||
// Each director instance's runtime-metrics deltas for the 30 s ending at `endedAt`.
|
||||
metrics = () => [{}]
|
||||
metrics = () => [{}],
|
||||
// The watched cell's own runtime-metrics deltas, when it runs the phone path.
|
||||
phone = null
|
||||
} = {}) {
|
||||
let samples = 0
|
||||
const monitoringSpans = []
|
||||
@@ -576,17 +612,33 @@ function fakeSources({
|
||||
}
|
||||
throw new Error(`unexpected fetch ${text}`)
|
||||
}
|
||||
const director = (entries) => entries.map((entry) => ({ ...entry, resource: { type: 'cloud_run_revision' } }))
|
||||
// One query's lines, as Cloud Logging would answer its filter alone.
|
||||
const answer = (filter) => {
|
||||
const summaries = director(ledger(samples).map((entry) => ({ ...entry, jsonPayload: { ...entry.jsonPayload, event: SUMMARY_EVENT } })))
|
||||
if (filter.includes(SEAT_EVENT)) return seatControl ? summaries : []
|
||||
if (filter.includes(SUMMARY_EVENT)) return summaries
|
||||
if (filter.includes('gce_instance')) {
|
||||
return phone ? metricsLines(filter, (at) => [{ ...phone(at), event: METRICS_EVENT, cellId: CELL }]).map((entry) => ({ ...entry, resource: { type: 'gce_instance' } })) : []
|
||||
}
|
||||
if (filter.includes(METRICS_EVENT)) return director(metricsLines(filter, (at) => metrics(at).map((deltas) => ({ ...deltas, event: METRICS_EVENT }))))
|
||||
return []
|
||||
}
|
||||
const logReads = []
|
||||
const runGcloud = async (args) => {
|
||||
if (args[0] === 'auth') return { stdout: 'token' }
|
||||
const filter = args[2]
|
||||
const summaries = ledger(samples).map((entry) => ({ ...entry, jsonPayload: { ...entry.jsonPayload, event: SUMMARY_EVENT } }))
|
||||
if (filter.includes(SEAT_EVENT)) return { stdout: JSON.stringify(seatControl ? summaries : []) }
|
||||
if (filter.includes(SUMMARY_EVENT)) return { stdout: JSON.stringify(ledger(samples)) }
|
||||
if (filter.includes(METRICS_EVENT)) return { stdout: JSON.stringify(metricsLines(filter, metrics)) }
|
||||
if (filter.includes('httpRequest.status=503')) return { stdout: JSON.stringify(requestLines(filter, per503)) }
|
||||
return { stdout: '[]' }
|
||||
logReads.push({ sample: samples, filter })
|
||||
// A sample's combined read is `(A) OR (B) ...`; each part answers as it would alone, deduplicated.
|
||||
const parts = filter.startsWith('(') ? filter.slice(1, -1).split(') OR (') : [filter]
|
||||
const seen = new Set()
|
||||
const entries = parts.flatMap(answer).filter((entry) => {
|
||||
const key = JSON.stringify(entry)
|
||||
return !seen.has(key) && seen.add(key)
|
||||
})
|
||||
return { stdout: JSON.stringify(entries) }
|
||||
}
|
||||
return { fetchImpl, runGcloud, monitoringSpans, readRolloutLease: async () => rolloutLease }
|
||||
return { fetchImpl, runGcloud, monitoringSpans, logReads, readRolloutLease: async () => rolloutLease }
|
||||
}
|
||||
|
||||
test('a segment samples once a minute, carries state to the next segment, and stops on a trip', async () => {
|
||||
@@ -968,15 +1020,95 @@ test('503s the director could not serve trip after three minutes over the line,
|
||||
const flippedAt = START - 2 * MINUTE
|
||||
const { state } = await watchFor(10, fakeSources({
|
||||
per503: (minute) => (minute < flippedAt ? 20 : 60),
|
||||
// 10 re-dials a minute throughout; the 40 more after the flip are queue waits that timed out.
|
||||
metrics: (at) => [{
|
||||
...rateLimited(5),
|
||||
stickyRejectionsByReasonDelta: at <= flippedAt ? {} : { 'wait-timeout': 20 }
|
||||
}]
|
||||
// 10 re-dials a minute on a throughout; the 40 more after the flip are queue waits that timed
|
||||
// out, 20 a minute on each of two instances.
|
||||
metrics: (at) => {
|
||||
const waits = at <= flippedAt ? {} : { stickyRejectionsByReasonDelta: { 'wait-timeout': 10 }, assign503sByCauseDelta: { 'sticky-lane': 10 } }
|
||||
const a = rateLimited(5)
|
||||
return [{ ...a, ...waits, assign503sByCauseDelta: { ...a.assign503sByCauseDelta, ...waits.assign503sByCauseDelta } }, waits]
|
||||
}
|
||||
}), flippedAt)
|
||||
assert.equal(state.state, 'tripped')
|
||||
assert.deepEqual(state.background, { medianPerMinute: 10, minutes: 10, source: 'measured' })
|
||||
assert.match(state.verdict, /director503: director 503s above 30\/min for 3 min \(50, 50, 50\)/)
|
||||
assert.match(state.verdict, /director503: director 503s above 30\/min for 3 min \(50, 50, 50\), 2 instances each above 15\/min$/)
|
||||
})
|
||||
|
||||
test('the combined read hands each query only its own lines', async () => {
|
||||
const at = START
|
||||
const endedAt = START - 3 * MINUTE
|
||||
const queries = sampleLogQueries({
|
||||
phoneRequest: { cellId: CELL, endedAt, minutes: 10 },
|
||||
director: { directorService: 'orca-cloud-relay', endedAt, minutes: 10 },
|
||||
seatRequest: { directorService: 'orca-cloud-relay', cellId: CELL, at }
|
||||
})
|
||||
const director = (ago, jsonPayload) => ({ timestamp: new Date(at - ago).toISOString(), resource: { type: 'cloud_run_revision' }, labels: { instanceId: 'a' }, jsonPayload })
|
||||
const entries = {
|
||||
metrics: director(5 * MINUTE, { event: METRICS_EVENT }),
|
||||
phone: { timestamp: new Date(at - 5 * MINUTE).toISOString(), resource: { type: 'gce_instance' }, jsonPayload: { event: METRICS_EVENT, cellId: CELL } },
|
||||
freshSummary: director(60_000, { event: SUMMARY_EVENT, pending: 0, dropped: 0 }),
|
||||
staleSummary: director(10 * MINUTE, { event: SUMMARY_EVENT, pending: 0, dropped: 0 }),
|
||||
ownSeat: director(2 * MINUTE, { event: SEAT_EVENT, cellId: CELL, epoch: 1, rowEpoch: 2 }),
|
||||
otherSeat: director(2 * MINUTE, { event: SEAT_EVENT, cellId: 'production-gce-c99', epoch: 1, rowEpoch: 2 })
|
||||
}
|
||||
let filter
|
||||
const logs = await readSampleLogs(
|
||||
fakeReader({ runGcloud: async (args) => ((filter = args[2]), { stdout: JSON.stringify(Object.values(entries)) }) }),
|
||||
queries
|
||||
)
|
||||
const names = (read) => read.entries.map((entry) => Object.keys(entries).find((name) => JSON.stringify(entries[name]) === JSON.stringify(entry)))
|
||||
assert.equal(filter.split(') OR (').length, 4)
|
||||
assert.deepEqual(names(logs.directorMetrics), ['metrics'])
|
||||
assert.deepEqual(names(logs.phone), ['phone'])
|
||||
// The ledger rule wants a summary from the last 150 s; the seat read's positive control, 15 min.
|
||||
assert.deepEqual(names(logs.ledger), ['freshSummary'])
|
||||
assert.deepEqual(names(logs.seatBehindRow), ['freshSummary', 'staleSummary', 'ownSeat'])
|
||||
// Without the phone path its query is not sent.
|
||||
const unwatched = sampleLogQueries({ phoneRequest: false, director: { directorService: 'orca-cloud-relay', endedAt, minutes: 10 }, seatRequest: { directorService: 'orca-cloud-relay', cellId: CELL, at } })
|
||||
const sent = await readSampleLogs(fakeReader({ runGcloud: async (args) => ((filter = args[2]), { stdout: '[]' }) }), unwatched)
|
||||
assert.equal(filter.split(') OR (').length, 3)
|
||||
assert.doesNotMatch(filter, /gce_instance/)
|
||||
assert.equal('phone' in sent, false)
|
||||
// A full read is truncated for every query; a failed one names its error.
|
||||
const full = await readSampleLogs(fakeReader({ runGcloud: async () => ({ stdout: JSON.stringify(Array.from({ length: 1_000 }, () => entries.metrics)) }) }), unwatched)
|
||||
assert.ok(Object.values(full).every((read) => read.failed && read.error === 'sample log read truncated'))
|
||||
})
|
||||
|
||||
// 10-21 18:39Z: twelve watches at ~5 Cloud Logging reads a sample hit the project's 60 a minute.
|
||||
test('a sample makes one Cloud Logging read, and a 429 retried inside its budget stays verifiable', async () => {
|
||||
const memory = { flagsApplied: { generation: 4, flags: { admitMode: 'reserve', readinessLocal: true, phonePath: 'memory' } } }
|
||||
const sources = fakeSources({ cell: () => memory, phone: () => ({ phoneAttachDeadlinesDelta: 0, clientAcceptCompletedDelta: 10 }) })
|
||||
// Sample 6's combined read answers 429 once; sample 8's (the 9th read), on all three attempts.
|
||||
let combined = 0
|
||||
let ninth = 0
|
||||
const runGcloud = async (args, options) => {
|
||||
if (args[0] === 'logging' && args[2].startsWith('(')) {
|
||||
combined += 1
|
||||
if (combined === 6) throw new Error('RESOURCE_EXHAUSTED: 429 Quota exceeded for ReadRequestsPerMinutePerProject')
|
||||
if (combined >= 9 && ninth < 3) {
|
||||
ninth += 1
|
||||
throw new Error('RESOURCE_EXHAUSTED: 429 Quota exceeded for ReadRequestsPerMinutePerProject')
|
||||
}
|
||||
}
|
||||
return sources.runGcloud(args, options)
|
||||
}
|
||||
const { state, lines } = await watchFor(12, { ...sources, runGcloud })
|
||||
assert.equal(state.state, 'watching')
|
||||
assert.equal(lines.length, 12)
|
||||
// One combined read per sample: 12, one retry for sample 6 and two for sample 8. Only the
|
||||
// one-time backgrounds read alone.
|
||||
assert.equal(combined, 15)
|
||||
const reads = sources.logReads.map(({ filter }) => filter)
|
||||
assert.equal(reads.filter((filter) => filter.startsWith('(')).length, 11)
|
||||
assert.ok(reads.filter((filter) => !filter.startsWith('(')).length <= 3)
|
||||
const combinedRead = reads.find((filter) => filter.startsWith('('))
|
||||
for (const part of ['gce_instance', METRICS_EVENT, SUMMARY_EVENT, SEAT_EVENT]) assert.ok(combinedRead.includes(part), part)
|
||||
// The retried 429 left sample 6 whole; sample 8, which never read, is one gap the next heals.
|
||||
assert.equal(lines[5].unverifiableStreak, 0)
|
||||
assert.ok(Object.values(lines[5].rules).every((rule) => rule.status !== 'unverifiable'))
|
||||
assert.equal(lines[7].unverifiableStreak, 1)
|
||||
assert.match(lines[7].rules.duplicateSeat.reason, /RESOURCE_EXHAUSTED/)
|
||||
assert.match(lines[7].rules.director503.reason, /director runtime metrics read failed: RESOURCE_EXHAUSTED/)
|
||||
assert.equal(lines[8].unverifiableStreak, 0)
|
||||
})
|
||||
|
||||
test('a minute no director instance logged runtime metrics for is unverifiable, not zero', async () => {
|
||||
@@ -1382,13 +1514,11 @@ async function phoneWatch(phoneMetrics, minutes) {
|
||||
const lines = []
|
||||
const config = parseAt(watchValues({ 'state-file': join(directory, 'state.json'), 'segment-minutes': String(minutes) }))
|
||||
const sources = fakeSources({
|
||||
cell: () => ({ flagsApplied: { generation: 4, flags: { admitMode: 'reserve', readinessLocal: true, phonePath: 'memory' } } })
|
||||
cell: () => ({ flagsApplied: { generation: 4, flags: { admitMode: 'reserve', readinessLocal: true, phonePath: 'memory' } } }),
|
||||
phone: phoneMetrics
|
||||
})
|
||||
const runGcloud = async (args) =>
|
||||
args[2]?.includes('gce_instance') ? { stdout: JSON.stringify(metricsLines(args[2], (at) => [phoneMetrics(at)])) } : sources.runGcloud(args)
|
||||
const state = await watchSegment(config, {
|
||||
...sources,
|
||||
runGcloud,
|
||||
idToken: 'id',
|
||||
accessToken: 'access',
|
||||
audit: {},
|
||||
|
||||
@@ -845,14 +845,26 @@ with fewer lines than a single instance logs (20) or at its entry limit is unver
|
||||
measured background leaves such minutes out (and is not measured with fewer than half of its 10
|
||||
metered). Coverage is any instance, not every one: an instance whose lines are missing while others
|
||||
log under-subtracts its re-dials, which can only push toward a trip, never hide one. The instance
|
||||
split counts 503s from Cloud Run's request log by `labels.instanceId` (the metric names no
|
||||
instance), less each instance's own scheduled 503s; 503s no instance answered count as one instance of their
|
||||
own, which can be one of the 2. With a single director the share is half the line, so that one
|
||||
instance alone never trips between the lines. A judged minute with no instance count is
|
||||
unverifiable. A single instance id must hold its share for all 3 minutes, so a fault that keeps replacing
|
||||
instances can pass under the broad line. That read stops at 5,000 lines (the 24 hours to 10-21
|
||||
peaked at 1,681): truncated or failed while the fleet is between the two lines, the sample is
|
||||
unverifiable. The same measure is the
|
||||
split counts each instance's own `/v1/assign` 503s from its runtime-metrics lines
|
||||
(`assign503sByCauseDelta`, by `labels.instanceId`; the metric names no instance), less that
|
||||
instance's own scheduled 503s. The fleet's non-drain 503s no instance's lines account for (Cloud
|
||||
Run's own, a route the director does not count, or an instance that stopped logging) are
|
||||
`unattributed`: summed over the 3 judged minutes, since an instance's 30 s lines skew against the
|
||||
fleet's minutes, and over the whole fleet line by themselves they trip (no one instance's stall
|
||||
explains them; the largest such sum in the 24 hours to 10-21 was 38, against 90). A stalled instance that also stops logging its lines therefore trips, on purpose: the 10-21 07:55Z instance kept logging through its stall. On the recorded 10-21 07:55Z stall this reads 40, 169, 5
|
||||
on the stalled instance, where Cloud Run's request log read 54, 155, 5. With a single director the
|
||||
share is half the line, so that one instance alone never trips between the lines. A judged minute
|
||||
with no instance count is unverifiable. A single instance id must hold its share for all 3
|
||||
minutes, so a fault that keeps replacing instances can pass under the broad line.
|
||||
|
||||
Each sample makes one Cloud Logging read: the director's runtime metrics, its ledger summaries,
|
||||
the cell's seat-behind-row lines and, while the phone path is watched, the cell's own runtime
|
||||
metrics, as one OR filter split back client-side. The project allows 60 reads a minute shared by
|
||||
every watch and tool; on 2026-10-21 18:39Z twelve watches at about five reads a sample drew 429s
|
||||
until c21 and c22 tripped unverifiable. A read is ~200 lines (1,000 is one page and the limit); one
|
||||
truncated or failed after its retries makes every log-read rule unverifiable for that sample,
|
||||
which counts once toward the streak as any unreadable rule did. The 503 background and the phone
|
||||
background are each read once, on their own. The same measure is the
|
||||
background and `background-503-per-minute`. Until the
|
||||
minutes before `flipped-at` are published (3 minutes past it) the 503 rule is pending, which does
|
||||
not add to the streak. The duplicate read also takes `orca_relay_reserve_ledger_summary`, which
|
||||
|
||||
Reference in New Issue
Block a user