Give the debounce tests a margin that survives a loaded runner - #572
Merged
Merged
Conversation
`Write debounced values into DB` and its Raw sibling failed sporadically, most recently on adapter-tests-sqlite (22.x, windows-latest) while the five other SQLite combinations passed; a re-run of the identical commit was green. The same pair is called out as timing-sensitive in #554. The cause is a relationship that was nowhere expressed. The datapoints in preInit() use `debounceTime: 500`, and logSampleData() spaced the values that are supposed to be kept 600 ms apart - a 100 ms margin between two processes. When a state change reaches the adapter late, its debounce timer starts late, the next value arrives before it fires and restarts it, and a value the test expects is swallowed. That is exactly the reported assertion. The check walks the sequence [1, 2.5, 3, 4, 5, 5, 6, 7, 7] and requires every returned value to be <= the current milestone; `4 <= expectedVals[expectedId]` fails when an earlier milestone is missing, so the pointer is still at 2.5 or 3 when the 4 arrives. The two debounce callers now pass the existing waitMultiplier as 2.5, putting the kept gaps at 1500 ms against the 500 ms window while the bursts stay at 50 ms, far inside it. logSampleData() documents what the gaps have to satisfy, so the next person changing either number can see the constraint. `testValueBlocked` deliberately keeps 1.5: its gaps have to stay *below* its blockTime of 1500 ms, so raising them globally would have made that test assert something else. Only the two debounce callers are changed. The sequence now takes ~36 s, so the two tests get 90 s instead of 45 s - the second failure mode in the same CI job was a bare "Timeout of 45000ms exceeded". The blocked test is unchanged at ~30 s against its 45 s. Not verified locally: the integration suite refuses to start while something listens on port 9000, and this machine has a live ioBroker admin there. CI exercises the suite on six SQLite combinations plus the other three dialects. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
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
1 participant
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.
Write debounced values into DBand its Raw sibling fail sporadically. Most recently onadapter-tests-sqlite (22.x, windows-latest)in #569 while the five other SQLite combinations passed — and a re-run of the identical commit was green. The same pair is called out as timing-sensitive in #554.The cause is a relationship nobody wrote down
The datapoints in
preInit()usedebounceTime: 500.logSampleData()spaced the values that are supposed to be kept 600 ms apart.A 100 ms margin, between two processes. When a state change reaches the adapter late, its debounce timer starts late, the next value arrives before it fires and restarts it, and a value the test expects is never stored. The two numbers live in different functions, so nothing made that constraint visible.
That is exactly the reported assertion. The check walks the sequence
[1, 2.5, 3, 4, 5, 5, 6, 7, 7]and requires every returned value to be<=the current milestone:This can only fire when an earlier milestone is missing — the pointer is still at 2.5 or 3 when the 4 arrives.
The fix
The two debounce callers pass the existing
waitMultiplieras2.5: kept gaps go to 1500 ms against the 500 ms window, bursts to 50 ms, still far inside it.logSampleData()now documents what the gaps have to satisfy.testValueBlockedis deliberately left alone. It passes 1.5, which puts its gaps at 900 ms — below itsblockTimeof 1500 ms, which is the point of that test. Raising the gap globally would have quietly made it assert something else. This is the trap in the obvious fix, and why the multiplier is set per caller rather than inlogSampleData.The sequence now takes ~36 s, so those two tests get 90 s instead of 45 s. The second failure mode in the very same CI job was a bare
Timeout of 45000ms exceeded.Write with 1s block valuesWhat is not verified, and one trap found on the way
I could not run the suite locally.
test/lib/setup.jsprobes port 9000 and bails out when something answers; this machine has a live ioBroker admin there, and stopping it is not mine to do. CI exercises this on six SQLite combinations plus MySQL, PostgreSQL and MS SQL.Worth knowing: that guard calls
process.exit(0). A run blocked by it reports success — mocha exits 0 having executed nothing. That is how it looked to me at first. Not a problem in CI, where nothing listens on 9000, but it can make a local "green" meaningless.One failure this does not explain. An earlier local run lost nearly everything — 2 of ≥9 expected values, both after the 10 s relog wait. That is not a 100 ms boundary effect, and I have not established what it was. The fix addresses the margin, which is the mechanism the CI failure demonstrates; it may not be the whole story.
🤖 Generated with Claude Code