[EDGENT-122] WebSocketClientTest intermittent travis build failure

• Type: Bug
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Component/s: Connectors
• Assignee: Dale LaBossiere
• Reporter: Dale LaBossiere
• Created: 06/Apr/16 19:51
• Updated: 28/Feb/17 16:40
• Resolved: 28/Feb/17 16:40

Description

Got two failures of WebSocketClientTest.testReconnectBytes().
One is in this build:
https://travis-ci.org/apache/incubator-quarks/builds/121228983

Can't precisely tell the timing of things. But its not an overall test-timeout failure. The server echo processing indicates the 3rd tuple (length ~20) wasn't received. 1st, 2nd, 4th ones were - see the "onByteMessage" messages below.

That sort of shouldn't happen because sendBinary loops if the call fails... hmm... but only if a check shows the connection is !open, otherwise it throws a runtime exception – it also logs an error saying sendBinary failed... but that doesn't seem to be in the transcript. I've got a couple of thoughts on improving logging to help get a better handle on this.

STDOUT =======================================
[junit] ===== testReconnectBytes
[junit] WebSocketServerEcho ws://localhost:0 needClientAuth=false
[junit] WebSocketServerEcho started ServerConnector@2ad14e76

{HTTP/1.1,[http/1.1]}{0.0.0.0:39504}
[junit] WebSocketServerEcho onOpen
[junit] WebSocketServerEcho onByteMessage 3 bytes
[junit] WebSocketServerEcho onByteMessage 3 bytes
[junit] WebSocketServerEcho restart: stop ServerConnector@2ad14e76{HTTP/1.1,[http/1.1]} {0.0.0.0:39504}

[junit] WebSocketServerEcho onClose reason=CloseReason[1005]
[junit] WebSocketServerEcho restart: scheduling start after 2sec
[junit] WebSocketServerEcho restart: starting...
[junit] WebSocketServerEcho ws://localhost:39504 needClientAuth=false
[junit] WebSocketServerEcho started ServerConnector@730dee18

{HTTP/1.1,[http/1.1]}{0.0.0.0:39504}
[junit] WebSocketServerEcho onOpen
[junit] WebSocketServerEcho onByteMessage 4 bytes
[junit] WebSocketServerEcho onClose reason=CloseReason[1005]
[junit] WebSocketServerEcho stop ServerConnector@730dee18{HTTP/1.1,[http/1.1]} {0.0.0.0:39504}

STDERR =======================================
[junit] INFO: Started ServerConnector@2ad14e76

{HTTP/1.1,[http/1.1]}{0.0.0.0:39504}
[junit] Apr 06, 2016 4:49:17 PM org.eclipse.jetty.server.Server doStart
[junit] INFO: Started @54723ms
[junit] Apr 06, 2016 4:49:17 PM quarks.connectors.runtime.Connector setStateUnsafe
[junit] INFO: WSCLIENT 4794d2a8 sid=null state CONNECTING (was DISCONNECTED)
[junit] Apr 06, 2016 4:49:17 PM quarks.connectors.wsclient.javax.websocket.runtime.WebSocketClientConnector doConnect
[junit] INFO: WSCLIENT 4794d2a8 sid=null connecting uri=ws://localhost:39504/echo
[junit] Apr 06, 2016 4:49:17 PM quarks.connectors.wsclient.javax.websocket.runtime.WebSocketClientConnector doConnect
[junit] INFO: WSCLIENT 4794d2a8 sid=websocket-1 connected uri=ws://localhost:39504/echo
[junit] Apr 06, 2016 4:49:17 PM quarks.connectors.runtime.Connector setStateUnsafe
[junit] INFO: WSCLIENT 4794d2a8 sid=websocket-1 state CONNECTED (was CONNECTING)
[junit] Apr 06, 2016 4:49:19 PM org.eclipse.jetty.server.AbstractConnector doStop
[junit] INFO: Stopped ServerConnector@2ad14e76{HTTP/1.1,[http/1.1]} {0.0.0.0:0}

