search

zeroc-ice / ice

All-in-one solution for creating networked applications with RPC, pub/sub, server deployment, and more.
https://zeroc.com
GNU General Public License v2.0
2k stars 592 forks source link

Ice/adapterDeactivation Java assertion and hang on Windows in CI #2334

Closed bernardnormier closed 2 days ago

bernardnormier commented 1 week ago

Seems to happen from time to time:

https://github.com/zeroc-ice/ice/actions/runs/9614875377/job/26520770057

[ running client/server test - 06/21/24 15:24:30 ]
- Config: ws,compress,ipv6,serialize,mx,x64
(C:\hostedtoolcache\windows\Java_Oracle_jdk\17\x64\bin\java -ea -Dtest.class=test.Ice.adapterDeactivation.Server test.TestDriver --Ice.Default.Host=::1 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ws --Ice.Override.Compress=1 --Ice.ThreadPool.Server.Serialize=1 --Ice.IPv6=1 --Ice.PreferIPv6Address=1 --Ice.Admin.Endpoints="tcp -h \"::1\"" --Ice.Admin.InstanceName=Server --IceMX.Metrics.Debug.GroupBy=id --IceMX.Metrics.Parent.GroupBy=parent --IceMX.Metrics.All.GroupBy=none --Ice.ThreadPool.Server.Size=1 --Ice.ThreadPool.Server.SizeMax=3 --Ice.ThreadPool.Server.SizeWarn=0 --Ice.PrintAdapterReady=1 env={'CLASSPATH': 'D:\\a\\ice\\ice\\java\\lib\\test.jar'})
(C:\hostedtoolcache\windows\Java_Oracle_jdk\17\x64\bin\java -ea -Dtest.class=test.Ice.adapterDeactivation.Client test.TestDriver --Ice.Default.Host=::1 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ws --Ice.Override.Compress=1 --Ice.ThreadPool.Server.Serialize=1 --Ice.IPv6=1 --Ice.PreferIPv6Address=1 --Ice.Admin.Endpoints="tcp -h \"::1\"" --Ice.Admin.InstanceName=Client --IceMX.Metrics.Debug.GroupBy=id --IceMX.Metrics.Parent.GroupBy=parent --IceMX.Metrics.All.GroupBy=none env={'CLASSPATH': 'D:\\a\\ice\\ice\\java\\lib\\test.jar'})
testing stringToProxy... ok
testing checked cast... ok
creating/destroying/recreating object adapter... ok
creating/activating/deactivating object adapter in one operation... ok
testing connection closure... Exception in thread "Ice.ThreadPool.Client-0" java.lang.AssertionError
    at com.zeroc.Ice.ConnectionI.setState(ConnectionI.java:1507)
    at com.zeroc.Ice.ConnectionI.finish(ConnectionI.java:1132)
    at com.zeroc.Ice.ConnectionI.finished(ConnectionI.java:992)
    at com.zeroc.IceInternal.ThreadPool$FinishedWorkItem.execute(ThreadPool.java:27)
    at com.zeroc.IceInternal.ThreadPoolWorkQueue.message(ThreadPoolWorkQueue.java:56)
    at com.zeroc.IceInternal.ThreadPool.run(ThreadPool.java:332)
    at com.zeroc.IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:629)
    at java.base/java.lang.Thread.run(Thread.java:842)
Exception in thread "main" java.lang.AssertionError
    at com.zeroc.IceInternal.Instance.destroy(Instance.java:1292)
    at com.zeroc.Ice.Communicator.close(Communicator.java:28)
    at test.Ice.adapterDeactivation.AllTests.allTests(AllTests.java:67)
    at test.Ice.adapterDeactivation.Client.run(Client.java:12)
    at test.TestDriver.main(TestDriver.java:14)
process C:\hostedtoolcache\windows\Java_Oracle_jdk\17\x64\bin\java -ea -Dtest.class=test.Ice.adapterDeactivation.Client test.TestDriver --Ice.Default.Host=::1 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ws --Ice.Override.Compress=1 --Ice.ThreadPool.Server.Serialize=1 --Ice.IPv6=1 --Ice.PreferIPv6Address=1 --Ice.Admin.Endpoints="tcp -h \"::1\"" --Ice.Admin.InstanceName=Client --IceMX.Metrics.Debug.GroupBy=id --IceMX.Metrics.Parent.GroupBy=parent --IceMX.Metrics.All.GroupBy=none pid=1920 is hanging - 06/21/24 15:26:01
bernardnormier commented 1 week ago

The assert is we setState(StateFinished) when the current state is not StateClosed.

bentoi commented 6 days ago

It's not clear why we only get this now!

I think the problem is that finished might be called before setState releases the connection's mutex.

It might be ran as soon as _threadPool.finish() is called here: https://github.com/zeroc-ice/ice/blob/355bea22355a8791daa72ef24f5b47be2b20c301/java/src/Ice/src/main/java/com/zeroc/Ice/ConnectionI.java#L1505

At this point _state is not set yet to StateClosed.

We can add locking in ConnectionI.finished and an assert(_state == StateClosed).

Adding locking in finish is not strictly necessary because it's only ran in the StateClosed state and all the data members it accesses are immutable at this point. We can locking however and some assert to ensure the state is still StateClosed.

bentoi commented 6 days ago

I was able to reproduce on macOS after 57 iterations, same configuration (on main).

bentoi commented 6 days ago

In 3.7, ConnectionI.finished locks the connection to unschedule the timeout so ConnectionI.finished can't execute until the lock held while setState is executed is released.

And once the state is set to StateClosed, the data members used by finish are guaranteed to be immutable.

bernardnormier commented 6 days ago

Indeed, it could be because in 3.7 we had: https://github.com/zeroc-ice/ice/blob/b08306ef3bf16a7ecadf558375b2eb4f14336047/java/src/Ice/src/main/java/com/zeroc/Ice/ConnectionI.java#L1373

whereas on main I removed the synchronized(this) alongside the connection timeouts:

https://github.com/zeroc-ice/ice/blob/355bea22355a8791daa72ef24f5b47be2b20c301/java/src/Ice/src/main/java/com/zeroc/Ice/ConnectionI.java#L959