Skip to content

test: detect and reconnect when the server stops reading the bot socket - #4018

Closed
u9g wants to merge 4 commits into
masterfrom
test/login-stall-detector
Closed

test: detect and reconnect when the server stops reading the bot socket#4018
u9g wants to merge 4 commits into
masterfrom
test/login-stall-detector

Conversation

@u9g

@u9g u9g commented Aug 27, 2026

Copy link
Copy Markdown
Member

CI occasionally fails a whole version with 40+ Event move did not fire errors right after the before hook (e.g. 1.19.3 in https://github.com/PrismarineJS/mineflayer/actions/runs/33027267332). The server log for those runs shows zero [flatbot: ...] command feedback and flatbot lost connection: Timed out exactly 30s after login.

Root cause (vanilla server ≤1.20.1, not mineflayer): Connection.sendPacket calls channel.config().setAutoRead(false) on the main thread for each PLAY packet sent while the channel attr still says LOGIN (the whole placeNewPlayer burst), and queues doSendPacket → setProtocol → setAutoRead(true) on the netty IO thread. Netty re-arms OP_READ only on a 0→1 transition of the autoRead flag, but the queued clearReadPending drops it unconditionally. With ≥2 doSendPacket tasks pending when the main thread flips the flag, the channel ends up autoRead=true with OP_READ off, nothing in PLAY ever calls read() again, and ReadTimeoutHandler(30) kills the connection. Reproduced locally at ~1% of logins under CPU load (10% with Connection DEBUG logging); the bot's bytes sit unread in the server's kernel Recv-Q. 1.20.2+ moved the protocol switch onto the IO thread (MC-265209), so only ≤1.20.1 is affected. Nothing the client sends can re-arm the read, so the only fix is to detect it and reconnect.

Detection: console commands still reach the bot, so op succeeds. The server's first reaction to anything the bot sent is echoing its settings skinParts (127) in that bot's own entity_metadata, ~160ms after login (max 1.45s under load), never on a stalled connection.

Where it's applied — every bot the suite creates, since the stalls actually hit in CI were not flatbot's (the inventory example child on 1.17.1, spawnbot on 1.19.3), each burning a 90s mocha timeout:

  • before hook: after op succeeds, require flatbot's own echo (3s grace), otherwise deop, end the bot and log in again.
  • bot.test.serverReads(username) in testCommon.js polls the joined bot's entity metadata for the echo. runExample uses it after the child has been teleported into view; a stalled child is killed and relaunched under the same name, which makes the server kick the dead session.
  • spawnEvent: spawnbot logs in at the world spawn, which on ≤1.17 superflat worlds is hundreds of blocks from flatbot, so its entity (and metadata) is never in view. It sends a chat line instead, which the server only broadcasts once it has read that socket; if flatbot doesn't get it within 3s the bot is ended and recreated. Three attempts each.

Zero cost on healthy logins (the echo normally lands before the op message / the child's arrival the tests already wait on).

Validation

  • 1.19.3: 0/498 false positives on healthy logins under load; healthy suite 72/72; with settings deliberately dropped on the first login, the hook reconnected and the suite passed 72/72.
  • exampleBee, exampleInventory on 1.16.5 and 1.21.8: pass, no gate trips.
  • spawnEvent on 1.8.8, 1.16.5, 1.19.3, 1.21.8 (spawnbot logging in 100–400 blocks away on the first two): pass, single login each.
  • Forced paths on 1.16.5: spawnbot chat suppressed on attempt 1 → gate tripped at 3s, attempt 2 passed; runExample with a forced stall on attempt 1 → child killed, relaunched, exampleInventory passed.

@rom1504

rom1504 commented Aug 28, 2026

Copy link
Copy Markdown
Member

CI fails

@u9g
u9g force-pushed the test/login-stall-detector branch from 15925d1 to 993e937 Compare August 29, 2026 14:11
@rom1504

rom1504 commented Aug 30, 2026

Copy link
Copy Markdown
Member

Ok I don't understand the one, will come back to it

// commands still reach that bot, so this echo is the only proof of life.
async function serverReads (username, timeoutMs = 3000) {
const deadline = Date.now() + timeoutMs
while (Date.now() < deadline) {

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't like this active wait loop. Can we use an event instead?

@u9g
u9g force-pushed the test/login-stall-detector branch from 1e21ccb to 332d031 Compare September 4, 2026 18:18
u9g and others added 4 commits September 4, 2026 17:11
The vanilla server (1.7 through at least 1.21.8) can lose netty read
interest on a connection during the login burst: Connection.sendPacket
calls setAutoRead(false) on the main thread for every PLAY packet sent
while the channel still says LOGIN and queues setAutoRead(true) on the
IO thread. Netty only re-arms OP_READ on a 0->1 transition but drops it
unconditionally on the queued clearReadPending, so with two or more
doSendPacket tasks pending when the main thread flips the flag the
socket ends up with autoRead=true and OP_READ off. Nothing in the PLAY
state ever calls read() again; the server reads nothing from the bot
until ReadTimeoutHandler(30) kills the connection.

Reproduced locally at ~1% of logins under CPU load (10% with Connection
DEBUG logging on). Console commands still reach the bot, so `op`
succeeds and the whole version then fails with "Event move did not
fire" from resetState after the 30s kick.

The server echoing our skinParts (127) in our own entity_metadata is its
first reaction to anything the bot sent; it lands ~160ms after login
(max 1.45s under load) and is never sent on a stalled connection. Wait
for it once `op` has succeeded and reconnect if it never comes.
…socket

The stalls hit in CI were not flatbot's: the inventory example child on
1.17.1 and spawnbot on 1.19.3 each logged in, never had a byte read, and
burned a 90s mocha timeout before the server dropped them. The before-hook
detector only guards flatbot.

Poll the joined bot's entity_metadata for the skinParts echo (127) that the
server only sends after reading that socket. runExample kills a stalled
child and relaunches it, which makes the server kick the dead session;
spawnEvent ends and recreates spawnbot. Three attempts each.
spawnbot logs in at the world spawn, which on <=1.17 superflat worlds is
hundreds of blocks from flatbot, so flatbot never sees its entity and the
metadata gate reported a stall on every attempt. Teleporting it into view
first is not reliable either: the 1.8 entity tracker did not surface the
teleported player within the window. A chat line from spawnbot reaching
flatbot needs neither and is only broadcast once its socket was read.
@u9g
u9g force-pushed the test/login-stall-detector branch from 332d031 to 39a136a Compare September 4, 2026 21:11
@github-actions

github-actions Bot commented Sep 4, 2026

Copy link
Copy Markdown
Contributor

Tests more than 1.5x slower than master (durations are noisy, so this is informational):

   5126ms ->   11027ms  mineflayer_external 1.11.2v nether
   5778ms ->   12635ms  mineflayer_external 1.19v exampleBee

@u9g

u9g commented Sep 6, 2026

Copy link
Copy Markdown
Member Author

Let’s just close this for now

@u9g u9g closed this Sep 6, 2026
@u9g

u9g commented Sep 6, 2026

Copy link
Copy Markdown
Member Author

I’m not saying it’s fixed, but if it becomes serious we can use this fix, as of now it’s a rare situation

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants