ice
ice copied to clipboard
zeroc-ice
java/Ice/idleTimeout failure (Windows, release)
From: https://github.com/zeroc-ice/ice/actions/runs/12874689581/job/35894581750?pr=3388
*** [174/272] Running java/Ice/idleTimeout tests ***
[ running client/server test - 01/20/25 20:39:35 ]
- Config: ssl,x64
(C:\hostedtoolcache\windows\Java_Oracle_jdk\17\x64\bin\java -ea -Dtest.class=test.Ice.idleTimeout.Server test.TestDriver --Ice.Default.Host=127.0.0.1 --Test.BasePort=14000 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ssl --Ice.IPv6=0 --IceSSL.*** --IceSSL.DefaultDir=D:\a\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': 'D:\\a\\ice\\ice\\java\\lib\\test.jar'})
(C:\hostedtoolcache\windows\Java_Oracle_jdk\17\x64\bin\java -ea -Dtest.class=test.Ice.idleTimeout.Client test.TestDriver --Ice.Default.Host=127.0.0.1 --Test.BasePort=14000 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ssl --Ice.IPv6=0 --IceSSL.*** --IceSSL.DefaultDir=D:\a\ice\ice\certs --IceSSL.Keystore=client.jks env={'CLASSPATH': 'D:\\a\\ice\\ice\\java\\lib\\test.jar'})
testing that the idle check does not abort a back-pressured connection... ok
testing that the idle check aborts a connection that does not receive anything for 1s... java.lang.RuntimeException
at test.Ice.idleTimeout.AllTests.test(AllTests.java:158)
at test.Ice.idleTimeout.AllTests.testConnectionAbortedByIdleCheck(AllTests.java:92)
at test.Ice.idleTimeout.AllTests.allTests(AllTests.java:27)
at test.Ice.idleTimeout.Client.run(Client.java:13)
at test.TestDriver.main(TestDriver.java:26)
Failed again in https://github.com/zeroc-ice/ice/actions/runs/12885418192/job/35923821724
2025-01-21T11:53:53.0252908Z *** [174/272] Running java/Ice/idleTimeout tests ***
2025-01-21T11:53:53.0254504Z [ running client/server test - 01/21/25 11:53:46 ]
2025-01-21T11:53:53.0256561Z - Config: ssl,x64
2025-01-21T11:53:53.0262878Z (C:\hostedtoolcache\windows\Java_Oracle_jdk\17\x64\bin\java -ea -Dtest.class=test.Ice.idleTimeout.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=D:\a\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': 'D:\\a\\ice\\ice\\java\\lib\\test.jar'})
2025-01-21T11:53:53.0268789Z (C:\hostedtoolcache\windows\Java_Oracle_jdk\17\x64\bin\java -ea -Dtest.class=test.Ice.idleTimeout.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=D:\a\ice\ice\certs --IceSSL.Keystore=client.jks env={'CLASSPATH': 'D:\\a\\ice\\ice\\java\\lib\\test.jar'})
2025-01-21T11:53:53.0287302Z testing that the idle check does not abort a back-pressured connection... com.zeroc.Ice.ConnectionAbortedException: Connection aborted by the idle check because it did not receive any bytes for 1s.
2025-01-21T11:53:53.0296561Z at com.zeroc.Ice.OutgoingAsync.waitForResponseOrUserEx(OutgoingAsync.java:102)
2025-01-21T11:53:53.0300414Z at com.zeroc.Ice.OutgoingAsync.waitForResponse(OutgoingAsync.java:89)
2025-01-21T11:53:53.0302204Z at test.Ice.idleTimeout.Test.TestIntfPrx.sleep(TestIntfPrx.java:24)
2025-01-21T11:53:53.0308592Z at test.Ice.idleTimeout.Test.TestIntfPrx.sleep(TestIntfPrx.java:19)
2025-01-21T11:53:53.0311048Z at test.Ice.idleTimeout.AllTests.testIdleCheckDoesNotAbortBackPressuredConnection(AllTests.java:55)
2025-01-21T11:53:53.0312297Z at test.Ice.idleTimeout.AllTests.allTests(AllTests.java:26)
2025-01-21T11:53:53.0313095Z at test.Ice.idleTimeout.Client.run(Client.java:13)
2025-01-21T11:53:53.0322813Z at test.TestDriver.main(TestDriver.java:26)
Cannot reproduce. Let's reopen if it fails again with the network tracing enabled
Failed again in https://github.com/zeroc-ice/ice/actions/runs/13133375931/job/36643248682
Server:
-- 2/4/25 11:26:24:307 Protocol: received request
message type = 0 (request)
compression status = 0 (not compressed; do not compress response, if any)
message size = 43
request id = 2
identity = test
facet =
operation = sleep
mode = 0 (normal)
context =
encoding = 1.1
transport = ssl
local address = 127.0.0.1:14000
remote address = 127.0.0.1:61982
-- 2/4/25 11:26:25:011 Protocol: sending validate connection
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:14000
remote address = 127.0.0.1:61982
-- 2/4/25 11:26:25:609 Protocol: sending validate connection
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:14000
remote address = 127.0.0.1:61982
-- 2/4/25 11:26:25:617 Network: closed ssl connection
local address = 127.0.0.1:14000
remote address = 127.0.0.1:61982
com.zeroc.Ice.ConnectionLostException
Client:
-- 2/4/25 11:26:24:307 Protocol: sending request
message type = 0 (request)
compression status = 0 (not compressed; do not compress response, if any)
message size = 43
request id = 2
identity = test
facet =
operation = sleep
mode = 0 (normal)
context =
encoding = 1.1
transport = ssl
local address = 127.0.0.1:61982
remote address = 127.0.0.1:14000
-- 2/4/25 11:26:25:427 Protocol: sending validate connection
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:61982
remote address = 127.0.0.1:14000
-- 2/4/25 11:26:25:439 Network: connection aborted by the idle check because it did not receive any bytes for 1s
local address = 127.0.0.1:61982
remote address = 127.0.0.1:14000
-- 2/4/25 11:26:25:441 Network: closed ssl connection
local address = 127.0.0.1:61982
remote address = 127.0.0.1:14000
From the logs in the last comment it shows the server send a "validate connection" at 11:26:25:011 and a second one at 11:26:25:609
The messages didn't show up in the client log. The client should be able to read them while waiting for sleep response.
And then idle check in the client closes the connection at 11:26:25:439
Similar failure for macOS https://github.com/zeroc-ice/ice/actions/runs/16813647292/job/47624942875
The last failure is similar to #4472 (but java vs csharp), i.e. it's the client-side idle check that aborts the connection while the server-side is flow-controled.
Back then, we didn't have Network=3 tracing so it's harder to see what's going on.
client log
-- 8/7/25 21:12:40:744 Protocol: sending request
message type = 0 (request)
compression status = 0 (not compressed; do not compress response, if any)
message size = 43
request id = 2
identity = test
facet =
operation = sleep
mode = 0 (normal)
context =
encoding = 1.1
transport = ssl
local address = 127.0.0.1:54430
remote address = 127.0.0.1:14100
-- 8/7/25 21:12:41:252 Protocol: sending validate connection
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:54430
remote address = 127.0.0.1:14100
-- 8/7/25 21:12:41:393 Protocol: received validate connection [1]
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:54430
remote address = 127.0.0.1:14100
-- 8/7/25 21:12:41:793 Protocol: sending validate connection
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:54430
remote address = 127.0.0.1:14100
-- 8/7/25 21:12:41:924 Protocol: received validate connection [2]
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:54430
remote address = 127.0.0.1:14100
-- 8/7/25 21:12:42:317 Protocol: sending validate connection
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:54430
remote address = 127.0.0.1:14100
<didn't receive [3] - why not?>
-- 8/7/25 21:12:42:920 Protocol: sending validate connection
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:54430
remote address = 127.0.0.1:14100
-- 8/7/25 21:12:42:963 Network: connection aborted by the idle check because it did not receive any bytes for 1s
local address = 127.0.0.1:54430
remote address = 127.0.0.1:14100
server log
-- 8/7/25 21:12:40:744 Protocol: received request
message type = 0 (request)
compression status = 0 (not compressed; do not compress response, if any)
message size = 43
request id = 2
identity = test
facet =
operation = sleep
mode = 0 (normal)
context =
encoding = 1.1
transport = ssl
local address = 127.0.0.1:14100
remote address = 127.0.0.1:54430
-- 8/7/25 21:12:41:390 Protocol: sending validate connection [1]
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:14100
remote address = 127.0.0.1:54430
-- 8/7/25 21:12:41:923 Protocol: sending validate connection [2]
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:14100
remote address = 127.0.0.1:54430
-- 8/7/25 21:12:42:489 Protocol: sending validate connection [3]
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:14100
remote address = 127.0.0.1:54430
-- 8/7/25 21:12:42:976 Protocol: sending reply
message type = 2 (reply)
compression status = 0 (not compressed; do not compress response, if any)
message size = 25
request id = 2
reply status = Ok
encoding = 1.1
transport = ssl
local address = 127.0.0.1:14100
remote address = 127.0.0.1:54430
-- 8/7/25 21:12:42:985 Protocol: received validate connection
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:14100
remote address = 127.0.0.1:54430
-- 8/7/25 21:12:42:985 Protocol: received validate connection
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:14100
remote address = 127.0.0.1:54430
-- 8/7/25 21:12:42:986 Protocol: received validate connection
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:14100
remote address = 127.0.0.1:54430
-- 8/7/25 21:12:42:988 Protocol: received validate connection
message type = 3 (validate connection)
compression status = 0 (not compressed; do not compress response, if any)
message size = 14
transport = ssl
local address = 127.0.0.1:14100
remote address = 127.0.0.1:54430
-- 8/7/25 21:12:43:020 Network: closed ssl connection
local address = 127.0.0.1:14100
remote address = 127.0.0.1:54430
com.zeroc.Ice.ConnectionLostException