diff --git a/src/UiPath.CoreIpc.Tests/RequestTimeoutTests.cs b/src/UiPath.CoreIpc.Tests/RequestTimeoutTests.cs new file mode 100644 index 00000000..aade8a4f --- /dev/null +++ b/src/UiPath.CoreIpc.Tests/RequestTimeoutTests.cs @@ -0,0 +1,100 @@ +using Xunit.Abstractions; + +namespace UiPath.Ipc.Tests; + +/// +/// A handler that outlives the server's request timeout still runs to completion, but +/// Server.OnRequestReceived then sends its response on the very token the timeout just canceled. +/// The send throws, the when (response is null) filter does not match because the handler +/// succeeded, and the request is consumed without ever being answered - on a connection that stays +/// perfectly healthy. +/// +public abstract class RequestTimeoutTests : TestBase +{ + #region " Setup " + private static readonly TimeSpan ServerTimeout = TimeSpan.FromSeconds(1); + private static readonly TimeSpan HandlerWork = TimeSpan.FromSeconds(3); + private static readonly TimeSpan Lease = TimeSpan.FromSeconds(10); + + private readonly Lazy _proxy; + + protected ISlowService Proxy => _proxy.Value!; + + protected sealed override IpcProxy IpcProxy => Proxy as IpcProxy ?? throw new InvalidOperationException($"Proxy was expected to be a {nameof(IpcProxy)} but was not."); + protected sealed override Type ContractType => typeof(ISlowService); + + protected RequestTimeoutTests(ITestOutputHelper outputHelper) : base(outputHelper) + { + CreateLazyProxy(out _proxy); + } + + protected override void ConfigureSpecificServices(IServiceCollection services) + => services + .AddSingleton() + .AddSingletonAlias(); + + /// Deliberately far shorter than . + protected override TimeSpan ServerRequestTimeout => ServerTimeout; + + protected override void ConfigureClient(IpcClient ipcClient) + { + base.ConfigureClient(ipcClient); + + // The client must send NO timeout. Request.GetTimeout makes a client supplied timeout win over + // the server's, so any value here would silently replace the ServerRequestTimeout under test and + // the bug would not reproduce. The lease below is what stops the test hanging forever instead. + ipcClient.RequestTimeout = null; + } + #endregion + + [Fact] + public async Task CompletedHandler_OutlivingTheRequestTimeout_StillGetsItsResponse() + { + Steps.Reset(); + Steps.Log($"CLIENT [1] server request timeout = {ServerTimeout.TotalSeconds:0.#}s, client RequestTimeout = none (waits forever)"); + Steps.Log($"CLIENT [2] handler will take {HandlerWork.TotalSeconds:0.#}s, i.e. it outlives the server deadline"); + Steps.Log($"CLIENT [3] sending request, awaiting the response with a {Lease.TotalSeconds:0.#}s test lease"); + + try + { + var result = await Proxy + .EchoAfterIgnoringCancellation("payload", HandlerWork) + .ShouldCompleteInAsync(Lease); + + Steps.Log($"CLIENT [7] response received: \"{result}\""); + result.ShouldBe("payload"); + } + catch (Exception ex) + { + Steps.Log($"CLIENT [7] NO RESPONSE EVER ARRIVED - {ex.GetType().Name} after the {Lease.TotalSeconds:0.#}s lease"); + await ProbeConnectionStillAlive(); + throw; + } + finally + { + _outputHelper.WriteLine(""); + _outputHelper.WriteLine("======================= STEP TRACE ======================="); + foreach (var line in Steps.Drain()) + { + _outputHelper.WriteLine(line); + } + _outputHelper.WriteLine("=========================================================="); + } + } + + /// Shows the pipe is fine - the first answer was lost, not the connection. + private async Task ProbeConnectionStillAlive() + { + try + { + var pong = await Proxy + .EchoAfterIgnoringCancellation("ping", TimeSpan.Zero) + .ShouldCompleteInAsync(TimeSpan.FromSeconds(5)); + Steps.Log($"CLIENT [8] a second call on the SAME connection returned \"{pong}\" - the pipe was healthy all along"); + } + catch (Exception ex) + { + Steps.Log($"CLIENT [8] the probe call also failed: {ex.GetType().Name}"); + } + } +} diff --git a/src/UiPath.CoreIpc.Tests/RequestTimeoutTestsOverNamedPipes.cs b/src/UiPath.CoreIpc.Tests/RequestTimeoutTestsOverNamedPipes.cs new file mode 100644 index 00000000..1ca13360 --- /dev/null +++ b/src/UiPath.CoreIpc.Tests/RequestTimeoutTestsOverNamedPipes.cs @@ -0,0 +1,22 @@ +using UiPath.Ipc.Transport.NamedPipe; +using Xunit.Abstractions; + +namespace UiPath.Ipc.Tests; + +public sealed class RequestTimeoutTestsOverNamedPipes : RequestTimeoutTests +{ + private string PipeName => Names.GetPipeName(role: "requestTimeout", TestRunId); + + public RequestTimeoutTestsOverNamedPipes(ITestOutputHelper outputHelper) : base(outputHelper) { } + + protected sealed override async Task CreateServerTransport() => new NamedPipeServerTransport + { + PipeName = PipeName + }; + + protected sealed override ClientTransport CreateClientTransport() => new NamedPipeClientTransport() + { + PipeName = PipeName, + AllowImpersonation = true, + }; +} diff --git a/src/UiPath.CoreIpc.Tests/Services/ISlowService.cs b/src/UiPath.CoreIpc.Tests/Services/ISlowService.cs new file mode 100644 index 00000000..9997a14e --- /dev/null +++ b/src/UiPath.CoreIpc.Tests/Services/ISlowService.cs @@ -0,0 +1,14 @@ +namespace UiPath.Ipc.Tests; + +public interface ISlowService +{ + /// + /// Returns the after has elapsed. + /// + /// + /// Deliberately has no parameter, so the server's request + /// timeout cannot stop it and it always runs to completion. This is the shape of the real world + /// contracts that hit the dropped response bug, such as Studio's IProjectProcessControlService.OpenProject. + /// + Task EchoAfterIgnoringCancellation(string value, TimeSpan waitOnServer); +} diff --git a/src/UiPath.CoreIpc.Tests/Services/SlowService.cs b/src/UiPath.CoreIpc.Tests/Services/SlowService.cs new file mode 100644 index 00000000..45a46fad --- /dev/null +++ b/src/UiPath.CoreIpc.Tests/Services/SlowService.cs @@ -0,0 +1,39 @@ +using System.Diagnostics; + +namespace UiPath.Ipc.Tests; + +/// Temporary step tracing, so the chronology of the dropped response is observable. +internal static class Steps +{ + private static readonly Stopwatch Clock = Stopwatch.StartNew(); + private static readonly System.Collections.Concurrent.ConcurrentQueue Lines = new(); + + public static void Reset() + { + while (Lines.TryDequeue(out _)) { } + Clock.Restart(); + } + + public static void Log(string message) => Lines.Enqueue($"t+{Clock.Elapsed.TotalSeconds,5:0.00}s {message}"); + + public static string[] Drain() => Lines.ToArray(); +} + +public sealed class SlowService : ISlowService +{ + public async Task EchoAfterIgnoringCancellation(string value, TimeSpan waitOnServer) + { + Steps.Log($"SERVER [4] handler entered for \"{value}\" - will work {waitOnServer.TotalSeconds:0.#}s, takes no CancellationToken parameter"); + + // Read-only peek at the ambient token purely so we can SEE it fire. The handler still does not + // act on it, so the scenario is unchanged - this is exactly what OpenProject does. + var ambient = IpcContext.Current?.CancellationToken ?? default; + using var registration = ambient.Register( + () => Steps.Log("SERVER [5] *** request timeout FIRED - token canceled, but nobody is observing it, so the work continues ***")); + + await Task.Delay(waitOnServer); // deliberately no token + + Steps.Log("SERVER [6] handler RAN TO COMPLETION - the answer now exists; Server is about to call SendResponse(response, token)"); + return value; + } +} diff --git a/src/UiPath.CoreIpc/Server/Server.cs b/src/UiPath.CoreIpc/Server/Server.cs index 34f2ab49..5f81e053 100644 --- a/src/UiPath.CoreIpc/Server/Server.cs +++ b/src/UiPath.CoreIpc/Server/Server.cs @@ -102,7 +102,14 @@ private async ValueTask OnRequestReceived(Request request) { Log($"{DebugName} sending response for {request}"); } - await SendResponse(response, token); + // Not on `token`: the handler has already produced this response, so cancelling its + // delivery throws away work that is done and leaves the peer waiting on a healthy + // connection - forever, unless it happens to set a client side RequestTimeout. A handler + // that outlives the request timeout is exactly when this bites, because the token is + // already canceled by the time we get here. OnError sends on `default` for the same reason, + // and Connection.SendMessage already writes with CancellationToken.None once it holds the + // send lock - the token only ever gated acquiring that lock. + await SendResponse(response, default); } catch (Exception ex) when (response is null) {