[junit] Apr 06, 2016 4:49:19 PM quarks.connectors.wsclient.javax.websocket.runtime.WebSocketClientConnector onError
[junit] SEVERE: WSCLIENT 4794d2a8 sid=websocket-1 onError org.eclipse.jetty.io.EofException
[junit] Apr 06, 2016 4:49:19 PM quarks.connectors.runtime.Connector connectionLost
[junit] INFO: Connection WSCLIENT 4794d2a8 sid=websocket-1 connectionLost()
[junit] org.eclipse.jetty.io.EofException
[junit] at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:197)
[junit] at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:419)
[junit] at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:313)
[junit] at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:141)
[junit] at org.eclipse.jetty.websocket.common.io.FrameFlusher$Flusher.flush(FrameFlusher.java:152)
[junit] at org.eclipse.jetty.websocket.common.io.FrameFlusher$Flusher.process(FrameFlusher.java:216)
[junit] at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241)
[junit] at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224)
[junit] at org.eclipse.jetty.websocket.common.io.FrameFlusher.enqueue(FrameFlusher.java:381)
[junit] at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.outgoingFrame(AbstractWebSocketConnection.java:598)
[junit] at org.eclipse.jetty.websocket.client.io.WebSocketClientConnection.outgoingFrame(WebSocketClientConnection.java:85)
[junit] at org.eclipse.jetty.websocket.common.extensions.ExtensionStack$Flusher.process(ExtensionStack.java:389)
[junit] at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241)
[junit] at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224)
[junit] at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.outgoingFrame(ExtensionStack.java:290)
[junit] at org.eclipse.jetty.websocket.common.WebSocketRemoteEndpoint.uncheckedSendFrame(WebSocketRemoteEndpoint.java:304)
[junit] at org.eclipse.jetty.websocket.common.WebSocketRemoteEndpoint.blockingWrite(WebSocketRemoteEndpoint.java:106)
[junit] at org.eclipse.jetty.websocket.common.WebSocketRemoteEndpoint.sendBytes(WebSocketRemoteEndpoint.java:252)
[junit] at org.eclipse.jetty.websocket.jsr356.JsrBasicRemote.sendBinary(JsrBasicRemote.java:67)
[junit] at quarks.connectors.wsclient.javax.websocket.runtime.WebSocketClientConnector.sendBinary(WebSocketClientConnector.java:207)
[junit] at quarks.connectors.wsclient.javax.websocket.runtime.WebSocketClientBinarySender.accept(WebSocketClientBinarySender.java:34)
[junit] at quarks.function.Functions$ThreadSafeConsumer.accept(Functions.java:197)
[junit] at quarks.runtime.etiao.SettableForwarder.accept(SettableForwarder.java:54)
[junit] at quarks.oplet.core.Pipe.submit(Pipe.java:65)
[junit] at quarks.oplet.functional.Filter.accept(Filter.java:37)
[junit] at quarks.runtime.etiao.SettableForwarder.accept(SettableForwarder.java:54)
[junit] at quarks.oplet.core.Pipe.submit(Pipe.java:65)
[junit] at quarks.oplet.functional.Map.accept(Map.java:47)
[junit] at quarks.runtime.etiao.SettableForwarder.accept(SettableForwarder.java:54)
[junit] at quarks.oplet.core.Pipe.submit(Pipe.java:65)
[junit] at quarks.oplet.functional.Map.accept(Map.java:47)
[junit] at quarks.runtime.etiao.SettableForwarder.accept(SettableForwarder.java:54)
[junit] at quarks.oplet.core.Source.submit(Source.java:47)
[junit] at quarks.oplet.functional.SupplierSource.process(SupplierSource.java:52)
[junit] at quarks.oplet.core.ProcessSource.run(ProcessSource.java:41)
[junit] at quarks.runtime.etiao.ThreadFactoryTracker$2.run(ThreadFactoryTracker.java:88)
[junit] at java.lang.Thread.run(Thread.java:745)
[junit] Caused by: java.io.IOException: Broken pipe
[junit] at sun.nio.ch.FileDispatcherImpl.writev0(Native Method)
[junit] at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:51)
[junit] at sun.nio.ch.IOUtil.write(IOUtil.java:148)
[junit] at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:503)
[junit] at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:177)
[junit] ... 36 more
[junit]
[junit] Apr 06, 2016 4:49:19 PM quarks.connectors.runtime.Connector setStateUnsafe
[junit] INFO: WSCLIENT 4794d2a8 sid=websocket-1 state DISCONNECTED (was CONNECTED)
[junit] Apr 06, 2016 4:49:19 PM quarks.connectors.runtime.Connector setStateUnsafe
[junit] INFO: WSCLIENT 4794d2a8 sid=websocket-1 state CONNECTING (was DISCONNECTED)
[junit] Apr 06, 2016 4:49:19 PM quarks.connectors.wsclient.javax.websocket.runtime.WebSocketClientConnector doConnect
[junit] INFO: WSCLIENT 4794d2a8 sid=websocket-1 connecting uri=ws://localhost:39504/echo
[junit] Apr 06, 2016 4:49:19 PM quarks.connectors.wsclient.javax.websocket.runtime.WebSocketClientConnector onError
[junit] SEVERE: WSCLIENT 4794d2a8 sid=websocket-1 onError java.net.ConnectException: Connection refused
[junit] Apr 06, 2016 4:49:19 PM quarks.connectors.runtime.Connector oneConnect
[junit] SEVERE: WSCLIENT 4794d2a8 sid=websocket-1 doConnect() failed
[junit] java.net.ConnectException: Connection refused
[junit] at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
[junit] at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:716)
[junit] at org.eclipse.jetty.io.SelectorManager.finishConnect(SelectorManager.java:337)
[junit] at org.eclipse.jetty.io.ManagedSelector.processConnect(ManagedSelector.java:341)
[junit] at org.eclipse.jetty.io.ManagedSelector.access$900(ManagedSelector.java:56)
[junit] at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.processSelected(ManagedSelector.java:278)
[junit] at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:170)
[junit] at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:162)
[junit] at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.execute(ExecuteProduceConsume.java:101)
[junit] at org.eclipse.jetty.io.ManagedSelector.run(ManagedSelector.java:136)
[junit] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654)
[junit] at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572)
[junit] at java.lang.Thread.run(Thread.java:745)
[junit]
[junit] Apr 06, 2016 4:49:19 PM quarks.connectors.runtime.Connector connectTask
[junit] INFO: WSCLIENT 4794d2a8 sid=websocket-1 connectTask() waiting 2000msec to retry
[junit] Apr 06, 2016 4:49:21 PM org.eclipse.jetty.server.Server doStart
[junit] INFO: jetty-9.3.6.v20151106
[junit] Apr 06, 2016 4:49:21 PM org.eclipse.jetty.server.handler.ContextHandler doStart
[junit] INFO: Started o.e.j.s.ServletContextHandler@70883b6

