Jetty

WebSockets with Safari gets messages stuck as if in a buffer that needs to be flushed.

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Major Major
  • Resolution: Duplicate
  • Affects Version/s: 8.0.1
  • Fix Version/s: None
  • Component/s: NIO
  • Labels:
    None
  • Number of attachments :
    1

Description

When using Safari, sending several messages through a websocket will lead to some of them not getting through right away. The last few messages often don't arrive until another message is sent later through the websocket to flush them out.

To reproduce, put this in Safari's debug console:
var x = new WebSocket('ws://localhost:8080/conn/')
for(i in [1, 2, 3, 4, 5]) x.send('x')

If you put a breakpoint in the onMessage method of your WebSocket.OnTextMessage handler, it will only get triggered twice, when it should have been triggered 5 times.

If in Safari you then type:
x.send('x')

The remaining messages will all come through and trigger the breakpoint another 4 times.

A look at WireShark suggests that Safari is in fact sending the messages, but for whatever reason they aren't propagating up into the WebSocket servlet. I traced the bug into the code and discovered that even if I put a breakpoint at SelectChannelEndPoint.schedule, it still wasn't being called for the missing messages, so it must be somewhere even farther down than that.

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Joakim Erdfelt added a comment -

Have been able to replicate this.
Using OSX 10.6.8 + Safari.
Configured pom.xml on https://github.com/jetty-project/jetty-autobahn-websocket-webapp to use
<jetty-version>8.0.1.v20110908</jetty-version>

What is seen is ...

var x = new WebSocket("ws://testserver:8080/");
336939 [qtp11935697-12] INFO org.eclipse.jetty.test.WebSocketEchoServlet - doWebSocketConnect([GET /]@28235257 org.eclipse.jetty.server.Request@1aed5f9, "null")
336940 [qtp11935697-12] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onOpen(org.eclipse.jetty.websocket.WebSocketConnectionD00@16921fd@192.168.1.121:8080<->192.168.1.132:52197)
for(i in [1,2,3,4,5]) x.send("aa");
343821 [qtp11935697-12] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars
343822 [qtp11935697-10] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars
343822 [qtp11935697-10] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars
/* waited 15 seconds */
x.send("x");
352797 [qtp11935697-10] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars
352798 [qtp11935697-9] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars
352798 [qtp11935697-12] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 1chars
x.close();
361737 [qtp11935697-15 Selector1] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onClose(1000, "")

Show
Joakim Erdfelt added a comment - Have been able to replicate this. Using OSX 10.6.8 + Safari. Configured pom.xml on https://github.com/jetty-project/jetty-autobahn-websocket-webapp to use <jetty-version>8.0.1.v20110908</jetty-version> What is seen is ... var x = new WebSocket("ws://testserver:8080/"); 336939 [qtp11935697-12] INFO org.eclipse.jetty.test.WebSocketEchoServlet - doWebSocketConnect( [GET /] @28235257 org.eclipse.jetty.server.Request@1aed5f9, "null") 336940 [qtp11935697-12] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onOpen(org.eclipse.jetty.websocket.WebSocketConnectionD00@16921fd@192.168.1.121:8080<->192.168.1.132:52197) for(i in [1,2,3,4,5] ) x.send("aa"); 343821 [qtp11935697-12] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars 343822 [qtp11935697-10] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars 343822 [qtp11935697-10] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars /* waited 15 seconds */ x.send("x"); 352797 [qtp11935697-10] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars 352798 [qtp11935697-9] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars 352798 [qtp11935697-12] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 1chars x.close(); 361737 [qtp11935697-15 Selector1] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onClose(1000, "")
Hide
Permalink
Joakim Erdfelt added a comment -

Also happens on 7.6.0-SNAPSHOT (master from Dec 12th)
Last commit id: 004fa1ce1ca5f57f55f8cadb749d33b510ba30df

var x = new WebSocket("ws://testserver:8080/");

2011-12-13 07:07:46.921:DBUG:oeji.nio:created SCEP@1b48197

{/192.168.1.132:52205->/192.168.1.121:8080,d=false,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=0}

