You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@edgent.apache.org by "Dale LaBossiere (JIRA)" <ji...@apache.org> on 2017/02/28 16:41:45 UTC
[jira] [Closed] (EDGENT-122) WebSocketClientTest intermittent
travis build failure
[ https://issues.apache.org/jira/browse/EDGENT-122?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Dale LaBossiere closed EDGENT-122.
----------------------------------
Resolution: Fixed
pretty outdated and haven't been seeing these so closing.
> WebSocketClientTest intermittent travis build failure
> -----------------------------------------------------
>
> Key: EDGENT-122
> URL: https://issues.apache.org/jira/browse/EDGENT-122
> Project: Edgent
> Issue Type: Bug
> Components: Connectors
> Reporter: Dale LaBossiere
> Assignee: Dale LaBossiere
> Priority: Minor
>
> 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}
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)