[ 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)