No stack trace on SockJS HTTP transport failure to write to the response [SPR-11201]

[spring-projects-issues]

Yohan Liyanage opened SPR-11201 and commented

In the latest snapshot build of 4.0, SockJS based Web Socket implementation fails to dispatch messages to subscribers randomly, when connected over Internet.

When I looked into the log file, I do not see any stack traces, but I see the following log output.

:38:51.577 [clientOutboundChannel-4] DEBUG o.s.m.simp.stomp.StompEncoder - Encoded STOMP command=MESSAGE headers={content-type=[application/json;charset=UTF-8], subscription=[sub-0], message-id=[fklmkqzi-0], destination=[/queue/synchronize]}
08:38:51.578 [clientOutboundChannel-4] TRACE o.s.w.s.s.t.s.WebSocketServerSockJsSession - Cancelling heartbeat
08:38:51.578 [clientOutboundChannel-4] TRACE o.s.w.s.s.t.s.WebSocketServerSockJsSession - Preparing to write SockJsFrame content='a["MESSAGE\ncontent-type:application/json;charset=UTF-8\nsubscription:sub-0\nmes...(truncated)'
08:38:51.581 [clientOutboundChannel-4] TRACE o.s.w.s.s.t.s.WebSocketServerSockJsSession - Write SockJsFrame content='a["MESSAGE\ncontent-type:application/json;charset=UTF-8\nsubscription:sub-0\nmes...(truncated)'
08:38:51.581 [clientOutboundChannel-4] TRACE o.s.w.s.a.j.JettyWebSocketSession - Sending TextMessage payload= a["MESSAGE.., length=439, last=true], WebSocket session id=f70433f
08:38:51.582 [clientOutboundChannel-4] WARN  o.s.w.s.s.t.s.WebSocketServerSockJsSession - Terminating connection after failure to send message: null
08:38:51.582 [clientOutboundChannel-4] DEBUG o.s.w.s.a.j.JettyWebSocketSession - Closing WebSocket session id=f70433f
08:38:51.586 [clientOutboundChannel-4] DEBUG o.s.w.s.s.t.s.WebSocketServerSockJsSession - SockJS session id=fklmkqzi was closed, CloseStatus [code=1011, reason=null]
08:38:51.586 [clientOutboundChannel-4] DEBUG o.s.w.s.h.LoggingWebSocketHandlerDecorator - Connection closed for SockJS session id=fklmkqzi, CloseStatus [code=1011, reason=null]
08:38:51.586 [clientOutboundChannel-4] TRACE o.s.m.s.ExecutorSubscribableChannel - [clientInboundChannel] sending message id=c3363e80-892a-d836-4ae2-23c2fbc91ef8
08:38:51.586 [clientInboundChannel-1] TRACE o.s.m.s.a.s.SimpAnnotationMethodMessageHandler - Ignoring message, no destination
08:38:51.586 [clientInboundChannel-1] DEBUG o.s.m.s.b.DefaultSubscriptionRegistry - Unregistering subscriptions for sessionId=fklmkqzi
08:38:51.587 [clientInboundChannel-1] TRACE o.s.m.s.u.DefaultUserDestinationResolver - Ignoring DISCONNECT message
08:38:51.587 [clientOutboundChannel-4] TRACE o.s.m.s.ChannelInterceptorChain - postSend (sent=true) message id c3363e80-892a-d836-4ae2-23c2fbc91ef8
08:38:51.587 [clientOutboundChannel-4] DEBUG o.s.m.simp.stomp.StompEncoder - Encoded STOMP command=ERROR headers={message=[Failed to write SockJsFrame content='a["MESSAGE\ncontent-type:application/json;charset=UTF-8\nsubscription:sub-0\nmes...(truncated)'; nested exception is java.nio.BufferOverflowException]}

From this, it appears that there seems to be a java.nio.BufferOverflowException. However, the stack trace is not being logged and it seems to be lost.

On the client side (Chrome), I see "WebSocket connection to 'ws://209.../' failed: Received unexpected compressed frame".

Environment Details:
Spring 4.0.0 Snapshot
Jetty 9.1.0
CentOS 6

---

Affects: 4.0 RC2

Referenced from: commits d0556e6

[spring-projects-issues]

Rossen Stoyanchev commented

Yes this was intentional to avoid filling up the log since the Servlet 3 async support does not provide a callback for disconnected clients. Hence it is expected to see an IOException on the next write to the response after a client has gone away.

I'll see if we can fine-tune this or make it configurable so that by default exceptions are visible. For more background, see SERVLET_SPEC-44.

[spring-projects-issues]

Yohan Liyanage commented

Thanks & noted. Having such an option would be extremely helpful. Right now, there's no way to track back when a write fails because the stack trace is not available.

[spring-projects-issues]

Myst Caster commented

Hello,

Issue comes from Jetty.
I posted a patch on Jetty bug tracker : https://bugs.eclipse.org/bugs/show_bug.cgi?id=424667

You can inject the fixed buffer pool in an embedded jetty with that kind of initialization :

import org.eclipse.jetty.server.Connector;
import org.eclipse.jetty.server.HttpConnectionFactory;
import org.eclipse.jetty.server.ServerConnector;
import org.eclipse.jetty.webapp.WebAppContext;
import org.eclipse.jetty.server.Server;


import <YOUR_PACKAGE>.ArrayByteBufferPool;


...


        Server server = new org.eclipse.jetty.server.Server();

        try(ServerConnector connector=new ServerConnector(server,null,null,new ArrayByteBufferPool(),-1,-1,new HttpConnectionFactory()) {
            connector.setPort(port);
            server.setConnectors(new Connector[]{connector});
            

            ...
    

            server.start();
            server.join();
        } catch (Exception e) {


            ...


        }


...

Basically, here is the issue :

1. You open a Websocket
2. Jetty automatically send an hearthbeat, initializing a buffer with a capacity of 3
3. After sending the message, Jetty ask the release method of you buffer pool to release that new buffer
4. Due to a bug, the buffer pool (initialized with a min size of 0, an increment of 1024 and a max size of 63*1024) accept the buffer and store it with the buffers of 1024 capacity.
5. Next time you ask for a buffer of size <= 1024, the buffer pool may return the capacity 3 buffer.

The web socket does not crash if you only send messages with less than 126 characters since Jetty only needs a size 3 buffer for this.

[spring-projects-issues]

Yohan Liyanage commented

Thank you Myst. What you said seems to be the root cause for the issue I was facing. Thanks again for the detailed explanation.

[spring-projects-issues]

Rossen Stoyanchev commented

The full stack trace is now logged in case of failure to send a message to a client. The error message provides a hint that this may be because the client went away. See commit d0556e.