{/,null,AVAILABLE}

[junit] Apr 06, 2016 4:49:21 PM org.eclipse.jetty.server.AbstractConnector doStart
[junit] INFO: Started ServerConnector@730dee18

{HTTP/1.1,[http/1.1]}{0.0.0.0:39504}
[junit] Apr 06, 2016 4:49:21 PM org.eclipse.jetty.server.Server doStart
[junit] INFO: Started @58932ms
[junit] Apr 06, 2016 4:49:21 PM quarks.connectors.wsclient.javax.websocket.runtime.WebSocketClientConnector doConnect
[junit] INFO: WSCLIENT 4794d2a8 sid=websocket-1 connecting uri=ws://localhost:39504/echo
[junit] Apr 06, 2016 4:49:21 PM quarks.connectors.wsclient.javax.websocket.runtime.WebSocketClientConnector doConnect
[junit] INFO: WSCLIENT 4794d2a8 sid=websocket-2 connected uri=ws://localhost:39504/echo
[junit] Apr 06, 2016 4:49:21 PM quarks.connectors.runtime.Connector setStateUnsafe
[junit] INFO: WSCLIENT 4794d2a8 sid=websocket-2 state CONNECTED (was CONNECTING)
[junit] Apr 06, 2016 4:49:32 PM quarks.runtime.etiao.Executable$1 accept
[junit] INFO: No more active user tasks
[junit] Apr 06, 2016 4:49:32 PM quarks.connectors.runtime.Connector close
[junit] INFO: Connection WSCLIENT 4794d2a8 sid=websocket-2 closing
[junit] Apr 06, 2016 4:49:32 PM quarks.connectors.runtime.Connector setStateUnsafe
[junit] INFO: WSCLIENT 4794d2a8 sid=websocket-2 state CLOSING (was CONNECTED)
[junit] Apr 06, 2016 4:49:32 PM quarks.connectors.runtime.Connector setStateUnsafe
[junit] INFO: WSCLIENT 4794d2a8 sid=websocket-2 state CLOSED (was CLOSING)
[junit] Apr 06, 2016 4:49:32 PM org.eclipse.jetty.server.AbstractConnector doStop
[junit] INFO: Stopped ServerConnector@730dee18{HTTP/1.1,[http/1.1]} {0.0.0.0:39504}

Issue Links

• links to: GitHub Pull Request #119