Skip to content

Commit b1f5795

Browse files
authored
fix(stovepipe): mint a distinct message id for each buildsignal re-poll (#465)
## Summary ### Why? `buildsignal` schedules its next poll by re-publishing to its own topic, and it reused the build id as the message id — byte-identical to the message `build` published to start the loop. The MySQL queue dedups on the `(topic, partition_key, id)` unique key and `InsertDelayed` swallows the collision with `ON DUPLICATE KEY UPDATE topic = topic`, returning success. So the reschedule was accepted and silently discarded. This is deterministic, not a race. The re-publish happens before the delivery is acked, and GC only collects up to the minimum *acked* offset on idle ticks, so the colliding row is always still present. The effect: any build that is not terminal on its first poll is never polled again. `Build.Status` freezes at `accepted`/`running`, the request never leaves `processing`, nothing is published to `record`, and the queue's `in_flight_count` slot is never released — so after `MaxConcurrent` such builds the queue stops admitting work entirely. Nothing caught it because the fake build runner could not report a non-terminal status until the previous commit, and the unit tests matched the published message with `gomock.Any()`. ### What? `publishBuildSignal` now mints `{buildID}/poll/{generation}`, where the generation is read off the id of the delivery being processed and incremented — so a chain runs `B` -> `B/poll/1` -> `B/poll/2` -> … The partition key stays the build id, so each build's poll loop keeps its own partition. The generation advances deterministically rather than randomly, which matters for the case a random suffix handles badly. The next id is a pure function of the delivery, so a redelivery racing the original computes the *same* id and dedup collapses the two into one message: the build keeps a single poll chain. A random suffix would instead fork a second chain, doubling the poll rate and racing the first chain's status CAS for no benefit. A stable id is not an option in the other direction either — that is the bug itself. Even a fixed-but-different id like `B/poll` only survives one extra tick, because the second tick's re-poll then collides with the message being processed. ## Test Plan ✅ `bazel test //stovepipe/...` — new unit test asserts successive re-polls mint distinct ids and never reuse the build id. Verified it genuinely regresses: reverting just the id line fails it with `"map[bk-1:{}]" should have 3 item(s), but has 1`. ✅ `bazel test //test/e2e/stovepipe/...` — new e2e ingests a queue carrying the `build-slow` marker and waits for the build row to reach `succeeded`, which requires more than one poll tick. The service log shows three distinct ids on the `buildsignal` topic for one build. ## Stack 1. #464 1. @ #465 1. #466 1. #467 1. #468 1. #469
1 parent efccfa3 commit b1f5795

5 files changed

Lines changed: 165 additions & 7 deletions

File tree

doc/rfc/stovepipe/steps/buildsignal.md

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -61,6 +61,10 @@ For a delivery carrying build id `B`:
6161
8. Else PublishAfter(B -> buildsignal, delayMs), partitioned by build id:
6262
- delayMs = pollDelay(status): shorter while running, longer while accepted.
6363
- a fresh message (retry_count resets to 0), not a nack — polling is not failure.
64+
- the message id must be unique per tick. The queue dedups on (topic, partition_key, id)
65+
and the delivery being processed is still un-acked, so its row is present: reusing B as
66+
the message id makes every re-poll collide with the message that scheduled it and be
67+
silently discarded, ending the poll loop after one tick.
6468
- ack.
6569
```
6670

stovepipe/controller/buildsignal/buildsignal.go

Lines changed: 38 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,8 @@ package buildsignal
2222
import (
2323
"context"
2424
"fmt"
25+
"strconv"
26+
"strings"
2527

2628
"github.com/uber-go/tally"
2729
entityqueue "github.com/uber/submitqueue/platform/base/messagequeue"
@@ -151,7 +153,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er
151153
}
152154

153155
delayMs := pollDelay(effective)
154-
if err := c.publishBuildSignal(ctx, build.ID, delayMs); err != nil {
156+
if err := c.publishBuildSignal(ctx, build.ID, msg.ID, delayMs); err != nil {
155157
return errs.NewRetryableError(fmt.Errorf("failed to reschedule poll for build %s: %w", build.ID, err))
156158
}
157159
c.logger.Debugw("rescheduled build status poll",
@@ -218,15 +220,48 @@ func (c *Controller) publishRecord(ctx context.Context, buildID, requestID strin
218220
return c.publish(ctx, stovepipemq.TopicKeyRecord, msg, 0)
219221
}
220222

223+
// pollIDInfix separates a build id from its poll generation in a re-poll
224+
// message id: "<buildID>/poll/<generation>".
225+
const pollIDInfix = "/poll/"
226+
227+
// nextPollMessageID returns the message id for the next poll of buildID, one
228+
// generation past the delivery that scheduled it. currentMsgID is the id of the
229+
// message being processed — either the initial publish from build (no
230+
// generation, so the next is 1) or a previous re-poll.
231+
//
232+
// The generation has to advance because the queue dedups on
233+
// (topic, partition_key, id) and the delivery being processed has not been acked
234+
// yet, so its row is still present: a re-poll reusing the current id would
235+
// collide with the message that scheduled it and be silently discarded, ending
236+
// the poll loop after one tick.
237+
//
238+
// It advances deterministically rather than randomly so the id stays a pure
239+
// function of the delivery. A redelivery racing the original computes the same
240+
// next id, so dedup collapses the two into one message and the build keeps a
241+
// single poll chain — where a random suffix would fork a second chain that
242+
// doubles the poll rate and races the first one's status CAS.
243+
func nextPollMessageID(buildID, currentMsgID string) string {
244+
generation := 0
245+
if rest, found := strings.CutPrefix(currentMsgID, buildID+pollIDInfix); found {
246+
if n, err := strconv.Atoi(rest); err == nil && n > 0 {
247+
generation = n
248+
}
249+
}
250+
return fmt.Sprintf("%s%s%d", buildID, pollIDInfix, generation+1)
251+
}
252+
221253
// publishBuildSignal re-publishes buildID to buildsignal after delayMs,
222254
// partitioned by build id so each build's poll loop runs in its own
223255
// partition. A fresh message, not a nack — polling is not failure.
224-
func (c *Controller) publishBuildSignal(ctx context.Context, buildID string, delayMs int64) error {
256+
//
257+
// currentMsgID is the id of the delivery being processed; see nextPollMessageID
258+
// for why the new id is derived from it rather than reused or randomized.
259+
func (c *Controller) publishBuildSignal(ctx context.Context, buildID, currentMsgID string, delayMs int64) error {
225260
payload, err := stovepipemq.Marshal(&stovepipemq.BuildSignal{Id: buildID})
226261
if err != nil {
227262
return fmt.Errorf("failed to serialize build signal: %w", err)
228263
}
229-
msg := entityqueue.NewMessage(buildID, payload, buildID, nil)
264+
msg := entityqueue.NewMessage(nextPollMessageID(buildID, currentMsgID), payload, buildID, nil)
230265
return c.publish(ctx, stovepipemq.TopicKeyBuildSignal, msg, delayMs)
231266
}
232267

stovepipe/controller/buildsignal/buildsignal_test.go

Lines changed: 74 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -326,3 +326,77 @@ func TestProcess(t *testing.T) {
326326
})
327327
}
328328
}
329+
330+
// TestPublishBuildSignalAdvancesPollGeneration is the regression test for the poll
331+
// loop stalling. The queue dedups on (topic, partition_key, id) and the delivery that
332+
// scheduled a re-poll is still un-acked when the re-poll is published, so a reused
333+
// message id makes the reschedule a silent no-op and the build is never polled again.
334+
// The generation therefore has to advance each tick. The partition key must stay the
335+
// build id so each poll loop keeps its own partition.
336+
func TestPublishBuildSignalAdvancesPollGeneration(t *testing.T) {
337+
ctrl := gomock.NewController(t)
338+
c, m := newController(t, ctrl)
339+
340+
var ids []string
341+
m.publisher.EXPECT().PublishAfter(gomock.Any(), "buildsignal", gomock.Any(), PollDelayRunningMs).
342+
DoAndReturn(func(_ context.Context, _ string, msg entityqueue.Message, _ int64) error {
343+
ids = append(ids, msg.ID)
344+
assert.Equal(t, testBuildID, msg.PartitionKey)
345+
return nil
346+
}).Times(3)
347+
348+
// Walk a chain: each publish is scheduled by the message the previous one minted.
349+
current := testBuildID
350+
for range 3 {
351+
require.NoError(t, c.publishBuildSignal(context.Background(), testBuildID, current, PollDelayRunningMs))
352+
current = ids[len(ids)-1]
353+
}
354+
355+
assert.Equal(t, []string{
356+
testBuildID + "/poll/1",
357+
testBuildID + "/poll/2",
358+
testBuildID + "/poll/3",
359+
}, ids, "each tick must mint a fresh id, or the reschedule dedups against the message that scheduled it")
360+
}
361+
362+
// TestPublishBuildSignalIsIdempotentPerDelivery pins the other half of the contract:
363+
// the next id is a pure function of the delivery being processed. A redelivery racing
364+
// the original computes the same id, so dedup collapses them and the build keeps a
365+
// single poll chain rather than forking a second one that doubles the poll rate and
366+
// races the first one's status CAS.
367+
func TestPublishBuildSignalIsIdempotentPerDelivery(t *testing.T) {
368+
ctrl := gomock.NewController(t)
369+
c, m := newController(t, ctrl)
370+
371+
var ids []string
372+
m.publisher.EXPECT().PublishAfter(gomock.Any(), "buildsignal", gomock.Any(), PollDelayRunningMs).
373+
DoAndReturn(func(_ context.Context, _ string, msg entityqueue.Message, _ int64) error {
374+
ids = append(ids, msg.ID)
375+
return nil
376+
}).Times(2)
377+
378+
scheduledBy := testBuildID + "/poll/7"
379+
require.NoError(t, c.publishBuildSignal(context.Background(), testBuildID, scheduledBy, PollDelayRunningMs))
380+
require.NoError(t, c.publishBuildSignal(context.Background(), testBuildID, scheduledBy, PollDelayRunningMs))
381+
382+
assert.Equal(t, ids[0], ids[1], "a redelivery of the same message must republish the same id so dedup collapses it")
383+
assert.Equal(t, testBuildID+"/poll/8", ids[0])
384+
}
385+
386+
func TestNextPollMessageID(t *testing.T) {
387+
tests := []struct {
388+
name string
389+
current string
390+
expected string
391+
}{
392+
{name: "initial publish from build starts at one", current: testBuildID, expected: testBuildID + "/poll/1"},
393+
{name: "advances the generation", current: testBuildID + "/poll/4", expected: testBuildID + "/poll/5"},
394+
{name: "unparsable generation restarts at one", current: testBuildID + "/poll/x", expected: testBuildID + "/poll/1"},
395+
{name: "another build's id is not a prefix match", current: "other/poll/9", expected: testBuildID + "/poll/1"},
396+
}
397+
for _, tt := range tests {
398+
t.Run(tt.name, func(t *testing.T) {
399+
assert.Equal(t, tt.expected, nextPollMessageID(testBuildID, tt.current))
400+
})
401+
}
402+
}

test/e2e/stovepipe/harness_test.go

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -130,3 +130,21 @@ func (s *StovepipeE2ESuite) assertIngestPersisted(queue, id string) {
130130
assert.Equal(t, id, s.uriMapping(queue), "URI mapping should point at the minted request id")
131131
assert.Equal(t, 1, s.publishedMessageCount(id), "should have published one process message for %s", id)
132132
}
133+
134+
// awaitBuildStatus blocks until the build row for a request reaches want. The
135+
// pipeline runs inside the stovepipe-service container, so the build's own status
136+
// column is the durable, black-box signal that the poll loop converged: buildsignal
137+
// is its only writer after build creates the row.
138+
func (s *StovepipeE2ESuite) awaitBuildStatus(requestID, want string) {
139+
pollUntil(processPollInterval, func() bool {
140+
var status string
141+
err := s.db.QueryRow("SELECT status FROM build WHERE request_id = ?", requestID).Scan(&status)
142+
if err != nil {
143+
// sql.ErrNoRows means the build row is not created yet.
144+
s.log.Logf("build for %s not readable yet: %v", requestID, err)
145+
return false
146+
}
147+
s.log.Logf("build for %s status = %q (want %q)", requestID, status, want)
148+
return status == want
149+
})
150+
}

test/e2e/stovepipe/suite_test.go

Lines changed: 31 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -30,10 +30,11 @@ package e2e_test
3030
// bazel test //test/e2e/stovepipe:stovepipe_test
3131
//
3232
// The stack runs the Stovepipe gRPC service plus a storage MySQL (request,
33-
// request_uri) and a queue MySQL (the process stage). Unlike the integration
34-
// suite (test/integration/stovepipe), which asserts only that Ingest *publishes*
35-
// a process message, this suite additionally drives the asynchronous process
36-
// consumer to completion — proving the ingest→process pipeline runs end-to-end.
33+
// request_uri, queue, build) and a queue MySQL (the pipeline stages). Unlike the
34+
// integration suite (test/integration/stovepipe), which asserts only that Ingest
35+
// *publishes* a process message, this suite additionally drives the asynchronous
36+
// consumers to completion — proving the ingest→process→build→buildsignal pipeline
37+
// runs end-to-end.
3738

3839
import (
3940
"context"
@@ -157,3 +158,29 @@ func (s *StovepipeE2ESuite) TestIngest_Idempotent() {
157158
id2 := s.ingest(queue)
158159
assert.Equal(s.T(), id, id2, "re-ingest of the same head should dedup to the same id")
159160
}
161+
162+
// TestIngest_SlowBuild_PollsToCompletion drives a build that is not terminal on its
163+
// first poll, which is the only path that exercises buildsignal's reschedule.
164+
//
165+
// The queue name carries a fake-buildrunner marker: the fake SourceControl resolves a
166+
// queue to "git://<queue>/HEAD", so the marker rides into the head URI and the fake
167+
// BuildRunner reports running for a while before succeeding. Reaching a terminal build
168+
// status therefore requires the poll loop to tick more than once.
169+
//
170+
// This is the regression test for the loop stalling: buildsignal re-publishes to its
171+
// own topic to schedule the next poll, and the queue dedups on
172+
// (topic, partition_key, id). While the delivery being processed is still un-acked its
173+
// row is present, so a re-poll that reuses the build id as the message id is silently
174+
// discarded and the build is never polled again — the build would sit at `running`
175+
// forever.
176+
func (s *StovepipeE2ESuite) TestIngest_SlowBuild_PollsToCompletion() {
177+
const queue = "monorepo/slow?buildrunner-fake=build-slow"
178+
179+
id := s.ingest(queue)
180+
s.log.Logf("Ingest succeeded: id=%s; waiting for the poll loop to reach a terminal build", id)
181+
182+
s.assertIngestPersisted(queue, id)
183+
184+
// Getting here at all means the reschedule produced a deliverable message.
185+
s.awaitBuildStatus(id, "succeeded")
186+
}

0 commit comments

Comments
 (0)