test(utilities): report why the continuous-mode wait timed out - #19485
test(utilities): report why the continuous-mode wait timed out#19485rangareddy wants to merge 1 commit into
Conversation
hudi-agent
left a comment
hudi-agent
left a comment
There was a problem hiding this comment.
Thanks for working on this! The PR makes the flaky continuous-mode waitTillCondition diagnosable by attaching the condition's last error to a timeout, stops the misleading "Condition completed successfully" log on failed polls, and shuts down the polling executor. A couple of things worth double-checking in the inline comments — how the polling thread responds to the new shutdown, and the timing margin in the new test. Please take a look at any inline comments, and this should be ready for a Hudi committer or PMC member to take it from here.
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## master #19485 +/- ##
=========================================
Coverage 77.49% 77.49%
Complexity 32799 32799
=========================================
Files 2522 2522
Lines 139179 139179
Branches 16734 16734
=========================================
+ Hits 107855 107863 +8
+ Misses 23748 23741 -7
+ Partials 7576 7575 -1
Flags with carried forward coverage won't be shown. Click here to find out more. 🚀 New features to boost your workflow:
|
hudi-agent
left a comment
hudi-agent
left a comment
There was a problem hiding this comment.
Thanks for working on this! This PR improves the diagnosability of the flaky testUpsertsContinuousModeWithMultipleWritersForConflicts timeout by having waitTillCondition retain and surface the last error the condition threw, shutting down its per-call polling executor, and having deltaStreamerTestRunner surface a streamer crash instead of the misleading "should have shutdown by now" failure. I traced the interrupt handling, the try/finally executor cleanup, the AtomicReference visibility, the exception-type change (verified no caller depends on the old TimeoutException), and the guarded dsFuture.get() in the caller — all paths check out, and the two issues raised in the prior round appear addressed. No new issues flagged from this automated pass — a Hudi committer or PMC member can take it from here for a final review.
cc @yihua
541e7bb to
ae2e970
Compare
hudi-agent
left a comment
hudi-agent
left a comment
There was a problem hiding this comment.
Thanks for working on this! This PR improves the diagnosability of the long-standing flaky testUpsertsContinuousModeWithMultipleWritersForConflicts (HUDI-6843): waitTillCondition now attaches the last condition error to timeout failures, stops the misleading success log on failed polls, shuts down the previously-leaked polling executor, and deltaStreamerTestRunner surfaces a dead streamer future eagerly. I traced the caller chains (multi-writer conflict handling and the graceful post-write-termination shutdown path in HoodieStreamer/HoodieIngestionService), the exception-type change from TimeoutException to AssertionError, and the new dsFuture.get() guarded by isDone() - all consistent and safe. No correctness issues found. A few style/readability suggestions in the inline comments. Please take a look, and this should be ready for a Hudi committer or PMC member to take it from here. - a Hudi committer or PMC member can take it from here for a final review.
. Code looks clean overall — a few very minor observations below.
cc @yihua
| res.get(timeoutInSecs, TimeUnit.SECONDS); | ||
| } catch (TimeoutException e) { | ||
| Throwable last = lastError.get(); | ||
| throw new AssertionError(String.format( |
There was a problem hiding this comment.
🤖 nit: the nested ternaries inside the AssertionError constructor are a little hard to parse at a glance — might be cleaner to compute cause and detail as local variables before the throw.
There was a problem hiding this comment.
Done in 1d01b62 — cause and detail are locals now:
} catch (TimeoutException e) {
Throwable last = lastError.get();
String detail = last == null
? "The condition returned false without throwing, so there is no further detail."
: "The last failure it reported was: " + last;
Throwable cause = last == null ? e : last;
throw new AssertionError(
String.format("Condition was not met within %d seconds. %s", timeoutInSecs, detail), cause);
}Reads better, and it makes the two branches independently obvious: the message explains the absence of detail, while the cause falls back to the TimeoutException so the failure is never thrown with a null cause.
Re-verified after both changes rather than assuming a rename and an extraction were safe: TestWaitTillCondition 4 green, checkstyle 0, apache-rat 0. I also re-ran the non-vacuity check by removing just the interrupt handling again, and pollingStopsOnceTheWaitHasGivenUp still fails with expected: <2> but was: <4>, so the extraction did not weaken the test.
Relates to apache#16228 (HUDI-6843). HUDI-6843 has been open since 2023 and every report of it looks identical: java.util.concurrent.TimeoutException at HoodieDeltaStreamerTestBase$TestHelpers.waitTillCondition(...:650) at TestHoodieDeltaStreamer.deltaStreamerTestRunner(...) That is the whole output. waitTillCondition polls the condition and catches Throwable, logging it at debug and discarding it, so when the condition never holds the only symptom is a bare TimeoutException naming the helper rather than the assertion that failed. The flake is unfixable as reported because nobody can tell which of the condition's four assertions never became true. Keep the last Throwable the condition threw and attach it to the failure, so a timeout says what it was still waiting for. Also stop claiming "Condition completed successfully" when the condition returned false, and shut down the polling executor, which leaked a thread on every call and is called by every continuous-mode test. Shutting that executor down needs InterruptedException handled apart from the catch-all. shutdownNow interrupts the polling thread, but Thread.sleep clears the interrupt flag when it throws, so catching it with everything else re-enters the loop. dsFuture never completes in the timeout case, so the loop has no other exit and the thread would poll for the life of the JVM - the shutdown would close nothing in exactly the case it was added for. Restore the flag and break, and check it in the loop condition. An interrupt is not a condition failure, so it is deliberately not recorded as the last error. In deltaStreamerTestRunner, surface a streamer that already failed before calling awaitDeltaStreamerShutdown. That branch never consumed dsFuture, so a dead streamer was reported two minutes later as "Deltastreamer should have shutdown by now", hiding the real cause. The other branch already does this via dsFuture.get(). Four tests for the helper, which had none. pollingStopsOnceTheWaitHasGivenUp counts evaluations after the wait fails and pins that the polling thread stops; with the interrupt handling reverted it reports 4 polls where 2 were expected. This does not stop the test flaking. It makes the next occurrence diagnosable, which is the prerequisite for fixing it.
ae2e970 to
1d01b62
Compare
hudi-agent
left a comment
hudi-agent
left a comment
There was a problem hiding this comment.
Thanks for working on this! This PR makes the flaky testUpsertsContinuousModeWithMultipleWritersForConflicts timeout diagnosable by attaching the condition's last thrown error to the failure, stops the misleading "Condition completed successfully" log on false polls, shuts down the previously-leaked polling executor, and surfaces an early streamer failure instead of a misleading two-minute awaitDeltaStreamerShutdown timeout. I traced the rewritten waitTillCondition (interrupt handling and catch ordering, executor shutdown on all paths, the TimeoutException→AssertionError conversion against its one caller) and the guarded dsFuture.get() in deltaStreamerTestRunner, and found the changes to be a strict improvement with no new correctness issues; the substantive concerns from prior rounds appear addressed. No issues flagged from this automated pass — a Hudi committer or PMC member can take it from here for a final review.
cc @yihua
4 participants
Describe the issue this Pull Request addresses
Relates to #16228 (HUDI-6843), a flaky
testUpsertsContinuousModeWithMultipleWritersForConflicts. Opensince September 2023, and every report of it is this and nothing more:
This PR does not stop the test flaking. It makes the next occurrence diagnosable, which is the
prerequisite for fixing it — and is why the issue has gone three years without progress.
waitTillConditionpolls the condition every two seconds and swallows whatever it throws:The condition for this test asserts four things — delta-commit count, compaction-commit count, record
count and distance count. When one of them never becomes true, the assertion error goes to
debugand isdropped,
res.get(360, SECONDS)expires, and the failure names only the helper. There is no way to tellwhich assertion was still failing, or what value it saw, so no two reports of this flake can be
distinguished and none of them is actionable.
Summary and Changelog
waitTillConditionkeeps the lastThrowablethe condition threw and attaches it to the failure, so atimeout reports what it was still waiting for instead of only that it gave up.
"Condition completed successfully"when the condition returned false — that linefired on every unsuccessful poll, which actively misleads anyone reading the log of a flake.
Executors.newSingleThreadExecutor()was created per call and nevershut down, leaking a thread on every wait; every continuous-mode deltastreamer test goes through here.
InterruptedExceptionis caught ahead of the catch-all so the shutdown actually stops the thread — seethe note under Verification for why the catch-all alone would not.
deltaStreamerTestRunnernow consumesdsFutureif it has already finished, before callingawaitDeltaStreamerShutdown. That branch never consumed the future, so a streamer that died wasreported two minutes later as
"Deltastreamer should have shutdown by now", hiding the real cause. Theother branch already does this via
dsFuture.get().Verification
New
TestWaitTillConditioncovers the helper directly, without Spark:timeoutFailureNamesTheLastConditionFailuresatisfiedConditionReturnsNormallyfinishedStreamerEndsTheWaitWithoutFailingpollingStopsOnceTheWaitHasGivenUpReverting the helper to master's form makes the first test fail with exactly the symptom from the issue,
which is the evidence that it is testing the right thing:
After the change the same scenario reports:
The condition's error is also set as the failure's cause, so the original stack trace survives.
4 tests green (27.4s),
checkstyle:checkandapache-rat:checkclean (Unapproved: 0).Why
InterruptedExceptionis caught separately (raised in review, and the reason for the second committhat is now squashed in): catching it with the catch-all makes the executor shutdown close nothing.
shutdownNow()interrupts the polling thread, butThread.sleepclears the interrupt flag when it throws, sothe catch-all swallowed the
InterruptedExceptionand re-entered the loop.dsFuturenever completes in thetimeout case, so the loop had no other exit and the thread kept polling for the life of the JVM — in exactly
the case the shutdown was added for.
pollingStopsOnceTheWaitHasGivenUppins this: it counts evaluationsafter the wait fails, and with the interrupt handling reverted it reports 4 polls where 2 were expected.
The timeout in
timeoutFailureNamesTheLastConditionFailurewas widened from 3s to 15s for the same reviewround. At one poll interval of slack, a late worker start could leave nothing recorded to report, which would
make a de-flaking test itself timing-sensitive.
The target test itself:
testUpsertsContinuousModeWithMultipleWritersForConflictspasses with thesechanges, run four times over both
HoodieTableTypeparameters — 8 green executions, ~88s per run:The full
TestHoodieDeltaStreamerWithMultiWriterclass also passes — re-run on the squashed commit: 5 tests,0 failures, 107.5s. No flake reproduced in those runs, so this change is not masking one — and had it flaked,
the new failure would have named the assertion that was still failing, which is the whole point.
Impact
Test infrastructure only — no production code. Nothing that passes today starts failing: the only new
failure path is the timeout, which already failed, and the "streamer already finished" case is pinned by a
test specifically to keep it non-failing.
Risk Level
low — test-only, and the behaviour changes are limited to what a failure reports.
Documentation Update
none
Contributor's checklist