test(backend): stop re-stubbing DateProvider while a released-data stream is in flight - #7161
Draft
corneliusroemer-agent wants to merge 1 commit into
Draft
corneliusroemer-agent wants to merge 1 commit into
corneliusroemer-agent wants to merge 1 commit into
Conversation
…ream is in flight
GetReleasedDataEndpointWithDataUseTermsUrlTest moved time by calling
`every { dateProvider.getCurrentInstant() } answers { ... }` mid-test. MockK
installs the matcher first and the answer second, so between the two there is a
matching stub whose answer is null. A matching stub means `relaxed = true` is
never consulted, so any other thread invoking the method in that window gets
`MockKException: no answer provided`. The other thread existed because the test
read an ETag off `getReleasedData()` without awaiting the response, leaving the
StreamingResponseBody running on the async executor.
Worse, that exception is thrown from inside the mock, which leaves MockK's
shared call recorder in SafeLoggingState. The next mock call on the test thread
then fails with "No other calls allowed in stdObjectAnswer", the request 500s,
and the test reports `expected:<200> but was:<500>`. Seen once in CI run
32856832097; reproduced locally 2/20 with the stubbing window widened by 3 ms,
0/100 after this change.
Answers are now installed once when the bean is created and tests only flip a
@volatile field, so no answerless stub ever exists. `relaxed` is dropped since
all three DateProvider methods are stubbed. The released-data responses whose
bodies these tests discard are now awaited too, so no stream is left running
into the next test's TRUNCATE.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
This is Claude's attempt to fix a really weird/complicated flake. Not sure this is the way to go, but it might be right that we have a bug in how things are set up - I just suspect there's an easier way out here.
Details
GetReleasedDataEndpointWithDataUseTermsUrlTestfails intermittently in CI withStatus expected:<200> but was:<500>in the test about expired restricted data use terms. Seen in run 32856832097; it was only diagnosable because that run archived the JUnit XML.What actually happens
The test changed the current time by re-running
every { dateProvider.getCurrentInstant() } answers { ... }in the middle of the test. MockK does that in two steps: recording theevery { ... }block adds an entry to the mock's answer list, and theanswers { ... }call then fills in what that entry should return. In between there is an entry that matches the call but has no answer yet, and anything calling the method in that window getsMockKException: no answer provided. Because the entry matches,relaxed = truenever comes into play, which is why a relaxed mock did not protect against this.Something else was calling the method at that moment. Two statements earlier the test reads an ETag off
getReleasedData()without waiting for the response body.get-released-datais a streaming endpoint, so the body keeps running on a background thread after the test moves on — 8-9 ms in that CI run, long enough to overlap. It hit the empty answer entry while building the data use terms for a record.That exception on its own is harmless: the controller catches errors during streaming and writes them into the response body, and this response was being thrown away anyway. The damage is indirect. The exception was thrown from inside the mock, which left MockK's call recorder — shared across threads — stuck in a logging mode. One millisecond later the test thread computed the ETag for the next request, called the same mock, got
No other calls allowed in stdObjectAnswerinstead of a date, and the request came back as a 500.The change
Answers are installed once when the mock bean is created, and the tests now move time by writing to a
@Volatilefield that the answer reads. Nothing is stubbed after the Spring context is up, so the window with a matching-but-empty answer no longer exists at any point, on any thread. This is a stronger guarantee than making the test wait for the background work: waiting would only shrink a window that is microseconds wide.relaxed = trueis dropped.DateProviderhas three methods and all three are stubbed, so strict mode now fails loudly if someone adds a fourth, rather than quietly returning a made-up value.Separately, the streamed responses whose bodies these tests discard are now waited for. A stream still running when the next test starts also races the
TRUNCATEthat clears the tables between tests, which has no lock or statement timeout — a hazard worth closing even though it is not what broke this test.Non-obvious things worth knowing
Faking
getCurrentInstant()alone is enough to move the whole clock:getCurrentDateTime()andgetCurrentDate()are answered withcallOriginal(), and MockK intercepts the calls the real implementations make back into the mock. The test that asserts the ETag changes on the date alone is what proves this still works.This flake needs a loaded machine. On its own the test class is far too fast to hit it — I ran the test 60 times in a row without a single failure, and measured why: with one record the background stream finishes in well under a millisecond, so it is long gone by the time the test re-stubs. Six full-suite runs did not reproduce it either. To show the mechanism I widened the gap between
everyandanswersby 3 ms and had a background thread call the date provider: 2 failures in 20, with exactly theexpected:<200> but was:<500>signature from CI, and none in 120 runs after this change. Six clean full-suite runs before and five after prove nothing on their own — the argument for the fix is that the failure mode is now structurally impossible, not that the tests went green.Two things this is not, both ruled out from the stack traces: it is not a scheduled background job (the two that use the date provider have initial delays of one hour and fifteen minutes, so neither runs during a test), and it is not state leaking in from another test class (the trace names this class's own mock bean and its own request).
Nothing else in the test suite mocks
DateProvider, so the same bug cannot be lurking elsewhere. The same shape — stubbing a mock while a request is still streaming — could apply to thekeycloakAdapterstubbing in the sibling classes, but nothing on the released-data path calls it, so I left those alone.🚀 Preview: Add
previewlabel to enable