testsoon: drain both cross-thread callbacks before the test returns - #703
Conversation
6cdb940 to
cd0cf25
Compare
|
Ah, thanks for the patch - looking at the code I think I intended to put only one item on the queue and the second is a fat finger but hey, we can go with 2 as well now that it works ;) |
| # The callback was posted to the dispatcher's queue; poll to execute it | ||
| poll() | ||
| check: crossThreadCallSoonFlag == true | ||
| # Join before polling so both posts are visible, then poll until both |
There was a problem hiding this comment.
the thread join shouldn't matter really, ie callSoon is executed independently of what's going on on the other thread.. what might happen however is that two callSoons get coalesced into a single poll handling them both - it's undefined how many wake-ups there are - so the while loop is correct but the comment is slightly misleading
There was a problem hiding this comment.
Yeah you're right, and the join placement was leftover caution, I moved it below the check.
That also broadens what the test can exercise: with the join first, both posts were always queued before the first poll, so the drain was always the batched case. With polling overlapping the thread, either interleaving can occur - both drained in one poll, or arriving separately. Comment reworded around the actual invariant: polls and callbacks don't map 1:1, so the loop counts completions, and nothing may stay queued past this frame
The cross-thread callSoon test posts two callbacks from a spawned thread, each carrying the address of a stack local, and polls once. When the dispatcher's queue drain lands between the two posts, the second callback stays queued, the check passes off the first, and the test returns. The next poll in the process fires the leftover callback through the dangling pointer into a dead frame. On linux-i386 the written byte lands on the stack canary of the timers suite's first waitFor, aborting testall with "stack smashing detected"; on other targets the same write is silent corruption of whatever occupies the address. Count the callbacks instead of latching a bool and poll until both have run: wake-ups do not map one to one with polls, so the completion count is the only sound exit condition, and no queued callback can then outlive the frame it points into.
cd0cf25 to
6781d1f
Compare
Happy accident then - the second post is what surfaced the drain race at all, and under the count it doubles as coverage for the coalesced case |
sweepSeeds/sweepSeedsWithBudget (chronos/simulation.nim) run a body across a seed range, collecting one SimSeedOutcome per seed regardless of its siblings' outcomes, and report the aggregate the checkLeaks way: a checkpoint per failing seed, one check at the end. collectSweepSeeds exposes the same aggregation loop without the unittest2 reporting, for a caller wanting its own, or none. tests/testsimulation.nim proves the aggregation itself: every seed runs and is collected in order, and a multi-seed failure reports every failing seed rather than stopping at the first (mutation-tested: an early-break regression fails only that test, 8/9 still green). tests/testcallbackqueue.nim gains a sim-driven suite exercising the real callSoon()/callIdle() machinery through a sim dispatcher under a sweep, alongside the existing structural CallbackQueue[T] tests. The pre-status-im#703 fixture (testsimulation.nim) reconstructs the shape of upstream status-im#703 - a callback observed before it has actually run, the same class as the leftover callSoon() callback that fired through a dangling pointer - using the sim seams that exist ahead of S13's simProducer: two readiness events delivered in the same batch, in a relative order RandomOracle controls. Swept over seeds 0-15, it reliably produces both outcomes, and the first failing seed reproduces identically on direct replay.
…uction Give S4's Arrival stub a real producer (RFC 0003 3.6, S13): simProducerPost (chronos/internal/asyncengine.nim, both platform forks) pushes onto the same real cross-thread MPSC threadCallbacks queue and waking flag doCallSoonCrossThread already uses - MpscQueue push/pop are plain atomics, sound single-threaded by construction - and schedules one Arrival SimEvent only on the false-to-true waking transition, the same "one wakeup per batch of pushes" invariant a genuine cross-thread post relies on. A post landing before a still-pending arrival's delivery joins it instead of minting a second one: 3.6's coalescing constraint is a legality rule enforced at push time, not a choice decideBatch is free to make, so the harness can never report a failure under a schedule the real protocol could not produce. simScheduleArrival (simengine.nim) keeps its S4 shape unchanged and stays a bare marker; the actor identity and payload travel through the co-scheduled MPSC queue instead of the SimEvent itself. chronos/simulation.nim's SimProducer/simProducer()/post() wrap this as the public surface, platform-neutral - the machinery is dispatcher-level (a queue and a flag), not seamed I/O, so it needs no POSIX/Windows split the way SimNet's stream/datagram accessors do. Reproducing upstream status-im#703's literal shape took a different route than a byte-for-byte port of tests/testsoon.nim's old bool-latch test. Two posts scripted back to back with nothing between them always legally coalesce into one arrival (3.6 forbids the oracle from splitting them), so that shape alone can never go RED under a sound implementation. The genuine reproduction is tests/testsimulation.nim's S9a fixture pattern, now with a real actor instead of its readiness-event stand-in for "producer": an independent reaper races the producer's arrival to be observed by a single, unrepeated check, and decideBatch's shuffle of the two events sharing one batch decides whether the reaper's callback fires before or after the producer's - order RandomOracle genuinely varies per seed. That fixture's own docstring records the literal repro as barred until simProducer existed; this slice supplies it. tests/testsimproducer.nim: "simProducer basics" (single post delivers after one poll iteration; two posts before any poll coalesce into one Arrival, checked across a full sweep since coalescing must hold for every seed, not just some). "simProducer arrival races" is the headline: the pre-status-im#703 shape (bool latch, single unrepeated check) fails at some seeds and passes at others in a 0..15 sweep, the first failing seed's own recorded trace replays the identical failure through ReplayOracle (independent of RandomOracle(seed) - RFC 0003 3.7's payoff), and the status-im#703 fix shape (the reaper re-arms and re-checks across iterations instead of trusting one snapshot) passes every seed. "drain-path coverage" sweeps three readiness events plus a two-post-coalesced arrival delivered in one batch, confirming every callback fires exactly once regardless of decideBatch's chosen order. Registered in testall and both nimble simLeafTests lists. No decision payload shape changed, so the S5 digest-regeneration exception is not used. Verified: testall define-off (refc/orc) 730/725 OK 0 FAILED; sim (refc/orc, testall plus all eleven leaf suites including testsimproducer) 0 FAILED everywhere; check_windows clean (0 Error lines); a no-strip release build of a plain `import chronos` consumer shows zero sim symbols, simProducerPost included.
The cross-thread callSoon test added in #694 has a race that leaves a callback queued after the test returns, carrying a pointer into the test's dead stack frame. On linux-i386 CI this aborts
testallwith*** stack smashing detected ***at the start of the timers suite, at a rate of roughly one run in ten. On other targets the same write lands silently.The test takes
addrof a stack-local flag, spawns a thread that posts two cross-thread callbacks with that pointer, and callspoll()once, without joining the thread first:wakingflag and wakes the loop; the second push sees the flag still set and skips the wake, as designed.processThreadCallbacksclearswakingand then drains the MPSC queue. If the drain lands between the two pushes, it moves only the first callback; the second push then re-arms the wake and stays queued for the next poll cycle.poll()runs callback one, the flag reads true, the check passes, and the test returns. The frame that owned the flag is gone.poll()anywhere in the process fires the leftover callback, which writestruethrough the dangling pointer.In
testall, the next poll is the timers suite's firstwaitFor. On linux-i386 the written byte lands on thatwaitForframe's stack canary, which is what the CI failures show:stack smashing detected, SIGABRT, traceback ending attesttime.nimtestTimer, always at timers-suite entry, on both Nim 1.6 and devel.Diagnosis is from a core dump of the faithful CI build (
nimble testfirst config plus-g, no other changes, no debugger attached, looped on a CI runner until it crashed): the canary slot held0x59014c00against a per-thread canary of0x59104c00read intact from neighboring frames, a single byte changed from0x10to0x01at canary offset 2, with the adjacent frame-trace record untouched. A one-byte0x01store through a stale pointer is exactlyflag = true.Whether the stray write crashes depends on where the byte lands, which varies with binary layout, so the crash itself comes and goes across otherwise-unrelated commits. Instrumenting the test settles the question directly: resetting the flag after the existing check and giving the loop one more spin before the frame dies shows the second callback stranded in 19 of 500 runs of the otherwise unmodified test at master (b71392a), on x86_64. The race is in the test as written; linux-i386 is merely where the consequence is visible.
The fix makes the test deterministic: count the callbacks instead of latching a bool, join the thread before polling so both posts are visible to the drain, and poll until both have run. Nothing queued can then outlive the frame it points into, and the test now fails loudly if either callback is dropped, which the old bool could not detect. Verified with 40 consecutive clean runs of the standalone binary and 120 clean iterations of the previously-crashing linux-i386 CI loop on the fixed commit (https://github.com/coreyleavitt/chronos/actions/runs/31351631105); the same loop on unfixed commits crashes within 8 to 55 iterations.
Found while running CI for #702.