ice csharp/Ice/retry failure (ubuntu)

from https://github.com/zeroc-ice/ice/actions/runs/10709606416/job/29694630089?pr=2720

*** [51/308] Running csharp/Ice/retry tests ***
[ running client/server test - 09/04/24 21:38:15 ]
- Config: ssl
(dotnet /home/runner/work/ice/ice/csharp/test/Ice/retry/msbuild/server/net8.0/server.dll --Ice.Default.Host=127.0.0.1 --Test.BasePort=14000 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ssl --Ice.IPv6=0 --IceSSL.*** --IceSSL.DefaultDir=/home/runner/work/ice/ice/certs --IceSSL.CAs=cacert.pem --IceSSL.VerifyPeer=2 --IceSSL.CertFile=server.p12 --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=/home/runner/work/ice/ice/csharp/test/Ice/retry/server-090424-2138.log)
(dotnet /home/runner/work/ice/ice/csharp/test/Ice/retry/msbuild/client/net8.0/client.dll --Ice.Default.Host=127.0.0.1 --Test.BasePort=14000 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ssl --Ice.IPv6=0 --IceSSL.*** --IceSSL.DefaultDir=/home/runner/work/ice/ice/certs --IceSSL.CAs=cacert.pem --IceSSL.VerifyPeer=2 --IceSSL.CertFile=client.p12 --Ice.Trace.Network=2 --Ice.Trace.Retry=1 --Ice.Trace.Protocol=1 --Ice.LogFile=/home/runner/work/ice/ice/csharp/test/Ice/retry/client-090424-2138.log)
testing stringToProxy... ok
testing checked cast... ok
calling regular operation with first proxy... ok
calling operation to kill connection with second proxy... ok
calling regular operation with first proxy again... ok
calling regular AMI operation with first proxy... ok
calling AMI operation to kill connection with second proxy... value = 1, expected = 0
failed:
   at Test.TestHelper.fail(String message, String detailMessage) in /home/runner/work/ice/ice/csharp/test/TestCommon/TestHelper.cs:line 183
   at Test.TestHelper.TestTraceListener.Fail(String message, String detailMessage) in /home/runner/work/ice/ice/csharp/test/TestCommon/TestHelper.cs:line 35
   at System.Diagnostics.TraceInternal.Fail(String message, String detailMessage)
   at System.Diagnostics.Debug.Fail(String message, String detailMessage)
   at Ice.retry.Instrumentation.testEqual(Int32& value, Int32 expected) in /home/runner/work/ice/ice/csharp/test/Ice/retry/Instrumentation.cs:line 147
   at Ice.retry.Instrumentation.testRetryCount(Int32 expected) in /home/runner/work/ice/ice/csharp/test/Ice/retry/Instrumentation.cs:line 156
   at Ice.retry.AllTests.allTests(TestHelper helper, Communicator communicator, Communicator communicator2, String rf) in /home/runner/work/ice/ice/csharp/test/Ice/retry/AllTests.cs:line 91
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
saved /home/runner/work/ice/ice/csharp/test/Ice/retry/client-090424-2138.log
saved /home/runner/work/ice/ice/csharp/test/Ice/retry/server-090424-2138.log

Sep 04 '24 23:09 bernardnormier

Note that this is a duplicate of #2583, except that this one is for Windows instead of Ubuntu. Which just shows that this bug isn't platform specific.

Sep 05 '24 02:09 InsertCreativityHere

The failure indicates there was an unexpected retry, here we abort the connection so a retry is unexpected. In both cases happen when using SSL, it would be interesting to see the log files to understand where the retry comes from.

I opened #2723 to upload logs after test failures, and hopefully would bring some light into this.

I wasn't able to reproduce this locally with Ubuntu or Windows.

Sep 05 '24 10:09 pepone

It turns out we already upload test logs:

-- 09/04/2024 21:38:16:163 client: Protocol: sending request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 38
   request id = 3
   identity = retry
   facet = 
   operation = op
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 09/04/2024 21:38:16:166 client: Network: closed ssl connection
   local address = 127.0.0.1:46144
   remote address = 127.0.0.1:14000
   Ice.ConnectionLostException: Exception of type 'Ice.ConnectionLostException' was thrown.
      at Ice.SSL.TransceiverI.finishRead(Buffer buf) in /home/runner/work/ice/ice/csharp/src/Ice/SSL/TransceiverI.cs:line 176
      at Ice.Internal.IdleTimeoutTransceiverDecorator.finishRead(Buffer buf) in /home/runner/work/ice/ice/csharp/src/Ice/Internal/IdleTimeoutTransceiverDecorator.cs:line 56
      at Ice.ConnectionI.finishAsync(Int32 operation) in /home/runner/work/ice/ice/csharp/src/Ice/ConnectionI.cs:line 706
-- 09/04/2024 21:38:16:167 client: Retry: retrying operation call because of exception
   Ice.ConnectionLostException: Exception of type 'Ice.ConnectionLostException' was thrown.
      at Ice.SSL.TransceiverI.finishRead(Buffer buf) in /home/runner/work/ice/ice/csharp/src/Ice/SSL/TransceiverI.cs:line 176
      at Ice.Internal.IdleTimeoutTransceiverDecorator.finishRead(Buffer buf) in /home/runner/work/ice/ice/csharp/src/Ice/Internal/IdleTimeoutTransceiverDecorator.cs:line 56
      at Ice.ConnectionI.finishAsync(Int32 operation) in /home/runner/work/ice/ice/csharp/src/Ice/ConnectionI.cs:line 706

Seems the retry is due an unexpected connection lost with SSL

Sep 05 '24 11:09 pepone

