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 WebSocket = require('ws');
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
```
Comment From: 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.