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.

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

Slic idle timeout test failures on Windows #4097

Closed
pepone opened this issue Nov 14, 2024 · 2 comments · Fixed by #4105
Closed

Slic idle timeout test failures on Windows #4097

pepone opened this issue Nov 14, 2024 · 2 comments · Fixed by #4105
Labels
bug Something isn't working
Milestone

Comments

@pepone
Copy link
Member

pepone commented Nov 14, 2024

https://github.com/icerpc/icerpc-csharp/actions/runs/11834164792/job/32974300856?pr=4096

Failed IceRpc:Tests:Transports:Slic:SlicTransportTests:Connection_with_idle_timeout_and_slow_write_is_not_aborted(False) [2 s]
2024-11-14T09:22:27.4319617Z   Error Message:
2024-11-14T09:22:27.4325179Z    IceRpc.IceRpcException : The connection was lost.
2024-11-14T09:22:27.4328508Z   Stack Trace:
2024-11-14T09:22:27.4340793Z      at IceRpc.Transports.Slic.Internal.SlicConnection.ThrowIfClosed() in /_/src/IceRpc/Transports/Slic/Internal/SlicConnection.cs:line 661
2024-11-14T09:22:27.4386659Z    at IceRpc.Transports.Slic.Internal.SlicStream.ThrowIfConnectionClosed() in /_/src/IceRpc/Transports/Slic/Internal/SlicStream.cs:line 401
2024-11-14T09:22:27.4410589Z    at IceRpc.Transports.Slic.Internal.SlicPipeWriter.WriteAsync(ReadOnlySequence`1 source, Boolean endStream, CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Slic/Internal/SlicPipeWriter.cs:line 101
2024-11-14T09:22:27.4422915Z    at IceRpc.Tests.Transports.Slic.SlicTransportTests.Connection_with_idle_timeout_and_slow_write_is_not_aborted(Boolean serverIdleTimeout) in D:\a\icerpc-csharp\icerpc-csharp\tests\IceRpc.Tests\Transports\Slic\SlicTransportTests.cs:line 618
2024-11-14T09:22:27.4440060Z    at IceRpc.Tests.Transports.Slic.SlicTransportTests.Connection_with_idle_timeout_and_slow_write_is_not_aborted(Boolean serverIdleTimeout) in D:\a\icerpc-csharp\icerpc-csharp\tests\IceRpc.Tests\Transports\Slic\SlicTransportTests.cs:line 628
2024-11-14T09:22:27.4449581Z    at NUnit.Framework.Internal.TaskAwaitAdapter.GenericAdapter`1.BlockUntilCompleted()
2024-11-14T09:22:27.4461066Z    at NUnit.Framework.Internal.MessagePumpStrategy.NoMessagePumpStrategy.WaitForCompletion(AwaitAdapter awaiter)
2024-11-14T09:22:27.4497061Z    at NUnit.Framework.Internal.AsyncToSyncAdapter.Await[TResult](Func`1 invoke)
2024-11-14T09:22:27.4511048Z    at NUnit.Framework.Internal.AsyncToSyncAdapter.Await(Func`1 invoke)
2024-11-14T09:22:27.4515455Z    at NUnit.Framework.Internal.Commands.TestMethodCommand.RunTestMethod(TestExecutionContext context)
2024-11-14T09:22:27.4524989Z    at NUnit.Framework.Internal.Commands.TestMethodCommand.Execute(TestExecutionContext context)
2024-11-14T09:22:27.4546901Z    at NUnit.Framework.Internal.Execution.SimpleWorkItem.<>c__DisplayClass3_0.<PerformWork>b__0()
2024-11-14T09:22:27.4555409Z    at NUnit.Framework.Internal.ContextUtils.<>c__DisplayClass1_0`1.<DoIsolated>b__0(Object _)
2024-11-14T09:22:27.4704559Z    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
2024-11-14T09:22:27.4706773Z --- End of stack trace from previous location ---
2024-11-14T09:22:27.4708558Z    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
2024-11-14T09:22:27.4710775Z    at NUnit.Framework.Internal.ContextUtils.DoIsolated(ContextCallback callback, Object state)
2024-11-14T09:22:27.4712528Z    at NUnit.Framework.Internal.ContextUtils.DoIsolated[T](Func`1 func)
2024-11-14T09:22:27.4714149Z    at NUnit.Framework.Internal.Execution.SimpleWorkItem.PerformWork()
2024-11-14T09:22:27.4715198Z 
2024-11-14T09:22:27.4716359Z   Failed IceRpc:Tests:Transports:Slic:SlicTransportTests:Connection_with_idle_timeout_and_slow_write_is_not_aborted(True) [2 s]
2024-11-14T09:22:27.4717953Z   Error Message:
2024-11-14T09:22:27.4718793Z    IceRpc.IceRpcException : The connection was lost.
2024-11-14T09:22:27.4719734Z   Stack Trace:
2024-11-14T09:22:27.4721383Z      at IceRpc.Transports.Slic.Internal.SlicConnection.ThrowIfClosed() in /_/src/IceRpc/Transports/Slic/Internal/SlicConnection.cs:line 661
2024-11-14T09:22:27.4724329Z    at IceRpc.Transports.Slic.Internal.SlicStream.ThrowIfConnectionClosed() in /_/src/IceRpc/Transports/Slic/Internal/SlicStream.cs:line 401
2024-11-14T09:22:27.4728005Z    at IceRpc.Transports.Slic.Internal.SlicPipeWriter.WriteAsync(ReadOnlySequence`1 source, Boolean endStream, CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Slic/Internal/SlicPipeWriter.cs:line 101
2024-11-14T09:22:27.4732851Z    at IceRpc.Tests.Transports.Slic.SlicTransportTests.Connection_with_idle_timeout_and_slow_write_is_not_aborted(Boolean serverIdleTimeout) in D:\a\icerpc-csharp\icerpc-csharp\tests\IceRpc.Tests\Transports\Slic\SlicTransportTests.cs:line 618
2024-11-14T09:22:27.4737838Z    at IceRpc.Tests.Transports.Slic.SlicTransportTests.Connection_with_idle_timeout_and_slow_write_is_not_aborted(Boolean serverIdleTimeout) in D:\a\icerpc-csharp\icerpc-csharp\tests\IceRpc.Tests\Transports\Slic\SlicTransportTests.cs:line 628
2024-11-14T09:22:27.4741395Z    at NUnit.Framework.Internal.TaskAwaitAdapter.GenericAdapter`1.BlockUntilCompleted()
2024-11-14T09:22:27.4743652Z    at NUnit.Framework.Internal.MessagePumpStrategy.NoMessagePumpStrategy.WaitForCompletion(AwaitAdapter awaiter)
2024-11-14T09:22:27.4745758Z    at NUnit.Framework.Internal.AsyncToSyncAdapter.Await[TResult](Func`1 invoke)
2024-11-14T09:22:27.4747350Z    at NUnit.Framework.Internal.AsyncToSyncAdapter.Await(Func`1 invoke)
2024-11-14T09:22:27.4749137Z    at NUnit.Framework.Internal.Commands.TestMethodCommand.RunTestMethod(TestExecutionContext context)
2024-11-14T09:22:27.4751706Z    at NUnit.Framework.Internal.Commands.TestMethodCommand.Execute(TestExecutionContext context)
2024-11-14T09:22:27.4753627Z    at NUnit.Framework.Internal.Execution.SimpleWorkItem.<>c__DisplayClass3_0.<PerformWork>b__0()
2024-11-14T09:22:27.4755523Z    at NUnit.Framework.Internal.ContextUtils.<>c__DisplayClass1_0`1.<DoIsolated>b__0(Object _)
2024-11-14T09:22:27.4757666Z    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
2024-11-14T09:22:27.4760617Z --- End of stack trace from previous location ---
2024-11-14T09:22:27.4781959Z    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
2024-11-14T09:22:27.4784934Z    at NUnit.Framework.Internal.ContextUtils.DoIsolated(ContextCallback callback, Object state)
2024-11-14T09:22:27.4786431Z    at NUnit.Framework.Internal.ContextUtils.DoIsolated[T](Func`1 func)
2024-11-14T09:22:27.4787693Z    at NUnit.Framework.Internal.Execution.SimpleWorkItem.PerformWork()
@pepone pepone added this to the 0.4.1 milestone Nov 14, 2024
@pepone
Copy link
Member Author

