ice icon indicating copy to clipboard operation
ice copied to clipboard
verified publisher icon zeroc-ice

java/Ice/background test failure (Ubuntu)

Open bernardnormier opened this issue 1 year ago • 2 comments

See https://github.com/zeroc-ice/ice/actions/runs/11386279184/job/31678101597?pr=2907

*** [215/312] Running java/Ice/background tests ***
[ running client/server test - 10/17/24 14:36:23 ]
- Config: ssl
(/opt/hostedtoolcache/Java_Oracle_jdk/17/x64/bin/java -ea -Djdk.net.URLClassPath.disableClassPathURLCheck=true -Dtest.class=test.Ice.background.Server test.TestDriver --Ice.Default.Host=127.0.0.1 --Test.BasePort=14200 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ssl --Ice.IPv6=0 --IceSSL.*** --IceSSL.DefaultDir=/home/runner/work/ice/ice/certs --IceSSL.Keystore=server.jks --Ice.ThreadPool.Server.Size=1 --Ice.ThreadPool.Server.SizeMax=3 --Ice.ThreadPool.Server.SizeWarn=0 --Ice.PrintAdapterReady=1 env={'CLASSPATH': '/home/runner/work/ice/ice/java/lib/test.jar'})
(/opt/hostedtoolcache/Java_Oracle_jdk/17/x64/bin/java -ea -Djdk.net.URLClassPath.disableClassPathURLCheck=true -Dtest.class=test.Ice.background.Client test.TestDriver --Ice.Default.Host=127.0.0.1 --Test.BasePort=14200 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ssl --Ice.IPv6=0 --IceSSL.*** --IceSSL.DefaultDir=/home/runner/work/ice/ice/certs --IceSSL.Keystore=client.jks env={'CLASSPATH': '/home/runner/work/ice/ice/java/lib/test.jar'})
testing connect... ok
testing initialization... ok
testing connection validation... com.zeroc.Ice.ConnectionAbortedException: Connection aborted by the idle check because it did not receive any bytes for 60s.
	at com.zeroc.Ice.OutgoingAsync.waitForResponseOrUserEx(OutgoingAsync.java:110)
	at com.zeroc.Ice.OutgoingAsync.waitForResponse(OutgoingAsync.java:93)
	at test.Ice.background.Test.BackgroundControllerPrx.holdAdapter(BackgroundControllerPrx.java:99)
	at test.Ice.background.Test.BackgroundControllerPrx.holdAdapter(BackgroundControllerPrx.java:94)
	at test.Ice.background.AllTests.validationTests(AllTests.java:710)
	at test.Ice.background.AllTests.allTests(AllTests.java:159)
	at test.Ice.background.Client.run(Client.java:40)
	at test.TestDriver.main(TestDriver.java:26)

bernardnormier avatar Oct 17 '24 15:10 bernardnormier

The log files from https://github.com/zeroc-ice/ice/actions/runs/11411974091/job/31757173288 suggests a deadlock in ObjectAdapter::hold.

Note that the adapter processing the request is different from the object adapter being held here:

client

