UdpAcceptorIT.concurrentConnections is failing intermittently

[jitsni]

UdpAcceptorIT.concurrentConnections[0] FAILED with exception org.junit.ComparisonFailure: Specified behavior did not match expected:<...ected
write "Hello"
[read "Hello"
write "Goodbye"
read "Goodbye"
close
closed]

but was:<...ected
write "Hello"
[]
(10.26 secs)
org.junit.ComparisonFailure: Specified behavior did not match expected:<...ected
write "Hello"
[read "Hello"
write "Goodbye"
read "Goodbye"
close
closed]
but was:<...ected
write "Hello"
[]

at org.junit.Assert.assertEquals(Assert.java:115)
at org.kaazing.k3po.junit.rules.SpecificationStatement.evaluate(SpecificationStatement.java:94)
at org.junit.rules.Verifier$1.evaluate(Verifier.java:35)
at org.kaazing.gateway.transport.udp.UdpAcceptorRule$AcceptorStatement.evaluate(UdpAcceptorRule.java:121)
at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
at org.junit.rules.RunRules.evaluate(RunRules.java:20)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at org.junit.runners.Suite.runChild(Suite.java:128)
at org.junit.runners.Suite.runChild(Suite.java:27)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:367)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:274)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:161)
at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290)
at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242)
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:121)

Caused by: org.junit.runners.model.MultipleFailureException: There were 2 errors:
org.junit.runners.model.TestTimedOutException(test timed out after 10 seconds)
java.lang.Exception(Appears to be stuck in thread New I/O worker #16)
at org.junit.internal.runners.statements.FailOnTimeout.createTimeoutException(FailOnTimeout.java:168)
at org.junit.internal.runners.statements.FailOnTimeout.getResult(FailOnTimeout.java:151)
at org.junit.internal.runners.statements.FailOnTimeout.evaluate(FailOnTimeout.java:127)
at org.kaazing.k3po.junit.rules.SpecificationStatement.evaluate(SpecificationStatement.java:63)
... 28 more
=================== BEGIN STORED LOG MESSAGES ===========================
Printing last 22 of 22 log messages
3975 transport.udp.accept [Time-limited test] DEBUG accept - UDP acceptor: worker count = 2
3981 org.kaazing.gateway.transport.nio.internal.AbstractNioAcceptor [Time-limited test] INFO AbstractNioAcceptor - Bound to resource: udp://127.0.0.1:8080
3988 transport.tcp.accept [New I/O udp boss #18] DEBUG accept - nextWorker: returning worker #1 of 2
3994 transport.tcp.accept [New I/O udp boss #18] DEBUG accept - nextWorker: returning worker #2 of 2
3998 transport.udp.accept [New I/O worker #16] INFO accept - [udp#10 127.0.0.1:34730] OPENED: (#10: kaazing niodatagramchannel, server, /127.0.0.1:34730 => /127.0.0.1:8080)
3998 transport.udp.accept [New I/O worker #16] TRACE accept - [udp#10 127.0.0.1:34730] RECEIVED: HeapBuffer[pos=0 lim=5 cap=5: 48 65 6C 6C 6F]
3998 transport.udp.accept [New I/O worker #16] TRACE accept - [udp#10 127.0.0.1:34730] WRITE: HeapBuffer[pos=0 lim=5 cap=5: 48 65 6C 6C 6F]
3999 transport.tcp.accept [New I/O udp boss #18] DEBUG accept - nextWorker: returning worker #1 of 2
4002 transport.udp.accept [New I/O worker #17] INFO accept - [udp#11 127.0.0.1:39981] OPENED: (#11: kaazing niodatagramchannel, server, /127.0.0.1:39981 => /127.0.0.1:8080)
4002 transport.udp.accept [New I/O worker #17] TRACE accept - [udp#11 127.0.0.1:39981] RECEIVED: HeapBuffer[pos=0 lim=5 cap=5: 48 65 6C 6C 6F]
4009 transport.udp.accept [New I/O worker #17] TRACE accept - [udp#11 127.0.0.1:39981] WRITE: HeapBuffer[pos=0 lim=5 cap=5: 48 65 6C 6C 6F]
4018 transport.udp.accept [New I/O worker #16] INFO accept - [udp#12 127.0.0.1:37003] OPENED: (#12: kaazing niodatagramchannel, server, /127.0.0.1:37003 => /127.0.0.1:8080)
4018 transport.udp.accept [New I/O worker #16] TRACE accept - [udp#10 127.0.0.1:34730] RECEIVED: HeapBuffer[pos=0 lim=7 cap=7: 47 6F 6F 64 62 79 65]
4018 transport.udp.accept [New I/O worker #16] TRACE accept - [udp#10 127.0.0.1:34730] WRITE: HeapBuffer[pos=0 lim=7 cap=7: 47 6F 6F 64 62 79 65]
4019 transport.udp.accept [New I/O worker #17] TRACE accept - [udp#11 127.0.0.1:39981] RECEIVED: HeapBuffer[pos=0 lim=7 cap=7: 47 6F 6F 64 62 79 65]
4019 transport.udp.accept [New I/O worker #17] TRACE accept - [udp#11 127.0.0.1:39981] WRITE: HeapBuffer[pos=0 lim=7 cap=7: 47 6F 6F 64 62 79 65]
6096 org.kaazing.mina.netty.socket.nio.NioDatagramChannelIoSession [New I/O worker #16] TRACE NioDatagramChannelIoSession - Closing udp session (#12: kaazing niodatagramchannel, server, /127.0.0.1:37003 => /127.0.0.1:8080) since it is idle
6097 transport.udp.accept [New I/O worker #16] INFO accept - [udp#12 127.0.0.1:37003] CLOSED: (#12: kaazing niodatagramchannel, server, /127.0.0.1:37003 => /127.0.0.1:8080)
6097 org.kaazing.mina.netty.socket.nio.NioDatagramChannelIoSession [New I/O worker #16] TRACE NioDatagramChannelIoSession - Closing udp session (#10: kaazing niodatagramchannel, server, /127.0.0.1:34730 => /127.0.0.1:8080) since it is idle
6098 transport.udp.accept [New I/O worker #16] INFO accept - [udp#10 127.0.0.1:34730] CLOSED: (#10: kaazing niodatagramchannel, server, /127.0.0.1:34730 => /127.0.0.1:8080)
6101 org.kaazing.mina.netty.socket.nio.NioDatagramChannelIoSession [New I/O worker #17] TRACE NioDatagramChannelIoSession - Closing udp session (#11: kaazing niodatagramchannel, server, /127.0.0.1:39981 => /127.0.0.1:8080) since it is idle
6101 transport.udp.accept [New I/O worker #17] INFO accept - [udp#11 127.0.0.1:39981] CLOSED: (#11: kaazing niodatagramchannel, server, /127.0.0.1:39981 => /127.0.0.1:8080)
=================== END STORED LOG MESSAGES ===========================

[dpwspoon]

Seen again in travis

[jitsni]

# Stream 3
connect await BOUND
        udp://localhost:8080
connected
write "Hello"
read "Hello"
write "Goodbye"
read "HelloGo"]

See the last line, it seems like "Hello" and "Goodbye" are combined. I think this is a bug in udp impl. Some investigation needs to be be done how buffers and threads interact in gateway. It could also be k3po issue. Let us ignore the test until this is fixed.

[jitsni]

PR #820 may fix this issue.