edgent-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Dale LaBossiere (JIRA)" <j...@apache.org>
Subject [jira] [Closed] (EDGENT-122) WebSocketClientTest intermittent travis build failure
Date Tue, 28 Feb 2017 16:41:45 GMT

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

Mime
View raw message