2011-12-13 07:07:46.926:DBUG:oejh.HttpParser:filled 196/196
2011-12-13 07:07:46.934:DBUG:oejs.Server:REQUEST / on AsyncHttpConnection@42552c//192.168.1.121:8080<->192.168.1.132:52205,g=HttpGenerator

{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=16,c=0},r=1
2011-12-13 07:07:46.934:DBUG:oejsh.ContextHandler:scope null||/ @ o.e.j.s.ServletContextHandler{/,null}
2011-12-13 07:07:46.934:DBUG:oejsh.ContextHandler:context=||/ @ o.e.j.s.ServletContextHandler{/,null}
2011-12-13 07:07:46.934:DBUG:oejs.ServletHandler:servlet |/|null -> org.eclipse.jetty.test.WebSocketEchoServlet-26392982
2011-12-13 07:07:46.934:DBUG:oejs.ServletHandler:chain=null
29888 [qtp6662015-9 - /] INFO org.eclipse.jetty.test.WebSocketEchoServlet - doWebSocketConnect((GET /)@22549907 org.eclipse.jetty.server.Request@1581593, "null")
2011-12-13 07:07:46.943:DBUG:oejw.WebSocketFactory:Websocket upgrade / 1 null WebSocketServletConnectionD00@d73c7a//192.168.1.121:8080<>192.168.1.132:52205
2011-12-13 07:07:46.944:DBUG:oejs.Server:RESPONSE / 101
2011-12-13 07:07:46.947:DBUG:oeji.nio:WebSocketServletConnectionD00@d73c7a//192.168.1.121:8080<>192.168.1.132:52205 replaced AsyncHttpConnection@42552c//192.168.1.121:8080<>192.168.1.132:52205,g=HttpGenerator{s=0,h=-1,b=-1,c=-1}

,p=HttpParser

{s=-14,l=0,c=-3}