-- 10/18/24 23:25:11:868 Protocol: sending batch request 
   message type = 1 (batch request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 524346
   number of requests = 1
   request #0:
   identity = background
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 10/18/24 23:25:11:885 Protocol: sending close connection 
   message type = 4 (close connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 10/18/24 23:25:11:887 Network: closed ssl connection
   local address = 127.0.0.1:42246
   remote address = 127.0.0.1:14100
-- 10/18/24 23:25:11:888 Protocol: sending request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 61
   request id = 43
   identity = backgroundController
   facet = 
   operation = holdAdapter
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 10/18/24 23:25:41:888 Protocol: sending validate connection 
   message type = 3 (validate connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 10/18/24 23:26:11:738 Network: connection aborted by the idle check because it did not receive any bytes for 60s
   local address = 127.0.0.1:55744
   remote address = 127.0.0.1:14101
-- 10/18/24 23:26:11:743 Network: closed tcp connection
   local address = 127.0.0.1:55744
   remote address = 127.0.0.1:14101

server

-- 10/18/24 23:25:11:887 Protocol: received close connection 
   message type = 4 (close connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 10/18/24 23:25:11:887 Network: closed ssl connection
   local address = 127.0.0.1:14100
   remote address = 127.0.0.1:42246
-- 10/18/24 23:25:11:888 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 61
   request id = 43
   identity = backgroundController
   facet = 
   operation = holdAdapter
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 10/18/24 23:25:11:888 Network: holding ssl connections at 127.0.0.1:14100

bernardnormier avatar Oct 19 '24 15:10 bernardnormier

#2937 may fix this bug.

bernardnormier avatar Oct 19 '24 15:10 bernardnormier

Still failing after #2937:

https://github.com/zeroc-ice/ice/actions/runs/11446667739/job/31846333775

*** [176/311] Running java/Ice/background tests ***
[ running client/server test - 10/21/24 19:19:48 ]
- Config: ssl
(/opt/hostedtoolcache/Java_Oracle_jdk/17/x64/bin/java -ea -Djdk.net.URLClassPath.disableClassPathURLCheck=true -Dtest.class=test.Ice.background.Server test.TestDriver --Ice.Default.Host=127.0.0.1 --Test.BasePort=14200 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ssl --Ice.IPv6=0 --IceSSL.*** --IceSSL.DefaultDir=/home/runner/work/ice/ice/certs --IceSSL.Keystore=server.jks --Ice.ThreadPool.Server.Size=1 --Ice.ThreadPool.Server.SizeMax=3 --Ice.ThreadPool.Server.SizeWarn=0 --Ice.PrintAdapterReady=1 --Ice.Trace.Network=2 --Ice.Trace.Protocol=1 --Ice.LogFile=/home/runner/work/ice/ice/java/test/src/main/java/test/Ice/background/server-102124-1919.log env={'CLASSPATH': '/home/runner/work/ice/ice/java/lib/test.jar'})
(/opt/hostedtoolcache/Java_Oracle_jdk/17/x64/bin/java -ea -Djdk.net.URLClassPath.disableClassPathURLCheck=true -Dtest.class=test.Ice.background.Client test.TestDriver --Ice.Default.Host=127.0.0.1 --Test.BasePort=14200 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ssl --Ice.IPv6=0 --IceSSL.*** --IceSSL.DefaultDir=/home/runner/work/ice/ice/certs --IceSSL.Keystore=client.jks --Ice.Trace.Network=2 --Ice.Trace.Protocol=1 --Ice.LogFile=/home/runner/work/ice/ice/java/test/src/main/java/test/Ice/background/client-102124-1919.log env={'CLASSPATH': '/home/runner/work/ice/ice/java/lib/test.jar'})
testing connect... ok
testing initialization... ok
testing connection validation... com.zeroc.Ice.ConnectionAbortedException: Connection aborted by the idle check because it did not receive any bytes for 60s.
	at com.zeroc.Ice.OutgoingAsync.waitForResponseOrUserEx(OutgoingAsync.java:110)
	at com.zeroc.Ice.OutgoingAsync.waitForResponse(OutgoingAsync.java:93)
	at test.Ice.background.Test.BackgroundControllerPrx.holdAdapter(BackgroundControllerPrx.java:99)
	at test.Ice.background.Test.BackgroundControllerPrx.holdAdapter(BackgroundControllerPrx.java:94)
	at test.Ice.background.AllTests.validationTests(AllTests.java:712)
	at test.Ice.background.AllTests.allTests(AllTests.java:161)
	at test.Ice.background.Client.run(Client.java:40)
	at test.TestDriver.main(TestDriver.java:26)
saved /home/runner/work/ice/ice/java/test/src/main/java/test/Ice/background/client-102124-1919.log
saved /home/runner/work/ice/ice/java/test/src/main/java/test/Ice/background/server-102124-1919.log

client:

-- 10/21/24 19:19:55:336 Protocol: sending batch request 
   message type = 1 (batch request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 114
   number of requests = 4
   request #0:
   identity = background
   facet = 
   operation = op
   mode = 0 (normal)
   context = 
   encoding = 1.1
   request #1:
   identity = background
   facet = 
   operation = op
   mode = 0 (normal)
   context = 
   encoding = 1.1
   request #2:
   identity = background
   facet = 
   operation = op
   mode = 0 (normal)
   context = 
   encoding = 1.1
   request #3:
   identity = background
   facet = 
   operation = op
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 10/21/24 19:19:55:337 Protocol: sending close connection 
   message type = 4 (close connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 10/21/24 19:19:55:338 Network: closed ssl connection
   local address = 127.0.0.1:59798
   remote address = 127.0.0.1:14200
-- 10/21/24 19:19:55:339 Protocol: sending request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 61
   request id = 45
   identity = backgroundController
   facet = 
   operation = holdAdapter
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 10/21/24 19:20:25:339 Protocol: sending validate connection 
   message type = 3 (validate connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 10/21/24 19:20:55:311 Network: connection aborted by the idle check because it did not receive any bytes for 60s
   local address = 127.0.0.1:46328
   remote address = 127.0.0.1:14201
-- 10/21/24 19:20:55:312 Network: closed tcp connection
   local address = 127.0.0.1:46328
   remote address = 127.0.0.1:14201

server:

-- 10/21/24 19:19:55:338 Protocol: received batch request 
   message type = 1 (batch request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 114
   number of requests = 4
   request #0:
   identity = background
   facet = 
   operation = op
   mode = 0 (normal)
   context = 
   encoding = 1.1
   request #1:
   identity = background
   facet = 
   operation = op
   mode = 0 (normal)
   context = 
   encoding = 1.1
   request #2:
   identity = background
   facet = 
   operation = op
   mode = 0 (normal)
   context = 
   encoding = 1.1
   request #3:
   identity = background
   facet = 
   operation = op
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 10/21/24 19:19:55:338 Protocol: received close connection 
   message type = 4 (close connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 10/21/24 19:19:55:338 Network: closed ssl connection
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:59798
-- 10/21/24 19:19:55:339 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 61
   request id = 45
   identity = backgroundController
   facet = 
   operation = holdAdapter
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 10/21/24 19:19:55:339 Network: holding ssl connections at 127.0.0.1:14200

bernardnormier avatar Oct 22 '24 14:10 bernardnormier

I can reproduce locally. I've attached the logs with tracing enabled from https://github.com/zeroc-ice/ice/commit/fad93220b71cd3c587379bda4f7f2d7a86aeb649

client-102324-1351.log server-102324-1351.log

externl avatar Oct 23 '24 13:10 externl

I disabled the idle check and grabbed the stack of the server.

2024-10-23 14:09:29
Full thread dump Java HotSpot(TM) 64-Bit Server VM (17.0.12+8-LTS-286 mixed mode, sharing):

Threads class SMR info:
_java_thread_list=0x0000ffff3c002770, length=18, elements={
0x0000ffff90023630, 0x0000ffff90125690, 0x0000ffff90126b10, 0x0000ffff9012c070,
0x0000ffff9012d4c0, 0x0000ffff9012e900, 0x0000ffff90130270, 0x0000ffff901317d0,
0x0000ffff90132c70, 0x0000ffff9013a010, 0x0000ffff9013d8b0, 0x0000ffff9025c590,
0x0000ffff9031bd30, 0x0000ffff90328a10, 0x0000fffef805cf70, 0x0000fffef809f150,
0x0000fffee80278d0, 0x0000ffff3c0017b0
}

"main" #1 prio=5 os_prio=0 cpu=173.10ms elapsed=61.30s tid=0x0000ffff90023630 nid=0x15266 in Object.wait()  [0x0000ffff981fe000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait([email protected]/Native Method)
	- waiting on <0x0000000083ed1400> (a com.zeroc.Ice.ObjectAdapterFactory)
	at java.lang.Object.wait([email protected]/Object.java:338)
	at com.zeroc.Ice.ObjectAdapterFactory.waitForShutdown(ObjectAdapterFactory.java:39)
	- locked <0x0000000083ed1400> (a com.zeroc.Ice.ObjectAdapterFactory)
	at com.zeroc.Ice.Communicator.waitForShutdown(Communicator.java:76)
	at test.Ice.background.Server.run(Server.java:125)
	at test.TestDriver.main(TestDriver.java:26)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=0.24ms elapsed=61.26s tid=0x0000ffff90125690 nid=0x1526e waiting on condition  [0x0000ffff7480c000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.ref.Reference.waitForReferencePendingList([email protected]/Native Method)
	at java.lang.ref.Reference.processPendingReferences([email protected]/Reference.java:253)
	at java.lang.ref.Reference$ReferenceHandler.run([email protected]/Reference.java:215)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.15ms elapsed=61.25s tid=0x0000ffff90126b10 nid=0x1526f in Object.wait()  [0x0000ffff7440c000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait([email protected]/Native Method)
	- waiting on <0x0000000083ed1b40> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:155)
	- locked <0x0000000083ed1b40> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run([email protected]/Finalizer.java:172)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.20ms elapsed=61.25s tid=0x0000ffff9012c070 nid=0x15270 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #5 daemon prio=9 os_prio=0 cpu=0.11ms elapsed=61.25s tid=0x0000ffff9012d4c0 nid=0x15271 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Monitor Deflation Thread" #6 daemon prio=9 os_prio=0 cpu=3.20ms elapsed=61.25s tid=0x0000ffff9012e900 nid=0x15272 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #7 daemon prio=9 os_prio=0 cpu=386.97ms elapsed=61.25s tid=0x0000ffff90130270 nid=0x15273 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"C1 CompilerThread0" #8 daemon prio=9 os_prio=0 cpu=305.10ms elapsed=61.24s tid=0x0000ffff901317d0 nid=0x15274 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"Sweeper thread" #9 daemon prio=9 os_prio=0 cpu=0.06ms elapsed=61.24s tid=0x0000ffff90132c70 nid=0x15275 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Notification Thread" #10 daemon prio=9 os_prio=0 cpu=0.04ms elapsed=61.24s tid=0x0000ffff9013a010 nid=0x15276 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Common-Cleaner" #11 daemon prio=8 os_prio=0 cpu=0.27ms elapsed=61.23s tid=0x0000ffff9013d8b0 nid=0x15278 in Object.wait()  [0x0000ffff6da0c000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait([email protected]/Native Method)
	- waiting on <no object reference available>
	at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:155)
	- locked <0x0000000083ed1d50> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run([email protected]/CleanerImpl.java:140)
	at java.lang.Thread.run([email protected]/Thread.java:842)
	at jdk.internal.misc.InnocuousThread.run([email protected]/InnocuousThread.java:162)

"Ice.ThreadPool.Client-0" #12 prio=5 os_prio=0 cpu=1.92ms elapsed=61.04s tid=0x0000ffff9025c590 nid=0x15279 runnable  [0x0000ffff6d60b000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.EPoll.wait([email protected]/Native Method)
	at sun.nio.ch.EPollSelectorImpl.doSelect([email protected]/EPollSelectorImpl.java:118)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
	- locked <0x0000000083ed2068> (a sun.nio.ch.Util$2)
	- locked <0x0000000083ed2018> (a sun.nio.ch.EPollSelectorImpl)
	at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
	at com.zeroc.Ice.Selector.select(Selector.java:199)
	at com.zeroc.Ice.ThreadPool.run(ThreadPool.java:366)
	at com.zeroc.Ice.ThreadPool$EventHandlerThread.run(ThreadPool.java:662)
	at java.lang.Thread.run([email protected]/Thread.java:842)

"Ice.ThreadPool.Server-0" #13 prio=5 os_prio=0 cpu=215.32ms elapsed=60.86s tid=0x0000ffff9031bd30 nid=0x15282 in Object.wait()  [0x0000ffff6ce0c000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait([email protected]/Native Method)
	- waiting on <no object reference available>
	at com.zeroc.Ice.ThreadPool.followerWait(ThreadPool.java:563)
	- locked <0x000000008b000460> (a com.zeroc.Ice.ThreadPool)
	at com.zeroc.Ice.ThreadPool.run(ThreadPool.java:405)
	- locked <0x000000008b000460> (a com.zeroc.Ice.ThreadPool)
	at com.zeroc.Ice.ThreadPool$EventHandlerThread.run(ThreadPool.java:662)
	at java.lang.Thread.run([email protected]/Thread.java:842)

"ControllerAdapter.ThreadPool-0" #14 prio=5 os_prio=0 cpu=13.50ms elapsed=60.85s tid=0x0000ffff90328a10 nid=0x15283 waiting for monitor entry  [0x0000ffff6ca0b000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at com.zeroc.Ice.ConnectionI.hold(ConnectionI.java:98)
	- waiting to lock <0x000000008ac23e80> (a com.zeroc.Ice.ConnectionI)
	at com.zeroc.Ice.IncomingConnectionFactory.setState(IncomingConnectionFactory.java:497)
	at com.zeroc.Ice.IncomingConnectionFactory.hold(IncomingConnectionFactory.java:33)
	- locked <0x000000008b0fb610> (a com.zeroc.Ice.IncomingConnectionFactory)
	at com.zeroc.Ice.ObjectAdapter.hold(ObjectAdapter.java:172)
	- locked <0x000000008b000000> (a com.zeroc.Ice.ObjectAdapter)
	at test.Ice.background.BackgroundControllerI.holdAdapter(BackgroundControllerI.java:33)
	at test.Ice.background.Test.BackgroundController._iceD_holdAdapter(BackgroundController.java:97)
	at test.Ice.background.Test.BackgroundController.dispatch(BackgroundController.java:209)
	at com.zeroc.Ice.ServantManager.dispatch(ServantManager.java:27)
	at com.zeroc.Ice.LoggerMiddleware.dispatch(LoggerMiddleware.java:25)
	at com.zeroc.Ice.ConnectionI.dispatchAll(ConnectionI.java:2219)
	at com.zeroc.Ice.ConnectionI.upcall(ConnectionI.java:858)
	at com.zeroc.Ice.ConnectionI.message(ConnectionI.java:794)
	at com.zeroc.Ice.ThreadPool.run(ThreadPool.java:352)
	at com.zeroc.Ice.ThreadPool$EventHandlerThread.run(ThreadPool.java:662)
	at java.lang.Thread.run([email protected]/Thread.java:842)

"Ice.Timer" #15 prio=5 os_prio=0 cpu=4.45ms elapsed=60.30s tid=0x0000fffef805cf70 nid=0x1529c waiting for monitor entry  [0x0000ffff6c60c000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at com.zeroc.Ice.ConnectionI.connectTimedOut(ConnectionI.java:2503)
	- waiting to lock <0x000000008ac23e80> (a com.zeroc.Ice.ConnectionI)
	at com.zeroc.Ice.ConnectionI$$Lambda$77/0x00000028010dc000.run(Unknown Source)
	at java.util.concurrent.Executors$RunnableAdapter.call([email protected]/Executors.java:539)
	at java.util.concurrent.FutureTask.run([email protected]/FutureTask.java:264)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run([email protected]/ScheduledThreadPoolExecutor.java:304)
	at java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1136)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:635)
	at java.lang.Thread.run([email protected]/Thread.java:842)

"Ice.ThreadPool.Server-1" #16 prio=5 os_prio=0 cpu=120.83ms elapsed=59.93s tid=0x0000fffef809f150 nid=0x1529d waiting for monitor entry  [0x0000ffff63e0b000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at com.zeroc.Ice.IncomingConnectionFactory.removeConnection(IncomingConnectionFactory.java:600)
	- waiting to lock <0x000000008b0fb610> (a com.zeroc.Ice.IncomingConnectionFactory)
	at com.zeroc.Ice.IncomingConnectionFactory$$Lambda$68/0x00000028010d2160.accept(Unknown Source)
	at com.zeroc.Ice.ConnectionI.sendResponseImpl(ConnectionI.java:2359)
	at com.zeroc.Ice.ConnectionI.sendResponse(ConnectionI.java:2282)
	- locked <0x000000008ac23e80> (a com.zeroc.Ice.ConnectionI)
	at com.zeroc.Ice.ConnectionI.lambda$dispatchAll$0(ConnectionI.java:2233)
	at com.zeroc.Ice.ConnectionI$$Lambda$91/0x00000028010ddfa8.accept(Unknown Source)
	at java.util.concurrent.CompletableFuture.uniWhenComplete([email protected]/CompletableFuture.java:863)
	at java.util.concurrent.CompletableFuture.uniWhenCompleteStage([email protected]/CompletableFuture.java:887)
	at java.util.concurrent.CompletableFuture.whenComplete([email protected]/CompletableFuture.java:2325)
	at java.util.concurrent.CompletableFuture.whenComplete([email protected]/CompletableFuture.java:144)
	at com.zeroc.Ice.ConnectionI.dispatchAll(ConnectionI.java:2225)
	at com.zeroc.Ice.ConnectionI.upcall(ConnectionI.java:858)
	at com.zeroc.Ice.ConnectionI.message(ConnectionI.java:794)
	at com.zeroc.Ice.ThreadPool.run(ThreadPool.java:352)
	at com.zeroc.Ice.ThreadPool$EventHandlerThread.run(ThreadPool.java:662)
	at java.lang.Thread.run([email protected]/Thread.java:842)

"Ice.ThreadPool.Server-2" #17 prio=5 os_prio=0 cpu=116.94ms elapsed=59.83s tid=0x0000fffee80278d0 nid=0x152a0 runnable  [0x0000ffff63a0b000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.EPoll.wait([email protected]/Native Method)
	at sun.nio.ch.EPollSelectorImpl.doSelect([email protected]/EPollSelectorImpl.java:118)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
	- locked <0x000000008b0fbce0> (a sun.nio.ch.Util$2)
	- locked <0x000000008b0fb848> (a sun.nio.ch.EPollSelectorImpl)
	at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
	at com.zeroc.Ice.Selector.select(Selector.java:199)
	at com.zeroc.Ice.ThreadPool.run(ThreadPool.java:366)
	at com.zeroc.Ice.ThreadPool$EventHandlerThread.run(ThreadPool.java:662)
	at java.lang.Thread.run([email protected]/Thread.java:842)

"Attach Listener" #18 daemon prio=9 os_prio=0 cpu=0.20ms elapsed=0.10s tid=0x0000ffff3c0017b0 nid=0x15396 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"VM Thread" os_prio=0 cpu=2.39ms elapsed=61.26s tid=0x0000ffff90121740 nid=0x1526d runnable  

"GC Thread#0" os_prio=0 cpu=8.08ms elapsed=61.30s tid=0x0000ffff9007d150 nid=0x15268 runnable  

"GC Thread#1" os_prio=0 cpu=1.93ms elapsed=60.99s tid=0x0000ffff4c004970 nid=0x1527a runnable  

"G1 Main Marker" os_prio=0 cpu=0.02ms elapsed=61.29s tid=0x0000ffff9008de00 nid=0x15269 runnable  

"G1 Conc#0" os_prio=0 cpu=0.06ms elapsed=61.29s tid=0x0000ffff9008ed80 nid=0x1526a runnable  

"G1 Refine#0" os_prio=0 cpu=0.28ms elapsed=61.28s tid=0x0000ffff900ecdb0 nid=0x1526b runnable  

"G1 Service" os_prio=0 cpu=6.24ms elapsed=61.28s tid=0x0000ffff900edcb0 nid=0x1526c runnable  

"VM Periodic Task Thread" os_prio=0 cpu=17.15ms elapsed=61.23s tid=0x0000ffff9013bac0 nid=0x15277 waiting on condition  

JNI global refs: 12, weak refs: 0


Found one Java-level deadlock:
=============================
"ControllerAdapter.ThreadPool-0":
  waiting to lock monitor 0x0000fffee00481c0 (object 0x000000008ac23e80, a com.zeroc.Ice.ConnectionI),
  which is held by "Ice.ThreadPool.Server-1"

"Ice.ThreadPool.Server-1":
  waiting to lock monitor 0x0000fffee0048dc0 (object 0x000000008b0fb610, a com.zeroc.Ice.IncomingConnectionFactory),
  which is held by "ControllerAdapter.ThreadPool-0"

Java stack information for the threads listed above:
===================================================
"ControllerAdapter.ThreadPool-0":
	at com.zeroc.Ice.ConnectionI.hold(ConnectionI.java:98)
	- waiting to lock <0x000000008ac23e80> (a com.zeroc.Ice.ConnectionI)
	at com.zeroc.Ice.IncomingConnectionFactory.setState(IncomingConnectionFactory.java:497)
	at com.zeroc.Ice.IncomingConnectionFactory.hold(IncomingConnectionFactory.java:33)
	- locked <0x000000008b0fb610> (a com.zeroc.Ice.IncomingConnectionFactory)
	at com.zeroc.Ice.ObjectAdapter.hold(ObjectAdapter.java:172)
	- locked <0x000000008b000000> (a com.zeroc.Ice.ObjectAdapter)
	at test.Ice.background.BackgroundControllerI.holdAdapter(BackgroundControllerI.java:33)
	at test.Ice.background.Test.BackgroundController._iceD_holdAdapter(BackgroundController.java:97)
	at test.Ice.background.Test.BackgroundController.dispatch(BackgroundController.java:209)
	at com.zeroc.Ice.ServantManager.dispatch(ServantManager.java:27)
	at com.zeroc.Ice.LoggerMiddleware.dispatch(LoggerMiddleware.java:25)
	at com.zeroc.Ice.ConnectionI.dispatchAll(ConnectionI.java:2219)
	at com.zeroc.Ice.ConnectionI.upcall(ConnectionI.java:858)
	at com.zeroc.Ice.ConnectionI.message(ConnectionI.java:794)
	at com.zeroc.Ice.ThreadPool.run(ThreadPool.java:352)
	at com.zeroc.Ice.ThreadPool$EventHandlerThread.run(ThreadPool.java:662)
	at java.lang.Thread.run([email protected]/Thread.java:842)
"Ice.ThreadPool.Server-1":
	at com.zeroc.Ice.IncomingConnectionFactory.removeConnection(IncomingConnectionFactory.java:600)
	- waiting to lock <0x000000008b0fb610> (a com.zeroc.Ice.IncomingConnectionFactory)
	at com.zeroc.Ice.IncomingConnectionFactory$$Lambda$68/0x00000028010d2160.accept(Unknown Source)
	at com.zeroc.Ice.ConnectionI.sendResponseImpl(ConnectionI.java:2359)
	at com.zeroc.Ice.ConnectionI.sendResponse(ConnectionI.java:2282)
	- locked <0x000000008ac23e80> (a com.zeroc.Ice.ConnectionI)
	at com.zeroc.Ice.ConnectionI.lambda$dispatchAll$0(ConnectionI.java:2233)
	at com.zeroc.Ice.ConnectionI$$Lambda$91/0x00000028010ddfa8.accept(Unknown Source)
	at java.util.concurrent.CompletableFuture.uniWhenComplete([email protected]/CompletableFuture.java:863)
	at java.util.concurrent.CompletableFuture.uniWhenCompleteStage([email protected]/CompletableFuture.java:887)
	at java.util.concurrent.CompletableFuture.whenComplete([email protected]/CompletableFuture.java:2325)
	at java.util.concurrent.CompletableFuture.whenComplete([email protected]/CompletableFuture.java:144)
	at com.zeroc.Ice.ConnectionI.dispatchAll(ConnectionI.java:2225)
	at com.zeroc.Ice.ConnectionI.upcall(ConnectionI.java:858)
	at com.zeroc.Ice.ConnectionI.message(ConnectionI.java:794)
	at com.zeroc.Ice.ThreadPool.run(ThreadPool.java:352)
	at com.zeroc.Ice.ThreadPool$EventHandlerThread.run(ThreadPool.java:662)
	at java.lang.Thread.run([email protected]/Thread.java:842)

Found 1 deadlock.

server-jstack.txt

externl avatar Oct 23 '24 14:10 externl