Note that this is a duplicate of https://github.com/zeroc-ice/ice/issues/2583, except that this one is for Windows instead of Ubuntu.

The title says "windows/debug", but looking at the logs seems it is Ubuntu too.

Sep 05 '24 11:09 pepone

This test keeps failing. Latest failure: https://github.com/zeroc-ice/ice/actions/runs/11351844341/job/31573331040?pr=2900

Oct 15 '24 19:10 bernardnormier

I cannot reproduce with a local Ubuntu 24.04 machine.

The test was expecting 0 retries, but there is a retry here:

-- 10/15/2024 18:49:21:355 client: Protocol: sending request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 38
   request id = 3
   identity = retry
   facet = 
   operation = op
   mode = 0 (normal)
   context = 
   encoding = 1.1
-- 10/15/2024 18:49:21:358 client: Network: closed ssl connection
   local address = 127.0.0.1:50764
   remote address = 127.0.0.1:14200
   Ice.ConnectionLostException: Exception of type 'Ice.ConnectionLostException' was thrown.
      at Ice.SSL.TransceiverI.finishRead(Buffer buf) in /home/runner/work/ice/ice/csharp/src/Ice/SSL/TransceiverI.cs:line 176
      at Ice.Internal.IdleTimeoutTransceiverDecorator.finishRead(Buffer buf) in /home/runner/work/ice/ice/csharp/src/Ice/Internal/IdleTimeoutTransceiverDecorator.cs:line 56
      at Ice.ConnectionI.finishAsync(Int32 operation) in /home/runner/work/ice/ice/csharp/src/Ice/ConnectionI.cs:line 688
-- 10/15/2024 18:49:21:358 client: Retry: retrying operation call because of exception
   Ice.ConnectionLostException: Exception of type 'Ice.ConnectionLostException' was thrown.
      at Ice.SSL.TransceiverI.finishRead(Buffer buf) in /home/runner/work/ice/ice/csharp/src/Ice/SSL/TransceiverI.cs:line 176
      at Ice.Internal.IdleTimeoutTransceiverDecorator.finishRead(Buffer buf) in /home/runner/work/ice/ice/csharp/src/Ice/Internal/IdleTimeoutTransceiverDecorator.cs:line 56
      at Ice.ConnectionI.finishAsync(Int32 operation) in /home/runner/work/ice/ice/csharp/src/Ice/ConnectionI.cs:line 688
-- 10/15/2024 18:49:21:365 client: Network: trying to establish ssl connection to 127.0.0.1:14200
-- 10/15/2024 18:49:21:380 client: Protocol: received validate connection 
   message type = 3 (validate connection)

Not clear what is happening, ConnectionLostException should only be retried if the request was not set.

Nov 05 '24 15:11 pepone

Failed again https://github.com/zeroc-ice/ice/actions/runs/11689188393/job/32551403603 :

*** [299/312] Running csharp/Ice/retry tests ***
[ running client/server test - 11/05/24 18:07:38 ]
- Config: ssl
(dotnet /home/runner/work/ice/ice/csharp/test/Ice/retry/msbuild/server/net8.0/server.dll --Ice.Default.Host=127.0.0.1 --Test.BasePort=14100 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ssl --Ice.IPv6=0 --IceSSL.*** --IceSSL.DefaultDir=/home/runner/work/ice/ice/certs --IceSSL.CAs=cacert.pem --IceSSL.VerifyPeer=2 --IceSSL.CertFile=server.p12 --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=/home/runner/work/ice/ice/csharp/test/Ice/retry/server-110524-1807.log)
(dotnet /home/runner/work/ice/ice/csharp/test/Ice/retry/msbuild/client/net8.0/client.dll --Ice.Default.Host=127.0.0.1 --Test.BasePort=14100 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ssl --Ice.IPv6=0 --IceSSL.*** --IceSSL.DefaultDir=/home/runner/work/ice/ice/certs --IceSSL.CAs=cacert.pem --IceSSL.VerifyPeer=2 --IceSSL.CertFile=client.p12 --Ice.Trace.Network=2 --Ice.Trace.Retry=1 --Ice.Trace.Protocol=1 --Ice.LogFile=/home/runner/work/ice/ice/csharp/test/Ice/retry/client-110524-1807.log)
testing stringToProxy... ok
testing checked cast... ok
calling regular operation with first proxy... ok
calling operation to kill connection with second proxy... ok
calling regular operation with first proxy again... ok
calling regular AMI operation with first proxy... ok
calling AMI operation to kill connection with second proxy... value = 1, expected = 0
System.Exception: Exception of type 'System.Exception' was thrown.
   at Ice.retry.Instrumentation.testEqual(Int32& value, Int32 expected) in /home/runner/work/ice/ice/csharp/test/Ice/retry/Instrumentation.cs:line 148
   at Ice.retry.Instrumentation.testRetryCount(Int32 expected) in /home/runner/work/ice/ice/csharp/test/Ice/retry/Instrumentation.cs:line 156
   at Ice.retry.AllTests.allTests(TestHelper helper, Communicator communicator, Communicator communicator2, String rf) in /home/runner/work/ice/ice/csharp/test/Ice/retry/AllTests.cs:line 91
   at Ice.retry.Client.runAsync(String[] args) in /home/runner/work/ice/ice/csharp/test/Ice/retry/Client.cs:line 34
   at Test.TestDriver.runTestAsync[T](String[] args) in /home/runner/work/ice/ice/csharp/test/TestCommon/TestHelper.cs:line 232
saved /home/runner/work/ice/ice/csharp/test/Ice/retry/client-110524-1807.log
saved /home/runner/work/ice/ice/csharp/test/Ice/retry/server-110524-1807.log

Nov 05 '24 19:11 bernardnormier