Use DEBUG log level for broken WebSocket client connections or write failures [SPR-12155]

[spring-projects-issues]

Rob Winch opened SPR-12155 and commented

At times LoggingWebSocketHandlerDecorator logs "IOException: Broken pipe at ERROR" inappropriately.

This can happen in the following scenario:

• A webpage creates a WebSocket connection
• The user refreshes the page which immediately terminates the WebSocket connection

Note that this is an intermitted issue and does not happen all of the time. Since this is a normal workflow, Spring should not log this at ERROR level.

A full stacktrace can be found below:

2014-09-04 10:55:14.809 ERROR 55031 --- [nio-8080-exec-1] s.w.s.h.LoggingWebSocketHandlerDecorator : Transport error in WebSocketServerSockJsSession[id=jhf9zdei]



java.io.IOException: java.util.concurrent.ExecutionException: java.io.IOException: Broken pipe

at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:243)

at org.apache.tomcat.websocket.WsSession.sendCloseMessage(WsSession.java:487)

at org.apache.tomcat.websocket.WsSession.onClose(WsSession.java:441)

at org.apache.tomcat.websocket.WsFrameBase.processDataControl(WsFrameBase.java:324)

at org.apache.tomcat.websocket.WsFrameBase.processData(WsFrameBase.java:270)

at org.apache.tomcat.websocket.WsFrameBase.processInputBuffer(WsFrameBase.java:116)

at org.apache.tomcat.websocket.server.WsFrameServer.onDataAvailable(WsFrameServer.java:54)

at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsReadListener.onDataAvailable(WsHttpUpgradeHandler.java:194)

at org.apache.coyote.http11.upgrade.AbstractServletInputStream.onDataAvailable(AbstractServletInputStream.java:189)

at org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:92)

at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:605)

at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1720)

at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1679)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)

at java.lang.Thread.run(Thread.java:744)

Caused by: java.util.concurrent.ExecutionException: java.io.IOException: Broken pipe

at org.apache.tomcat.websocket.FutureToSendHandler.get(FutureToSendHandler.java:102)

at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:238)

... 16 common frames omitted

Caused by: java.io.IOException: Broken pipe

at sun.nio.ch.FileDispatcherImpl.write0(Native Method)

at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)

at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)

at sun.nio.ch.IOUtil.write(IOUtil.java:65)

at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:466)

at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:123)

at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:185)

at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWriteInternal(NioServletOutputStream.java:93)

at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWrite(NioServletOutputStream.java:60)

at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.writeInternal(AbstractServletOutputStream.java:125)

at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.write(AbstractServletOutputStream.java:92)

at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.onWritePossible(WsRemoteEndpointImplServer.java:94)

at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doWrite(WsRemoteEndpointImplServer.java:81)

at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:393)

at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:287)

at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:233)

... 16 common frames omitted

---

Affects: 4.1 GA

Issue Links:

• Logs fill with unnecessary stack traces when using SockJS streaming transports [SPR-11438] #16064 Logs fill with unnecessary stack traces when using SockJS streaming transports

Referenced from: commits 5b1cbf0

1 votes, 3 watchers

[spring-projects-issues]

Rossen Stoyanchev commented

The LoggingWSHD logs every exception it hears about through the onError callback. It has no idea what the error is or that in this case it's something harmless such as closing the browser tab. In other cases it could be that connectivity is lost of other reasons and not as harmless.

Perhaps a reasonable improvement here would be to avoid logging full stack traces in LoggingWSHD unless explicitly configured to do so. After all the purpose of this decorator is to automate logging but could easily fill up the logs.

[spring-projects-issues]

Rob Winch commented

I think that getting any sort of ERROR level logging (with or without a stacktrace) when a normal user workflow is performed is undesirable. Many monitoring solutions would send all sorts of alerts if an ERROR level log is detected.

[spring-projects-issues]

Rossen Stoyanchev commented

After some further discussion, the thinking is if a client connection is lost for any reason (browser tab closed, wifi lost, etc.) or if there is a failure to send message (a very closely related condition which results in the connection being closed), we should be using debug-level logging.

Such errors have a very high potential to be false positives. They have a high noise factor with little (nothing) to be done. They are much more closely related to connect and disconnect events that are currently logged at debug level.

[spring-projects-issues]

Rossen Stoyanchev commented

Modified title (was "LoggingWebSocketHandlerDecorator logs IOException: Broken pipe at ERROR inappropriately").