TcpSocketConsumer java.lang.AssertionError: Found tid=1486392198574 in the old map

[amichair]

While trying to use ChronicleEngine to access a queue remotely, we occasionally see the following AssertionError (once every few runs):

524748  [1, Demo Asset remote]
2017-02-06T16:43:18.847 /TcpChannelHub-Reads-(none) TcpSocketConsumer java.lang.AssertionError: Found tid=1486392198574 in the old map.
        at net.openhft.chronicle.network.connection.TcpChannelHub$TcpSocketConsumer.processData(TcpChannelHub.java:1346)
        at net.openhft.chronicle.network.connection.TcpChannelHub$TcpSocketConsumer.running(TcpChannelHub.java:1231)
        at net.openhft.chronicle.network.connection.TcpChannelHub$TcpSocketConsumer.lambda$start$3(TcpChannelHub.java:1160)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

and sometimes (not always) it is then immediately followed in the logs by this:

525660  [2, Demo Asset remote]
2017-02-06T16:43:18.852 tree-1/conc-event-loop-0 TcpEventHandler java.io.IOException: Broken pipe
        at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
        at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
        at sun.nio.ch.IOUtil.write(IOUtil.java:51)
        at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
        at net.openhft.chronicle.network.TcpEventHandler.tryWrite(TcpEventHandler.java:332)
        at net.openhft.chronicle.network.TcpEventHandler.invokeHandler(TcpEventHandler.java:253)
        at net.openhft.chronicle.network.TcpEventHandler.action(TcpEventHandler.java:183)
        at net.openhft.chronicle.threads.VanillaEventLoop.runAllMediumHandler(VanillaEventLoop.java:286)
        at net.openhft.chronicle.threads.VanillaEventLoop.run(VanillaEventLoop.java:206)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

After the assertion error (with or without the IOException) the logs are silent for a few seconds, and then there is what appears to be a loop of acquires and releases (onAcquired/onReleased callbacks) that never stops.

Being an assertion, I take it to mean it's a code error that should never occur, but the cryptic message doesn't help much in understanding what the issue is... we hope it means something to you and can be fixed soon :-)

[RobAustin]

Which version are you using ? Have you tried updating to the latest ?

[RobAustin]

Was it working an then after an upgrade stopped working? or has it never worked for you ?

[amichair]

We're stuck on queue 4.5.16 and engine 1.13.21 until the resource leaks and weakreference errors issues are resolved (separate issues open for that). I just tried with the latest 4.5.25 and 1.13.26, and it still happens though possibly less often (or maybe it's just s fluke in tests). We only recently started trying to use the engine and remote access to the queue, so I can't say if it's something that broke recently or not - we see it since we started testing.

[RobAustin]

could you write a unit test that reproduces this issue( submit it via a pull request), I'll then fix it.

[RobAustin]

@amichair closing this as we don't have a unit test