pepone commented Nov 14, 2024

2024-11-14T09:22:27.4410589Z    at IceRpc.Transports.Slic.Internal.SlicPipeWriter.WriteAsync(ReadOnlySequence`1 source, Boolean endStream, CancellationToken cancellationToken) in /_/src/IceRpc/Transports/Slic/Internal/SlicPipeWriter.cs:line 101
2024-11-14T09:22:27.4422915Z    at IceRpc.Tests.Transports.Slic.SlicTransportTests.Connection_with_idle_timeout_and_slow_write_is_not_aborted(Boolean serverIdleTimeout) in D:\a\icerpc-csharp\icerpc-csharp\tests\IceRpc.Tests\Transports\Slic\SlicTransportTests.cs:line 618
2024-11-14T09:22:27.4440060Z    at IceRpc.Tests.Transports.Slic.SlicTransportTests.Connection_with_idle_timeout_and_slow_write_is_not_aborted(Boolean serverIdleTimeout) in D:\a\icerpc-csharp\icerpc-csharp\tests\IceRpc.Tests\Transports\Slic\SlicTransportTests.cs:line 628

for (int i = 0; i < 4; ++i)
{
// Slow writes to the server (the server doesn't even read them).
_ = await stream.Output.WriteAsync(new byte[1], default);
await Task.Delay(TimeSpan.FromMilliseconds(500));
}
stream.Output.Complete();
ValueTask<IMultiplexedStream> nextAcceptStreamTask = sut.Server.AcceptStreamAsync(default);
// Assert
Assert.That(acceptStreamTask.IsCompleted, Is.True);
Assert.That(nextAcceptStreamTask.IsCompleted, Is.False);
await sut.Client.CloseAsync(MultiplexedConnectionCloseError.NoError, default);
Assert.That(async () => await nextAcceptStreamTask, Throws.InstanceOf<IceRpcException>());

The stack is a bit confusing, writing on line 618 stream.Output.WriteAsync fails, why does lines 628 appears in the stack at all? Seems like NUnit does this.

The test took 2s but it was still writing, when it fails, most likely the machine was running slow. I think we should either not run this in parallel or decrease the Delay between writes to 250ms

@pepone pepone added the bug Something isn't working label Nov 14, 2024
@pepone
Copy link
Member Author

pepone commented Nov 14, 2024

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant