fix(runner): check the polling deadline after the attempt, not instead of it - #45
Open
monikon22 wants to merge 2 commits into
Open
fix(runner): check the polling deadline after the attempt, not instead of it#45monikon22 wants to merge 2 commits into
monikon22 wants to merge 2 commits into
Conversation
…d of it
Every polling helper was shaped `while (Date.now() < deadline) { attempt; sleep }`,
so the loop could exit on the clock without ever looking at what arrived during
the last sleep. The value is in the buffer, the wait reports a timeout, and the
log reads "the confirmation arrived and it timed out anyway".
The window is not the 50ms it looks like. A bot loading chunks blocks the event
loop for seconds; the socket data flushes in one batch when it unblocks, and the
sleep timer that was already pending resolves past the deadline. Under that stall
the AuthMe preflight failed with `did not confirm registration in time` on a run
whose log shows `Successfully registered!` five messages before the failure was
printed.
The loops now check the deadline after the attempt, so the last thing each does
before giving up is look one more time. `poll`, `waitForAssertion` and `waitUntil`
in utils, `pollAssertion` and `pollUntilPass` in matchers — the same omission in
all five. `waitForStable` already had the right order and is untouched.
One deliberate consequence: a helper called with a timeout of zero now makes one
attempt rather than none, which is what "poll until the deadline" should have
meant.
`_registerPersistentListeners` captured `username` into a local and printed that local on every chat line. `username` is `bot.username`, which mineflayer leaves undefined until the client is through the handshake, so the listeners could go up holding nothing and every message afterwards read "[Bot undefined]". Those are the lines worth reading when a login wall misbehaves, so it cost exactly where it hurt. `_captureSpawnPromise` already reads the name lazily for this reason; these three log calls now do the same.
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 one stands alone. It fixes a bug that is already on
master, it does not depend onanything else, and it can be merged on its own.
It came out of a larger piece of work, proposed separately in #46 — that issue needs a
decision from you, this PR does not.
The bug
Every polling helper is shaped like this:
The loop can exit on the clock without ever looking at what arrived during the last sleep. The
value is sitting in the buffer, the wait reports a timeout, and the log reads as though the
confirmation arrived and the wait ignored it.
That final window is not the 50 ms it looks like. A bot loading chunks blocks the event loop for
seconds; the socket data flushes in one batch when it unblocks, and the
sleeptimer that wasalready pending resolves past the deadline. Under that stall an AuthMe login test failed with
did not confirm registration in timeon a run whose own log showsSuccessfully registered!five messages above the failure.
The change
The deadline is now checked after the attempt, so the last thing each helper does before
giving up is look one more time. Same one-line omission in five places:
runner-package/lib/utils.ts—poll,waitForAssertion,waitUntilrunner-package/lib/matchers.ts—pollAssertion,PollMatchers.pollUntilPasswaitForStablealready had the right order and is untouched. Its second loop deliberately checksthe clock first, since "stay true for the whole duration" should stop at the end of the window.
One deliberate consequence: a helper called with a timeout of zero now makes one attempt rather
than none. That is what "poll until the deadline" should have meant.
The second commit is unrelated but tiny, and in the same corner.
_registerPersistentListenerscaptured
usernameinto a local before the handshake finished, so bot chat lines could print[Bot undefined]— including every line a login wall produces, which are the ones worth readingwhen authentication misbehaves.
_captureSpawnPromisealready reads the name lazily for exactlythis reason; the three log calls now do the same.
On evidence
I want to be straight about this: the failure is a race, and I could not make it fail on demand.
The argument is the log ordering — at the instant
pollthrew, the matching message was alreadyin the buffer, and the path from that throw to the printed failure crosses only microtasks — plus
an isolated repro of the old and new
pollover the same input, where the old one throws and thenew one resolves. The suite passes before and after.