Some Eclipse Foundation services are deprecated, or will be soon. Please ensure you've read this important communication.

Bug 370387

Summary:	SafariWebsocketDraft0Test failure during build
Product:	[RT] Jetty	Reporter:	Jan Bartel <janb>
Component:	websocket	Assignee:	Simone Bordet <simone.bordet>
Status:	RESOLVED FIXED	QA Contact:
Severity:	normal
Priority:	P3	CC:	gregw, jetty-inbox, tbecker
Version:	8.1.0
Target Milestone:	7.5.x
Hardware:	PC
OS:	Linux
Whiteboard:

Description Jan Bartel

2012-02-01 21:45:48 EST

On jetty-8 trunk:



-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running org.eclipse.jetty.websocket.WebSocketCommTest
2012-02-02 13:40:51.983:INFO:oejs.Server:jetty-8.1.1-SNAPSHOT
2012-02-02 13:40:52.080:INFO:oejs.AbstractConnector:Started SelectChannelConnector@0.0.0.0:59019
Server URI: ws://localhost:59019/
Sending msg-0
Sending msg-1
Sending msg-2
Sending msg-3
Sending msg-4
Closing client socket
2012-02-02 13:40:52.733:INFO:oejsh.ContextHandler:stopped o.e.j.s.ServletContextHandler{/,null}
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.989 sec
Running org.eclipse.jetty.websocket.WebSocketParserD08Test
Tests run: 9, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.036 sec
Running org.eclipse.jetty.websocket.WebSocketGeneratorRFC6455Test
Tests run: 7, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.014 sec
Running org.eclipse.jetty.websocket.WebSocketClientTest
Tests run: 14, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 11.78 sec
Running org.eclipse.jetty.websocket.WebSocketLoadRFC6455Test
2012-02-02 13:41:04.645:INFO:oejs.Server:jetty-8.1.1-SNAPSHOT
2012-02-02 13:41:04.648:INFO:oejs.AbstractConnector:Started SelectChannelConnector@0.0.0.0:51679
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.917 sec
Running org.eclipse.jetty.websocket.WebSocketParserD06Test
tosend=00F00fFf84Fb479a6c9c60Df579f7d9364
Tests run: 8, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.021 sec
Running org.eclipse.jetty.websocket.WebSocketParserD00Test
Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.007 sec
Running org.eclipse.jetty.websocket.WebSocketMessageD06Test
2012-02-02 13:41:06.645:INFO:oejs.Server:jetty-8.1.1-SNAPSHOT
2012-02-02 13:41:06.649:INFO:oejs.AbstractConnector:Started SelectChannelConnector@0.0.0.0:53252
Tests run: 14, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.923 sec
Running org.eclipse.jetty.websocket.WebSocketMessageD00Test
2012-02-02 13:41:08.556:INFO:oejs.Server:jetty-8.1.1-SNAPSHOT
2012-02-02 13:41:08.558:INFO:oejs.AbstractConnector:Started SelectChannelConnector@0.0.0.0:44147
Tests run: 9, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 8.334 sec
Running org.eclipse.jetty.websocket.WebSocketMessageRFC6455Test
2012-02-02 13:41:16.898:INFO:oejs.Server:jetty-8.1.1-SNAPSHOT
2012-02-02 13:41:16.900:INFO:oejs.AbstractConnector:Started SelectChannelConnector@0.0.0.0:45251
2012-02-02 13:41:18.375:WARN:oejw.WebSocketConnectionRFC6455:Text message too large > 15 chars for SCEP@3488b1e6{l(/127.0.0.1:47044)<->r(/127.0.0.1:45251),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{WebSocketServletConnectionRFC6455 p=WebSocketParserRFC6455@72813bc1 state=DATA buffer= g=WebSocketGeneratorRFC6455@27a36a2 closed=false buffer=-1}
2012-02-02 13:41:18.414:WARN:oejw.WebSocketConnectionRFC6455:Text message too large > 15 chars for SCEP@512d8ecd{l(/127.0.0.1:47045)<->r(/127.0.0.1:45251),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{WebSocketServletConnectionRFC6455 p=WebSocketParserRFC6455@1d716fa0 state=DATA buffer= g=WebSocketGeneratorRFC6455@257807a closed=false buffer=-1}
2012-02-02 13:41:18.494:WARN:oejw.WebSocketConnectionRFC6455:Binary message too large > 15B for SCEP@33238785{l(/127.0.0.1:47047)<->r(/127.0.0.1:45251),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{WebSocketServletConnectionRFC6455 p=WebSocketParserRFC6455@1ee2433b state=DATA buffer= g=WebSocketGeneratorRFC6455@18abe654 closed=false buffer=-1}
2012-02-02 13:41:18.535:WARN:oejw.WebSocketConnectionRFC6455:Binary message too large > 15B for SCEP@21270107{l(/127.0.0.1:47048)<->r(/127.0.0.1:45251),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{WebSocketServletConnectionRFC6455 p=WebSocketParserRFC6455@239a0feb state=DATA buffer= g=WebSocketGeneratorRFC6455@578b1f8f closed=false buffer=-1}
2012-02-02 13:41:25.695:WARN:oejw.WebSocketConnectionRFC6455:Text message too large > 10240 chars for SCEP@27f8922{l(/127.0.0.1:47056)<->r(/127.0.0.1:45251),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{WebSocketServletConnectionRFC6455 p=WebSocketParserRFC6455@38a1aa85 state=DATA buffer= g=WebSocketGeneratorRFC6455@7dc21ece closed=false buffer=-1}
2012-02-02 13:41:26.245:WARN:oejw.WebSocketConnectionRFC6455:NOTUTF8 - org.eclipse.jetty.util.Utf8Appendable$NotUtf8Exception: Not valid UTF8! byte 28 in state 2 for SCEP@ee31e33{l(/127.0.0.1:47081)<->r(/127.0.0.1:45251),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{WebSocketServletConnectionRFC6455 p=WebSocketParserRFC6455@7aec898a state=DATA buffer= g=WebSocketGeneratorRFC6455@3f3a0212 closed=false buffer=-1} org.eclipse.jetty.util.Utf8Appendable$NotUtf8Exception: Not valid UTF8! byte 28 in state 2
Tests run: 24, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 9.419 sec
Running org.eclipse.jetty.websocket.WebSocketGeneratorD06Test
Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.005 sec
Running org.eclipse.jetty.websocket.WebSocketOverSSLTest
2012-02-02 13:41:26.327:INFO:oejs.Server:jetty-8.1.1-SNAPSHOT
2012-02-02 13:41:26.566:INFO:oejus.SslContextFactory:Enabled Protocols [SSLv2Hello, TLSv1, SSLv3] of [SSLv2Hello, SSLv3, TLSv1]
2012-02-02 13:41:26.568:INFO:oejs.AbstractConnector:Started SslSelectChannelConnector@0.0.0.0:55787
2012-02-02 13:41:26.579:INFO:oejus.SslContextFactory:Enabled Protocols [SSLv2Hello, TLSv1, SSLv3] of [SSLv2Hello, SSLv3, TLSv1]
2012-02-02 13:41:26.794:INFO:oejs.Server:jetty-8.1.1-SNAPSHOT
2012-02-02 13:41:26.799:INFO:oejus.SslContextFactory:Enabled Protocols [SSLv2Hello, TLSv1, SSLv3] of [SSLv2Hello, SSLv3, TLSv1]
2012-02-02 13:41:26.801:INFO:oejs.AbstractConnector:Started SslSelectChannelConnector@0.0.0.0:49711
2012-02-02 13:41:26.807:INFO:oejus.SslContextFactory:Enabled Protocols [SSLv2Hello, TLSv1, SSLv3] of [SSLv2Hello, SSLv3, TLSv1]
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 3.125 sec
Running org.eclipse.jetty.websocket.SafariWebsocketDraft0Test
2012-02-02 13:41:29.448:INFO:oejs.Server:jetty-8.1.1-SNAPSHOT
2012-02-02 13:41:29.450:INFO:oejs.AbstractConnector:Started SelectChannelConnector@0.0.0.0:35699
2012-02-02 13:41:34.484:INFO:oejsh.ContextHandler:stopped o.e.j.s.ServletContextHandler{/,null}
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 5.094 sec <<< FAILURE!
Running org.eclipse.jetty.websocket.WebSocketGeneratorD08Test
Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.007 sec
Running org.eclipse.jetty.websocket.WebSocketLoadD08Test
2012-02-02 13:41:34.552:INFO:oejs.Server:jetty-8.1.1-SNAPSHOT
2012-02-02 13:41:34.578:INFO:oejs.AbstractConnector:Started SelectChannelConnector@0.0.0.0:53720
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.167 sec
Running org.eclipse.jetty.websocket.WebSocketServletRFCTest
2012-02-02 13:41:35.721:INFO:oejs.Server:jetty-8.1.1-SNAPSHOT
2012-02-02 13:41:35.722:INFO:oejs.AbstractConnector:Started SelectChannelConnector@0.0.0.0:49723
Server URI: ws://localhost:49723/
2012-02-02 13:41:35.727:WARN:oejw.WebSocketFactory:Unsupported Websocket version: 29
2012-02-02 13:41:35.738:WARN:oejw.WebSocketConnectionRFC6455:java.lang.RuntimeException: Something bad happened for SCEP@6d56d7c8{l(/127.0.0.1:33999)<->r(/127.0.0.1:49723),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{WebSocketServletConnectionRFC6455 p=WebSocketParserRFC6455@14eac7c8 state=DATA buffer= g=WebSocketGeneratorRFC6455@41e22632 closed=false buffer=-1} java.lang.RuntimeException: Something bad happened
2012-02-02 13:41:36.249:INFO:oejsh.ContextHandler:stopped o.e.j.s.ServletContextHandler{/,null}
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.582 sec
Running org.eclipse.jetty.websocket.WebSocketGeneratorD00Test
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.002 sec
Running org.eclipse.jetty.websocket.WebSocketParserRFC6455Test
Tests run: 10, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.013 sec
Running org.eclipse.jetty.websocket.WebSocketRedeployTest
2012-02-02 13:41:36.324:INFO:oejs.Server:jetty-8.1.1-SNAPSHOT
2012-02-02 13:41:36.343:INFO:oejs.AbstractConnector:Started SelectChannelConnector@0.0.0.0:40031
2012-02-02 13:41:36.365:INFO:oejsh.ContextHandler:stopped o.e.j.s.ServletContextHandler{/test_context,null}
2012-02-02 13:41:36.502:INFO:oejs.Server:jetty-8.1.1-SNAPSHOT
2012-02-02 13:41:36.506:INFO:oejs.AbstractConnector:Started SelectChannelConnector@0.0.0.0:47454
2012-02-02 13:41:36.589:INFO:oejsh.ContextHandler:stopped o.e.j.s.ServletContextHandler{/test_context,null}
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.322 sec
Running org.eclipse.jetty.websocket.WebSocketMessageD08Test
2012-02-02 13:41:36.653:INFO:oejs.Server:jetty-8.1.1-SNAPSHOT
2012-02-02 13:41:36.654:INFO:oejs.AbstractConnector:Started SelectChannelConnector@0.0.0.0:34988
2012-02-02 13:41:38.374:WARN:oejw.WebSocketConnectionD08:Text message too large > 15 chars for SCEP@71d382ab{l(/127.0.0.1:57209)<->r(/127.0.0.1:34988),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{WS/D8 p=WebSocketParserD08@da3b359|DATA|[1985191693,-1,m=-1,g=31,p=31,c=8192]={} g=org.eclipse.jetty.websocket.WebSocketGeneratorD08@6bef4b2b}
2012-02-02 13:41:38.414:WARN:oejw.WebSocketConnectionD08:Text message too large > 15 chars for SCEP@677210a5{l(/127.0.0.1:57210)<->r(/127.0.0.1:34988),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{WS/D8 p=WebSocketParserD08@1b071c0|DATA|[1727788317,-1,m=-1,g=25,p=25,c=8192]={} g=org.eclipse.jetty.websocket.WebSocketGeneratorD08@279977bd}
2012-02-02 13:41:38.494:WARN:oejw.WebSocketConnectionD08:Binary message too large > 15B for SCEP@4ccd21c{l(/127.0.0.1:57212)<->r(/127.0.0.1:34988),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{WS/D8 p=WebSocketParserD08@5075c744|DATA|[1727788317,-1,m=-1,g=31,p=31,c=8192]={} g=org.eclipse.jetty.websocket.WebSocketGeneratorD08@646d6aa0}
2012-02-02 13:41:38.534:WARN:oejw.WebSocketConnectionD08:Binary message too large > 15B for SCEP@41f6321{l(/127.0.0.1:57213)<->r(/127.0.0.1:34988),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{WS/D8 p=WebSocketParserD08@6c229ed4|DATA|[1424598978,-1,m=-1,g=25,p=25,c=8192]={} g=org.eclipse.jetty.websocket.WebSocketGeneratorD08@3804dd1b}
max=2466
2012-02-02 13:41:46.054:WARN:oejw.WebSocketConnectionD08:Text message too large > 10240 chars for SCEP@1d4fcd9a{l(/127.0.0.1:57225)<->r(/127.0.0.1:34988),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{WS/D8 p=WebSocketParserD08@2f4c7a98|DATA|[1985191693,-1,m=-1,g=8192,p=8192,c=8192]={} g=org.eclipse.jetty.websocket.WebSocketGeneratorD08@4604a96a}
Tests run: 20, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 9.473 sec

Results :

Tests in error: 
  testSendTextMessages(org.eclipse.jetty.websocket.SafariWebsocketDraft0Test): Read timed out

Comment 1 Thomas Becker

2012-02-23 09:51:23 EST

Jan, is this reproducible for you?

I've tried to reproduce this by doing a whole build a couple of times without success and then I've run the individual tests for a while in  a loop like this:

while [ $? -eq "0" ] ; do mvn -Dtest=SafariWebsocketDraft0Test test ; done

It never fails for me. (macos, jdk1.6.0_29, mvn 3.0.3).

Comment 2 Thomas Becker

2012-02-23 09:51:57 EST

If it's an intermittent failure, then I will dig a bit more into the test and it's timings.

Comment 3 Simone Bordet

2012-02-24 05:30:57 EST

The test was incorrectly using a BufferedReader *and* the input stream to read the bytes.

It was possible that the hixie bytes were already read by the BufferedReader when the test attempted to read them from the input stream, causing the read to timeout.

Comment 4 Greg Wilkins

2012-02-27 02:48:17 EST

note that this fix was applied to both jetty-7 and jetty-8.  We should still be avoiding direct jetty-8 changes for anything but servlet 3.0 stuff so changes from 7 can be merged to 8.