Exception in Tomcat when SockJS top URL is a WebSocket upgrade

[ablil]

Creating simple websocke/sompt server

Spring fails to parse HTTP request header, although it sends 200 response to the client and close the connection immediately.

How to reproduce

Download sample code from official guides, then set log level to debug logging.level.root=debug on application.properties.
Run the server, and try connecting with simple JS client code.

JS client

const ws = new WebSocket('ws://dev.contabo:8080/gs-guide-websocket')
ws.on('open', () => {
  console.log("connection opened");
})

ws.on('message', () => {
  console.log('message recieved');
})

ws.on('close', () => {
  console.log('connection closed');
})

ws.on('error', (item) => {
  console.log(item)
})

It gives the following error on the log:

2021-05-11 16:07:12.682 DEBUG 12588 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/chatspace", parameters={}
2021-05-11 16:07:12.687 DEBUG 12588 --- [nio-8080-exec-1] o.s.w.s.s.s.WebSocketHandlerMapping      : Mapped to org.springframework.web.socket.sockjs.support.SockJsHttpRequestHandler@4a68cc76
2021-05-11 16:07:12.693 DEBUG 12588 --- [nio-8080-exec-1] o.s.w.s.s.t.h.DefaultSockJsService       : Processing transport request: GET http://localhost:8080/chatspace
2021-05-11 16:07:12.696 DEBUG 12588 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 200 OK
2021-05-11 16:07:12.701 DEBUG 12588 --- [nio-8080-exec-1] o.a.coyote.http11.Http11InputBuffer      : Before fill(): parsingHeader: [true], parsingRequestLine: [true], parsingRequestLinePhase: [0], parsingRequestLineStart: [0], byteBuffer.position(): [0], byteBuffer.limit(): [0], end: [232]
2021-05-11 16:07:12.701 DEBUG 12588 --- [nio-8080-exec-1] o.a.tomcat.util.net.SocketWrapperBase    : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@56fe2702:org.apache.tomcat.util.net.NioChannel@54ea376e:java.nio.channels.SocketChannel[connected local=/127.0.0.1:8080 remote=/127.0.0.1:50988]], Read from buffer: [0]
2021-05-11 16:07:12.701 DEBUG 12588 --- [nio-8080-exec-1] org.apache.tomcat.util.net.NioEndpoint   : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@56fe2702:org.apache.tomcat.util.net.NioChannel@54ea376e:java.nio.channels.SocketChannel[connected local=/127.0.0.1:8080 remote=/127.0.0.1:50988]], Read direct from socket: [0]
2021-05-11 16:07:12.701 DEBUG 12588 --- [nio-8080-exec-1] o.a.coyote.http11.Http11InputBuffer      : Received []
2021-05-11 16:07:12.702 DEBUG 12588 --- [nio-8080-exec-1] o.apache.coyote.http11.Http11Processor   : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@56fe2702:org.apache.tomcat.util.net.NioChannel@54ea376e:java.nio.channels.SocketChannel[connected local=/127.0.0.1:8080 remote=/127.0.0.1:50988]], Status in: [OPEN_READ], State out: [OPEN]
2021-05-11 16:07:12.702 DEBUG 12588 --- [nio-8080-exec-1] org.apache.tomcat.util.net.NioEndpoint   : Registered read interest for [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@56fe2702:org.apache.tomcat.util.net.NioChannel@54ea376e:java.nio.channels.SocketChannel[connected local=/127.0.0.1:8080 remote=/127.0.0.1:50988]]
2021-05-11 16:07:12.707 DEBUG 12588 --- [nio-8080-exec-2] o.a.coyote.http11.Http11InputBuffer      : Before fill(): parsingHeader: [true], parsingRequestLine: [true], parsingRequestLinePhase: [0], parsingRequestLineStart: [0], byteBuffer.position(): [0], byteBuffer.limit(): [0], end: [232]
2021-05-11 16:07:12.707 DEBUG 12588 --- [nio-8080-exec-2] o.a.tomcat.util.net.SocketWrapperBase    : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@56fe2702:org.apache.tomcat.util.net.NioChannel@54ea376e:java.nio.channels.SocketChannel[connected local=/127.0.0.1:8080 remote=/127.0.0.1:50988]], Read from buffer: [0]
2021-05-11 16:07:12.707 DEBUG 12588 --- [nio-8080-exec-2] o.apache.coyote.http11.Http11Processor   : Error parsing HTTP request header

java.io.EOFException: null
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.fillReadBuffer(NioEndpoint.java:1345) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.read(NioEndpoint.java:1255) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.coyote.http11.Http11InputBuffer.fill(Http11InputBuffer.java:794) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.coyote.http11.Http11InputBuffer.parseRequestLine(Http11InputBuffer.java:359) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:261) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1707) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[na:na]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at java.base/java.lang.Thread.run(Thread.java:832) ~[na:na]

2021-05-11 16:07:12.708 DEBUG 12588 --- [nio-8080-exec-2] o.apache.coyote.http11.Http11Processor   : Error state [CLOSE_CONNECTION_NOW] reported while processing request

java.io.EOFException: null
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.fillReadBuffer(NioEndpoint.java:1345) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.read(NioEndpoint.java:1255) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.coyote.http11.Http11InputBuffer.fill(Http11InputBuffer.java:794) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.coyote.http11.Http11InputBuffer.parseRequestLine(Http11InputBuffer.java:359) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:261) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1707) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[na:na]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.45.jar:9.0.45]
	at java.base/java.lang.Thread.run(Thread.java:832) ~[na:na]

2021-05-11 16:07:12.708 DEBUG 12588 --- [nio-8080-exec-2] o.apache.coyote.http11.Http11Processor   : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@56fe2702:org.apache.tomcat.util.net.NioChannel@54ea376e:java.nio.channels.SocketChannel[connected local=/127.0.0.1:8080 remote=/127.0.0.1:50988]], Status in: [OPEN_READ], State out: [CLOSED]
2021-05-11 16:07:12.709 DEBUG 12588 --- [nio-8080-exec-2] o.apache.tomcat.util.threads.LimitLatch  : Counting down[http-nio-8080-exec-2] latch=1
2021-05-11 16:07:12.709 DEBUG 12588 --- [nio-8080-exec-2] org.apache.tomcat.util.net.NioEndpoint   : Calling [org.apache.tomcat.util.net.NioEndpoint@2a267286].closeSocket([org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@56fe2702:org.apache.tomcat.util.net.NioChannel@54ea376e:java.nio.channels.SocketChannel[connected local=/127.0.0.1:8080 remote=/127.0.0.1:50988]])
2021-05-11 16:07:24.104 DEBUG 12588 --- [)-192.168.1.109] sun.rmi.transport.tcp                    : RMI TCP Connection(8)-192.168.1.109: (port 42343) connection closed

[rstoyanchev]

At the top URL, we respond with a 200 "Welcome to SocketJS" as required by the SockJS protocol. However, given the request is a WebSocket upgrade (rather than a regular HTTP GET), Tomcat seems to run into an exception. This is outside our control and we do not request for a WebSocket upgrade to be started, and in any case the upgrade doesn't succeed with a 200 response.

That said, given the possibility for confusion when experimenting and pointing to the top URL, we can set the response to 400 in this scenario which also seems to cause Tomcat to not run into the same exception.