,r=1
29906 [qtp6662015-9] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onOpen(WebSocketServletConnectionD00@d73c7a//192.168.1.121:8080<->192.168.1.132:52205)

for(i in [1,2,3,4,5]) x.send("aa");

44305 [qtp6662015-15] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars
44307 [qtp6662015-15] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars
44307 [qtp6662015-15] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars

/* waited 10 seconds */
x.send("x");

64617 [qtp6662015-15] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars
64617 [qtp6662015-13] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars
64617 [qtp6662015-12] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 1chars

x.close();

2011-12-13 07:08:29.354:DBUG:oejin.ChannelEndPoint:ishut SCEP@1b48197

{/192.168.1.132:52205->/192.168.1.121:8080,d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}

2011-12-13 07:08:29.356:DBUG:oejin.ChannelEndPoint:close SCEP@1b48197

{/192.168.1.132:52205->/192.168.1.121:8080,d=true,open=true,ishut=true,oshut=false,rb=false,wb=false,w=true,i=1r}

2011-12-13 07:08:29.357:DBUG:oeji.nio:destroyEndPoint SCEP@1b48197

{null->/192.168.1.121:8080,d=false,open=false,ishut=true,oshut=true,rb=false,wb=false,w=true,i=1!}

72309 [qtp6662015-10 Selector0] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onClose(1000, "")

Show
Joakim Erdfelt added a comment - Also happens on 7.6.0-SNAPSHOT (master from Dec 12th) Last commit id: 004fa1ce1ca5f57f55f8cadb749d33b510ba30df var x = new WebSocket("ws://testserver:8080/"); 2011-12-13 07:07:46.921:DBUG:oeji.nio:created SCEP@1b48197 {/192.168.1.132:52205->/192.168.1.121:8080,d=false,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=0} 2011-12-13 07:07:46.926:DBUG:oejh.HttpParser:filled 196/196 2011-12-13 07:07:46.934:DBUG:oejs.Server:REQUEST / on AsyncHttpConnection@42552c//192.168.1.121:8080<->192.168.1.132:52205,g=HttpGenerator {s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=16,c=0},r=1 2011-12-13 07:07:46.934:DBUG:oejsh.ContextHandler:scope null||/ @ o.e.j.s.ServletContextHandler{/,null} 2011-12-13 07:07:46.934:DBUG:oejsh.ContextHandler:context=||/ @ o.e.j.s.ServletContextHandler{/,null} 2011-12-13 07:07:46.934:DBUG:oejs.ServletHandler:servlet |/|null -> org.eclipse.jetty.test.WebSocketEchoServlet-26392982 2011-12-13 07:07:46.934:DBUG:oejs.ServletHandler:chain=null 29888 [qtp6662015-9 - /] INFO org.eclipse.jetty.test.WebSocketEchoServlet - doWebSocketConnect((GET /)@22549907 org.eclipse.jetty.server.Request@1581593, "null") 2011-12-13 07:07:46.943:DBUG:oejw.WebSocketFactory:Websocket upgrade / 1 null WebSocketServletConnectionD00@d73c7a//192.168.1.121:8080< >192.168.1.132:52205 2011-12-13 07:07:46.944:DBUG:oejs.Server:RESPONSE / 101 2011-12-13 07:07:46.947:DBUG:oeji.nio:WebSocketServletConnectionD00@d73c7a//192.168.1.121:8080< >192.168.1.132:52205 replaced AsyncHttpConnection@42552c//192.168.1.121:8080< >192.168.1.132:52205,g=HttpGenerator{s=0,h=-1,b=-1,c=-1} ,p=HttpParser {s=-14,l=0,c=-3} ,r=1 29906 [qtp6662015-9] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onOpen(WebSocketServletConnectionD00@d73c7a//192.168.1.121:8080<->192.168.1.132:52205) for(i in [1,2,3,4,5] ) x.send("aa"); 44305 [qtp6662015-15] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars 44307 [qtp6662015-15] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars 44307 [qtp6662015-15] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars /* waited 10 seconds */ x.send("x"); 64617 [qtp6662015-15] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars 64617 [qtp6662015-13] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 2chars 64617 [qtp6662015-12] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onMessage 1chars x.close(); 2011-12-13 07:08:29.354:DBUG:oejin.ChannelEndPoint:ishut SCEP@1b48197 {/192.168.1.132:52205->/192.168.1.121:8080,d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r} 2011-12-13 07:08:29.356:DBUG:oejin.ChannelEndPoint:close SCEP@1b48197 {/192.168.1.132:52205->/192.168.1.121:8080,d=true,open=true,ishut=true,oshut=false,rb=false,wb=false,w=true,i=1r} 2011-12-13 07:08:29.357:DBUG:oeji.nio:destroyEndPoint SCEP@1b48197 {null->/192.168.1.121:8080,d=false,open=false,ishut=true,oshut=true,rb=false,wb=false,w=true,i=1!} 72309 [qtp6662015-10 Selector0] INFO org.eclipse.jetty.test.WebSocketEchoServlet - onClose(1000, "")
Hide
Permalink
Joakim Erdfelt added a comment -

Wireshark capture of this transaction.

src ip : 192.168.1.132 (OSX w/Safari)
dest ip: 192.168.1.121 (linux websocket server using jetty-websocket 7.6.0-SNAPSHOT from latest master)

time 0 - open websocket
time 8 - send 5 "aa-#" messages
time 21 - send 1 "x" message
time 30 - close websocket

Show
Joakim Erdfelt added a comment - Wireshark capture of this transaction. src ip : 192.168.1.132 (OSX w/Safari) dest ip: 192.168.1.121 (linux websocket server using jetty-websocket 7.6.0-SNAPSHOT from latest master) time 0 - open websocket time 8 - send 5 "aa-#" messages time 21 - send 1 "x" message time 30 - close websocket
Hide
Permalink
Joakim Erdfelt added a comment -

According to the latest wireshark capture ...
While it is true that safari does indeed send all 5 messages, it doesn't send them at the time expected.

Of the 5 messages issued by javascript on safari, this is what is seen.

Safari issues the Upgrade request without specifying the draft version, so jetty defaults to expected behavior and chooses WebSocketConnectionD00 (aka Draft 0) for the connection behavior.

Safari Javascript issues 5 messages.
"aa-0", "aa-1", "aa-2", "aa-3", "aa-4"

Safari's Websocket implementation sends the following websocket messages:

Packet 10: "aa-0"
Packet 12: "aa-1" FF00 "aa-2" FF00 "aa-3" FF00 "aa-4" FF
Packet 14: "aa-0"
Packet 15: "aa-1"
Packet 16: "aa-2"

Then nothing else is sent by Safari.

Now we have Safari's javascript issues 1 message as "x"

We see the following in the wireshark capture.

Packet 20: "x"
Packet 21: "aa-3"
Packet 22: "aa-4"
Packet 23: "x"

What I don't understand is why/what Packet 12 is all about.
And why we get the "x" twice as Packet 20 and 23.

Show
Joakim Erdfelt added a comment - According to the latest wireshark capture ... While it is true that safari does indeed send all 5 messages, it doesn't send them at the time expected. Of the 5 messages issued by javascript on safari, this is what is seen. Safari issues the Upgrade request without specifying the draft version, so jetty defaults to expected behavior and chooses WebSocketConnectionD00 (aka Draft 0) for the connection behavior. Safari Javascript issues 5 messages. "aa-0", "aa-1", "aa-2", "aa-3", "aa-4" Safari's Websocket implementation sends the following websocket messages: Packet 10: "aa-0" Packet 12: "aa-1" FF00 "aa-2" FF00 "aa-3" FF00 "aa-4" FF Packet 14: "aa-0" Packet 15: "aa-1" Packet 16: "aa-2" Then nothing else is sent by Safari. Now we have Safari's javascript issues 1 message as "x" We see the following in the wireshark capture. Packet 20: "x" Packet 21: "aa-3" Packet 22: "aa-4" Packet 23: "x" What I don't understand is why/what Packet 12 is all about. And why we get the "x" twice as Packet 20 and 23.
Hide
Permalink
Joakim Erdfelt added a comment -

A new SafariD00 helper class in the test cases for jetty-websocket has been created, and a new SafariWebsocketDraft0Test has been created that can replicate this scenario entirely within a unit test.
Test case fails (as described in this jira) on Linux.
This new test case is set as @Ignore for now.

Show
Joakim Erdfelt added a comment - A new SafariD00 helper class in the test cases for jetty-websocket has been created, and a new SafariWebsocketDraft0Test has been created that can replicate this scenario entirely within a unit test. Test case fails (as described in this jira) on Linux. This new test case is set as @Ignore for now.
Hide
Permalink
Thomas Becker added a comment - - edited

Problem is that we exit the parsing of the messages in WebSocketParserD00.java too early.

This is line 159-174 of 7.6-SNAPSHOT:

WebSocketParserD00.java line 159-174
                    case STATE_SENTINEL_DATA:
                        b=_buffer.get();
                        if ((b&0xff)==0xff)
                        {
                            _state=STATE_START;
                            int l=_buffer.getIndex()-_buffer.markIndex()-1;
                            _handler.onFrame((byte)0,_opcode,_buffer.sliceFromMark(l));
                            _buffer.setMarkIndex(-1);
                            if (_buffer.length()==0)
                            {
                                _buffers.returnBuffer(_buffer);
                                _buffer=null;
                            }
                            return total_filled;
                        }
                        continue;

In line 172 we "return total_filled". That means after the first 0xff byte we stop parsing the data bytes. But according to the spec we should continue reading until there's no more data bytes on the wire.

See: http://tools.ietf.org/html/draft-ietf-hybi-thewebsocketprotocol-00#section-5.3 step 3. [...] 3. Return to the step labeled frame. [...] for reference. Moving "return total_filled;" into that branch "if (_buffer.length()==0)" resolves the issue and makes Joakime's test pass just fine.
I guess the same counts for "case STATE_DATA:". If you can review what I just said and say I'm right, I'll provide you a patch immediately fixing both cases.

Show
Thomas Becker added a comment - - edited Problem is that we exit the parsing of the messages in WebSocketParserD00.java too early. This is line 159-174 of 7.6-SNAPSHOT: WebSocketParserD00.java line 159-174 case STATE_SENTINEL_DATA: b=_buffer.get(); if ((b&0xff)==0xff) { _state=STATE_START; int l=_buffer.getIndex()-_buffer.markIndex()-1; _handler.onFrame(( byte )0,_opcode,_buffer.sliceFromMark(l)); _buffer.setMarkIndex(-1); if (_buffer.length()==0) { _buffers.returnBuffer(_buffer); _buffer= null ; } return total_filled; } continue ; In line 172 we "return total_filled". That means after the first 0xff byte we stop parsing the data bytes. But according to the spec we should continue reading until there's no more data bytes on the wire. See: http://tools.ietf.org/html/draft-ietf-hybi-thewebsocketprotocol-00#section-5.3 step 3. [...] 3. Return to the step labeled frame . [...] for reference. Moving "return total_filled;" into that branch "if (_buffer.length()==0)" resolves the issue and makes Joakime's test pass just fine. I guess the same counts for "case STATE_DATA:". If you can review what I just said and say I'm right, I'll provide you a patch immediately fixing both cases.
Hide
Permalink
Andrew Lee added a comment -

This is great! Looking forward to a patched version. Thank you!

Show
Andrew Lee added a comment - This is great! Looking forward to a patched version. Thank you!
Hide
Permalink
Greg Wilkins added a comment -

I've push to git a fix that has the D0 parser returning an indication that progress has been made if a message has been processed, even if no fill was done.

I've not closed this issue as we need to merge this kind test into the general testing of all websocket implementations. We also need to review D06 and D08 for similar issues.

for clarity, we should probably also rename the "filled" variable in the handle loop to "parse_progress" or similar.

Show
Greg Wilkins added a comment - I've push to git a fix that has the D0 parser returning an indication that progress has been made if a message has been processed, even if no fill was done. I've not closed this issue as we need to merge this kind test into the general testing of all websocket implementations. We also need to review D06 and D08 for similar issues. for clarity, we should probably also rename the "filled" variable in the handle loop to "parse_progress" or similar.
Hide
Permalink
Jan Bartel added a comment -

Greg, you were the last to look at this issue, is it fixed?

thanks
Jan

Show
Jan Bartel added a comment - Greg, you were the last to look at this issue, is it fixed? thanks Jan
Hide
Permalink
Vicente Ruiz added a comment - - edited

Hi there,

I think that we are experiencing a similar problem.

Here an explanation of our issue (in Apache Wave using jetty 8.1.1 and later 8.1.4):

https://issues.apache.org/jira/browse/WAVE-358

See for websocket frames:
http://homes.ourproject.org/~vjrj/otros/websocket-stuck.svg

the frame 9 (<-) should be the response for frame 7 (->) but the connection stucks in 7 til a new client petition is generated, that is frame 8 (->).

So the question is, can be related with this issue? is it fixed?

Show
Vicente Ruiz added a comment - - edited Hi there, I think that we are experiencing a similar problem. Here an explanation of our issue (in Apache Wave using jetty 8.1.1 and later 8.1.4): https://issues.apache.org/jira/browse/WAVE-358 See for websocket frames: http://homes.ourproject.org/~vjrj/otros/websocket-stuck.svg the frame 9 (<-) should be the response for frame 7 (->) but the connection stucks in 7 til a new client petition is generated, that is frame 8 (->). So the question is, can be related with this issue? is it fixed?
Hide
Permalink
Vicente Ruiz added a comment - - edited

For us, the problem seems related with SSL, so probably is a different issue. The websocket messages are send, but for some reason are not received by the client (probably a checksum/corruption problem).

Show
Vicente Ruiz added a comment - - edited For us, the problem seems related with SSL, so probably is a different issue. The websocket messages are send, but for some reason are not received by the client (probably a checksum/corruption problem).
Hide
Permalink
Jan Bartel added a comment -

Assigning to Joakim to update tests as per Greg's post.

Show
Jan Bartel added a comment - Assigning to Joakim to update tests as per Greg's post.
Hide
Permalink
Jan Bartel added a comment -

This issue was moved to jetty eclipse bugzilla: https://bugs.eclipse.org/bugs/show_bug.cgi?id=396560

Show
Jan Bartel added a comment - This issue was moved to jetty eclipse bugzilla: https://bugs.eclipse.org/bugs/show_bug.cgi?id=396560

People

  • Assignee:
    Joakim Erdfelt
    Reporter:
    Andrew Lee
Vote (1)
Watch (3)

Dates

  • Created:
    Updated:
    Resolved: