Skip to content

Server: spurious "no draft matches" (1002) close fired on an already-open connection, from a different thread than the one that accepted it #1511

Description

@Maxxxtreme

Environment

  • Java-WebSocket version: 1.6.0 (latest at time of writing)
  • Used as the transport layer inside a third-party OCPP library (eu.chargetime.ocpp /
    WebSocketServer subclass), with a 4-thread WebSocketWorker pool (default configuration,
    decodercount = 4)
  • Server registers a single Draft_6455 instance with a configured subprotocol list
    (["ocpp2.0.1", ""]) and no custom extensions (library auto-adds DefaultExtension)
  • JDK: Eclipse Temurin 24 (server-side), running in a Kubernetes pod behind a TLS-terminating
    reverse proxy (Envoy) that forwards plaintext WebSocket traffic to the application
  • Client: a Node.js ws-based WebSocket client, connecting over TLS through the proxy above

Summary

We are intermittently seeing a connection get accepted, fully complete its WebSocket handshake
(including subprotocol negotiation), have onOpen fire and be handed off to our application code -
and then, roughly 100 microseconds later, get closed by the server with code 1002 and reason
"no draft matches", without any second HTTP handshake ever being parsed for that connection.

This happens for maybe 20-50% of connection attempts in our environment (highly variable, we have
not found a reliable way to force it on demand), and results in the client observing an abnormal
closure (code 1006) despite having just successfully connected.

What we've confirmed via TRACE-level logging

We instrumented org.java_websocket at TRACE level and captured the following sequence for a
single, real failing connection (headers/IDs redacted, timestamps in server-local time with
nanosecond precision from our own structured logging - not part of Java-WebSocket itself):

[WebSocketWorker-76] TRACE WebSocketImpl - process(759): (GET /ocpp2.0/<redacted> HTTP/1.1
host: <redacted>
sec-websocket-version: 13
sec-websocket-key: <redacted>
connection: Upgrade
upgrade: websocket
sec-websocket-extensions: permessage-deflate; client_max_window_bits
sec-websocket-protocol: ocpp2.0.1
...
)
[WebSocketWorker-76] TRACE Draft_6455 - acceptHandshakeAsServer - Matching extension found: DefaultExtension
[WebSocketWorker-76] TRACE Draft_6455 - acceptHandshake - Matching protocol found: ocpp2.0.1
[WebSocketWorker-76] TRACE WebSocketImpl - write(247): HTTP/1.1 101 Web Socket Protocol Handshake
Connection: Upgrade
...
Sec-WebSocket-Protocol: ocpp2.0.1
Server: TooTallNate Java-WebSocket
Upgrade: websocket

[WebSocketWorker-76] TRACE WebSocketImpl - open using draft: Draft_6455 extension: DefaultExtension protocol: ocpp2.0.1 max frame size: 2147483647
[WebSocketWorker-76] DEBUG (application) - On connection open (resource descriptor: /ocpp2.0/<redacted>)
[WebSocketWorker-76] INFO  (application) - Creating new session ...
[WebSocketSelector-79] DEBUG (application) - On connection close (resource descriptor: /ocpp2.0/<redacted>, code: 1002, reason: no draft matches, remote: false)
[WebSocketSelector-79] TRACE WebSocketImpl - send frame: Framedata{ opcode:CLOSING, ... } code: 1000
[WebSocketSelector-79] TRACE Draft_6455 - afterEnconding(2): ...
[WebSocketSelector-79] TRACE WebSocketImpl - write(4): ...

Key observations:

  1. The handshake headers are valid (Sec-WebSocket-Version: 13, Sec-WebSocket-Protocol: ocpp2.0.1), and Draft_6455.acceptHandshakeAsServer explicitly logs a successful match for
    both extension and protocol.
  2. open(...) is called, onOpen fires, and our application code receives and begins processing
    the new session - all on thread WebSocketWorker-76.
  3. Approximately 100 microseconds later, a different thread - WebSocketSelector-79, which by
    naming convention (WebSocketServer.doSetupSelectorAndServerThread()) is the single NIO
    selector thread, distinct from the WebSocketWorker pool that performs handshake
    decoding/matching - closes the same connection (same resource descriptor) with code 1002
    and reason "no draft matches".
  4. Critically, WebSocketImpl.decode(ByteBuffer) unconditionally logs a "process(N): (...)" TRACE
    line on every invocation (before even checking readyState). We only ever see one such
    line for the connection above - meaning decodeHandshake() (the only code path that can produce
    the "no draft matches" log message / InvalidDataException) was never invoked a second time
    for this connection. Yet the close event carries exactly that reason string.

This rules out (at least in our case) a genuine second/duplicate handshake attempt for the same
socket, a multi-draft ambiguity (we only register one draft), and any application-level session
bookkeeping issue on our side (the handshake match is real and logged as such).

Suspected area (not confirmed as root cause)

We have not been able to pin this down to a single line with full confidence, and would appreciate
maintainer input, but the area we find most suspicious is the handoff between the selector thread
and the worker-thread pool in WebSocketServer:

  • doRead() reads bytes on the selector thread and calls queue(conn), which does
    ws.getWorkerThread().put(ws) - handing the connection object itself to a WebSocketWorker's
    BlockingQueue<WebSocketImpl>.
  • WebSocketWorker.run() does ws = iqueue.take(); buf = ws.inQueue.poll(); assert(buf != null); doDecode(ws, buf);. Note poll() is non-blocking and can return null, and assert is a no-op
    in a production JVM (assertions disabled by default) - so if ws is ever queued to a worker
    before (or without) a corresponding buffer being available in ws.inQueue, this would silently
    proceed with buf == null into doDecode/decode.

We are not confident this is the actual mechanism (we were not able to correlate an exception/log
line matching this exact path in our captures), but it's the most plausible shared-state or
ordering issue we could identify between the selector thread and the worker pool for an
already-opened connection.

Reproduction

Unfortunately we have not been able to build a minimal, reliable, on-demand reproduction. It
occurs intermittently (20-50% of attempts) only in our real deployed environment (client connecting
over a WAN-ish network path through a TLS-terminating reverse proxy), and we were unable to
reproduce it at all in ~100 local attempts using a direct, unproxied, low-latency loopback
connection to the same server code, with various injected latency/TLS-termination conditions we
could simulate locally. This suggests some degree of network-timing sensitivity, but since the
defect appears to require a second, distinct decode-dispatch event that we can't find independent
evidence of, we suspect it may also depend on JIT warmup, GC pauses, or other JVM-level scheduling
jitter under the worker thread pool that are hard to force deterministically.

We're happy to test any proposed patch against our environment, understanding it may take several
attempts (dozens of connection attempts per test) to get a statistically meaningful signal, given
the intermittent nature.

Impact

For us, this causes charging station (IoT device) WebSocket connections to occasionally fail
immediately after what was, by all visible evidence, a fully successful handshake - requiring the
client to reconnect. We've mitigated the resulting NullPointerException and incorrect
online/offline status flapping on our own application side, but the underlying spurious
disconnect/reconnect itself can only be fixed in this library.

Any guidance on where else to look, or whether this rings a bell as a known issue, would be very
much appreciated.

Activity

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

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions