Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

java/Ice/ami test failure (Windows, CI) #3049

Closed
bernardnormier opened this issue Nov 4, 2024 · 11 comments
Closed

java/Ice/ami test failure (Windows, CI) #3049

bernardnormier opened this issue Nov 4, 2024 · 11 comments
Assignees
@bernardnormier
Labels
bug java
Milestone
3.8.0

Comments

@bernardnormier
Copy link
Member

From https://github.com/zeroc-ice/ice/actions/runs/11667259880/job/32484152445:

[ running client/server test - 11/04/24 16:21:48 ]
- Config: wss,x64
(C:\hostedtoolcache\windows\Java_Oracle_jdk\17\x64\bin\java -ea -Dtest.class=test.Ice.ami.Server test.TestDriver --Ice.Default.Host=127.0.0.1 --Test.BasePort=14200 --Ice.Warn.Connections=1 --Ice.Default.Protocol=wss --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 --Ice.Trace.Network=2 --Ice.Trace.Retry=1 --Ice.Trace.Protocol=1 --Ice.LogFile=D:\a\ice\ice\java\test\src\main\java\test\Ice\ami\server-110424-1621.log 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.ami.Client test.TestDriver --Ice.Default.Host=127.0.0.1 --Test.BasePort=14200 --Ice.Warn.Connections=1 --Ice.Default.Protocol=wss --Ice.IPv6=0 --IceSSL.*** --IceSSL.DefaultDir=D:\a\ice\ice\certs --IceSSL.Keystore=client.jks --Ice.Trace.Network=2 --Ice.Trace.Retry=1 --Ice.Trace.Protocol=1 --Ice.LogFile=D:\a\ice\ice\java\test\src\main\java\test\Ice\ami\client-110424-1621.log env={'CLASSPATH': 'D:\\a\\ice\\ice\\java\\lib\\test.jar'})
testing begin/end invocation... ok
testing local exceptions... ok
testing sent callback... ok
testing sent async callback... ok
testing unexpected exceptions... ok
testing batch requests with proxy... ok
testing batch requests with connection... ok
testing batch requests with communicator... ok
testing future operations... ok
testing connection close... java.util.concurrent.CompletionException: com.zeroc.Ice.CloseTimeoutException: Close timed out.
	at java.base/java.util.concurrent.CompletableFuture.reportJoin(CompletableFuture.java:413)
	at java.base/java.util.concurrent.CompletableFuture.join(CompletableFuture.java:2118)
	at test.Ice.ami.AllTests.allTests(AllTests.java:969)
	at test.Ice.ami.Client.run(Client.java:20)
	at test.TestDriver.main(TestDriver.java:26)
Caused by: com.zeroc.Ice.CloseTimeoutException: Close timed out.
	at com.zeroc.Ice.ConnectionI.closeTimedOut(ConnectionI.java:2498)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)
saved D:\a\ice\ice\java\test\src\main\java\test\Ice\ami\client-110424-1621.log
saved D:\a\ice\ice\java\test\src\main\java\test\Ice\ami\server-110424-1621.log
@bernardnormier bernardnormier added this to the 3.8.0 milestone Nov 4, 2024
@InsertCreativityHere
Copy link
Member

Possibly related to: #3044

@bernardnormier
Copy link
Member Author

Looking the logs:

client

-- 11/4/24 16:21:53:477 Protocol: sending request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 49
   request id = 38
   identity = test
   facet = 
   operation = closeConnection
   mode = 0 (normal)
   context = 
   encoding = 1.1
...
-- 11/4/24 16:21:53:556 Network: received wss data frame with payload length of 14 bytes
   local address = 127.0.0.1:65089
   remote address = 127.0.0.1:14200
-- 11/4/24 16:21:53:556 Protocol: received close connection 
   message type = 4 (close connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 11/4/24 16:21:53:556 Network: gracefully closing wss connection
   local address = 127.0.0.1:65089
   remote address = 127.0.0.1:14200
-- 11/4/24 16:21:53:563 Network: sent wss connection close frame
   local address = 127.0.0.1:65089
   remote address = 127.0.0.1:14200
-- 11/4/24 16:22:03:601 Network: closed wss connection
   local address = 127.0.0.1:65089
   remote address = 127.0.0.1:14200
   com.zeroc.Ice.CloseTimeoutException: Close timed out.
-- 11/4/24 16:22:03:602 Retry: retrying operation call because of exception
   com.zeroc.Ice.CloseTimeoutException: Close timed out.
-- 11/4/24 16:22:03:603 Retry: retrying operation call because of exception
   com.zeroc.Ice.CloseTimeoutException: Close timed out.
-- 11/4/24 16:22:03:603 Retry: retrying operation call because of exception

server

- 11/4/24 16:21:53:478 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 49
   request id = 38
   identity = test
   facet = 
   operation = closeConnection
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:478 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 38
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:478 Network: received wss data frame with payload length of 42 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:478 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 42
   request id = 39
   identity = test
   facet = 
   operation = ice_ping
   mode = 2 (idempotent)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:478 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 39
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:480 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:480 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 40
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:480 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 40
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:483 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:483 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 41
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:483 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 41
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:484 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:484 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 42
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:484 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 42
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:490 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:490 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 43
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:490 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 43
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:493 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:493 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 44
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:493 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 44
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:497 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:497 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 45
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:497 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 45
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:498 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:498 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 46
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:498 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 46
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:499 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:499 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 47
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:499 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 47
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:501 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:501 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 48
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:501 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 48
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:502 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:502 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 49
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:503 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 49
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:503 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:504 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 50
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:504 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 50
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:505 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:505 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 51
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:505 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 51
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:508 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:508 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 52
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:508 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 52
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:509 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:509 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 53
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:509 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 53
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:511 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:511 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 54
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:511 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 54
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:512 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:512 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 55
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:512 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 55
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:514 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:515 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 56
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:515 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 56
   reply status = 0 (ok)
   encoding = 1.1
-- 11/4/24 16:21:53:556 Protocol: sending close connection 
   message type = 4 (close connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 11/4/24 16:21:53:562 Network: gracefully closing wss connection
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:564 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:564 Protocol: received request during closing
   (ignored by server, client will retry)
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 57
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:565 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:568 Protocol: received request during closing
   (ignored by server, client will retry)
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 58
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:568 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:568 Protocol: received request during closing
   (ignored by server, client will retry)
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 59
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:568 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:572 Protocol: received request during closing
   (ignored by server, client will retry)
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 60
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:572 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:572 Protocol: received request during closing
   (ignored by server, client will retry)
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 61
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:21:53:572 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:21:53:573 Protocol: received request during closing
   (ignored by server, client will retry)
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 62
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 11/4/24 16:22:03:603 Network: closed wss connection
   local address = 127.0.0.1:14200
   remote address = 127.0.0.1:65089
-- 11/4/24 16:22:03:605 Network: received wss data frame with payload length of 14 bytes
   local address = 127.0.0.1:14201
   remote address = 127.0.0.1:65086
-- 11/4/24 16:22:03:605 Protocol: received close connection 
   message type = 4 (close connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14

@bernardnormier bernardnormier mentioned this issue Nov 4, 2024
Closed
@pepone
Copy link
Member

pepone commented Nov 12, 2024

Failed again in https://github.com/zeroc-ice/ice/actions/runs/11794851864/job/32853329283

2024-11-12T10:53:56.2038521Z testing batch requests with communicator... ok
2024-11-12T10:53:56.2044098Z testing future operations... ok
2024-11-12T10:53:56.2045650Z testing connection close... java.util.concurrent.CompletionException: com.zeroc.Ice.CloseTimeoutException: Close timed out.
2024-11-12T10:53:56.2048120Z 	at java.base/java.util.concurrent.CompletableFuture.reportJoin(CompletableFuture.java:413)
2024-11-12T10:53:56.2049607Z 	at java.base/java.util.concurrent.CompletableFuture.join(CompletableFuture.java:2118)
2024-11-12T10:53:56.2050734Z 	at test.Ice.ami.AllTests.allTests(AllTests.java:970)
2024-11-12T10:53:56.2051471Z 	at test.Ice.ami.Client.run(Client.java:20)
2024-11-12T10:53:56.2053334Z 	at test.TestDriver.main(TestDriver.java:26)
2024-11-12T10:53:56.2054410Z Caused by: com.zeroc.Ice.CloseTimeoutException: Close timed out.
2024-11-12T10:53:56.2055531Z 	at com.zeroc.Ice.ConnectionI.closeTimedOut(ConnectionI.java:2509)
2024-11-12T10:53:56.2056803Z 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
2024-11-12T10:53:56.2058070Z 	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2024-11-12T10:53:56.2059803Z 	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
2024-11-12T10:53:56.2062239Z 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2024-11-12T10:53:56.2063853Z 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2024-11-12T10:53:56.2065018Z 	at java.base/java.lang.Thread.run(Thread.java:833)
2024-11-12T10:53:56.2066356Z saved D:\a\ice\ice\java\test\src\main\java\test\Ice\ami\client-111224-1053.log
2024-11-12T10:53:56.2067834Z saved D:\a\ice\ice\java\test\src\main\java\test\Ice\ami\server-111224-1053.log

@bernardnormier bernardnormier self-assigned this Nov 12, 2024
@bernardnormier
Copy link
Member Author

The odd part of the latest logs:

client

-- 11/12/24 10:53:45:277 Network: received wss data frame with payload length of 14 bytes
   local address = 127.0.0.1:64115
   remote address = 127.0.0.1:14000
-- 11/12/24 10:53:45:277 Protocol: received close connection  <== graceful closure initiated by server
   message type = 4 (close connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
   transport = wss
   local address = 127.0.0.1:64115
   remote address = 127.0.0.1:14000
-- 11/12/24 10:53:45:277 Network: gracefully closing wss connection 
   local address = 127.0.0.1:64115
   remote address = 127.0.0.1:14000
-- 11/12/24 10:53:45:279 Network: sent wss connection close frame
   local address = 127.0.0.1:64115
   remote address = 127.0.0.1:14000

== 10 seconds ==

-- 11/12/24 10:53:55:282 Network: closed wss connection
   local address = 127.0.0.1:64115
   remote address = 127.0.0.1:14000
   com.zeroc.Ice.CloseTimeoutException: Close timed out.
-- 11/12/24 10:53:55:283 Retry: retrying operation call because of exception

server

-- 11/12/24 10:53:45:278 Network: gracefully closing wss connection
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115
-- 11/12/24 10:53:45:279 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115
-- 11/12/24 10:53:45:279 Protocol: received request during closing
   (ignored by server, client will retry)
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 24
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
   transport = wss
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115
-- 11/12/24 10:53:45:279 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115
-- 11/12/24 10:53:45:279 Protocol: received request during closing
   (ignored by server, client will retry)
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 25
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
   transport = wss
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115
-- 11/12/24 10:53:45:279 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115
-- 11/12/24 10:53:45:279 Protocol: received request during closing
   (ignored by server, client will retry)
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 26
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
   transport = wss
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115
-- 11/12/24 10:53:45:279 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115
-- 11/12/24 10:53:45:279 Protocol: received request during closing
   (ignored by server, client will retry)
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 27
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
   transport = wss
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115
-- 11/12/24 10:53:45:279 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115
-- 11/12/24 10:53:45:279 Protocol: received request during closing
   (ignored by server, client will retry)
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 28
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
   transport = wss
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115
-- 11/12/24 10:53:45:279 Network: received wss data frame with payload length of 10292 bytes
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115
-- 11/12/24 10:53:45:279 Protocol: received request during closing
   (ignored by server, client will retry)
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 29
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
   transport = wss
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115

== 10 seconds delay ==

-- 11/12/24 10:53:55:283 Network: closed wss connection
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115
-- 11/12/24 10:53:55:285 Network: received wss data frame with payload length of 14 bytes
   local address = 127.0.0.1:14001
   remote address = 127.0.0.1:64111

There is no "Network: received wss connection close frame" in the server log.

@pepone
Copy link
Member

pepone commented Nov 12, 2024 

-- 11/12/24 10:53:45:279 Protocol: received request during closing
   (ignored by server, client will retry)
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 10292
   request id = 29
   identity = test
   facet = 
   operation = opWithPayload
   mode = 0 (normal)
   context = 
   encoding = 1.1
   transport = wss
   local address = 127.0.0.1:14000
   remote address = 127.0.0.1:64115

Is this "received request during closing" expected with the test? One issue with this test is that it doesn't wait for the completion of previous async opWithPayload operations like in:

ice/java/test/src/main/java/test/Ice/ami/AllTests.java

Line 775 in 1720369

test(r2.getOperation().equals("opWithPayload"));

I was working on cleaning this up

This was referenced Nov 12, 2024
Merged
Closed
@pepone
Copy link
Member

pepone commented Nov 13, 2024

ice/java/test/src/main/java/test/Ice/ami/AllTests.java

Line 974 in 53f04f9

p.ice_getCachedConnection().close();

This should be inside while loop, otherwise when we retry the close might be already in progress.

@pepone
Copy link
Member

pepone commented Nov 13, 2024

I also got

testing connection close... java.lang.NullPointerException: Cannot invoke "com.zeroc.Ice.Connection.close()" because the return value of "test.Ice.ami.Test.TestIntfPrx.ice_getCachedConnection()" is null
        at test.Ice.ami.AllTests.allTests(AllTests.java:976)
        at test.Ice.ami.Client.run(Client.java:20)
        at test.TestDriver.main(TestDriver.java:26)

@bernardnormier
Copy link
Member Author

Is this "received request during closing" expected with the test?

Yes, that's a core part of the test. Verify that the client actually retries with a new connection.

@bernardnormier
Copy link
Member Author

I was able to reproduce this failure in a VM with wss by:

  • reducing the test to just this remote close test
  • running it in a loop

Failed after ~40 iterations. And later on after 210 iterations. Could not reproduce it with ws with over 18K iterations.

@bernardnormier
Copy link
Member Author

bernardnormier commented Nov 13, 2024 •
edited
Loading

This should be inside while loop, otherwise when we retry the close might be already in progress.

Why would this be a concern? If the close is already in the progress:

  • if the client already received the CloseConnection message from the server, it sends the request on a new connection
  • if the client has not received the CloseConnection message from the server yet, it sends the request on the "old" connection, and never gets a reply, but retries because it gets a CloseConnection message on that connection.

@pepone
Copy link
Member

pepone commented Nov 13, 2024

Fixed by #3142

@pepone pepone closed this as completed Nov 13, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@bernardnormier bernardnormier

Labels
bug java
Projects
None yet
Milestone
3.8.0
Development

No branches or pull requests
3 participants
@pepone @bernardnormier @InsertCreativityHere