Connect: stale `init_handshake_complete` lets a heartbeat race the handshake on reconnect (1008 connect_worker_hello_invalid_msg)

[kuba415]

Summary

On every reconnect there is a window in which HeartbeatHandler can send WORKER_HEARTBEAT on a freshly-opened WebSocket before WORKER_CONNECT has been sent. The gateway closes the connection with 1008 policy violation connect_worker_hello_invalid_msg, and the SDK logs Connection closed abnormally at ERROR.

It's non-fatal — the reconnect loop recovers about a second later — but it's an ERROR-level log from a healthy worker, which means anything wired to ERROR logs (Sentry's LoggingIntegration, in our case) raises an alert for a connection that is fine.

The SDK already anticipates this exact string, in heartbeat_handler.py:

# We can't send heartbeats until the handshake is complete. Doing so
# isn't fatal, but will result in "connect_worker_hello_invalid_msg"
# logs
await self._state.init_handshake_complete.wait_for(True)

The guard is correct; it just isn't reset when the connection it describes goes away.

Root cause

init_handshake_complete survives the connection it belongs to. On main:

1. models.py L46-54 — State.close_ws() clears conn_init and ws, and sets conn_state to RECONNECTING, but leaves init_handshake_complete at True.
2. init_handshake_handler.py L106 — it's only reset to False when the new GATEWAY_HELLO arrives.
3. heartbeat_handler.py L55-70 — the sender loop is wait for flag → wait for a non-None ws → send → sleep(10). On a reconnect it sails through the stale True, and ws.wait_for_not_none() returns the moment run() assigns the new socket — which happens before the handshake, inside the POST_CONNECT_SETTLE_SEC window.

So if the heartbeat's 10s tick elapses while the socket is being replaced, the first frame on the new connection is a heartbeat rather than WORKER_CONNECT.

It self-corrects: after the 1008 the sender is mid-sleep(10), so the next reconnect has a clear window. That's why it shows up as an isolated error rather than a loop.

Evidence

Production worker on ECS Fargate, inngest[connect]==0.5.18, CPython 3.12.14, connection had been up 13 hours (so: a gateway drain, not a deploy):

18:22:19.544  POST https://api.inngest.com/v0/connect/start  200
18:22:19.629  Connection closed abnormally                        <- 85 ms later
              received 1008 (policy violation) connect_worker_hello_invalid_msg;
              then sent 1008 (policy violation) connect_worker_hello_invalid_msg
18:22:20.654  POST https://api.inngest.com/v0/connect/start  200   <- recovered, 1.03 s
19:03:53.606  POST https://api.inngest.com/v0/connect/start  200   <- later reconnect, clean

85 ms after asking for a gateway endpoint is too early for the handshake to have completed. Frequency looks like roughly (handshake window ÷ 10s heartbeat period): 1 of 3 reconnects here, ~1 event/day for us.

A genuinely malformed hello (bad signing key, two transports registered for one app) produces the same close reason, so the two are hard to tell apart from the log alone — which is a second, smaller reason to eliminate the benign source.

Suggested fix

Reset the flag with the connection it describes, in State.close_ws():

def close_ws(self) -> None:
    if self.allow_reconnect():
        self.conn_state.value = ConnectionState.RECONNECTING
    self.conn_init.value = None
    self.ws.value = None
    self.init_handshake_complete.value = False

That makes the invariant "the flag is only True while a handshake-complete socket is live" hold for the socket's whole lifetime, rather than from the next GATEWAY_HELLO onward. init_handshake_handler.py L106 then becomes belt-and-braces rather than the only reset.

Versions

Reproduced on 0.5.18. Verified by reading the source that the same window exists in 0.5.19 and on main — 0.5.19 refactored _heartbeat_sender to resolve the socket inside safe_send (which addresses the stale socket problem from #261), but the stale flag is unchanged.

Happy to open a PR if the suggested fix looks right to you.