From 7319e2d79afdeab4f4bdd3634ecf31d1f03cad4a Mon Sep 17 00:00:00 2001 From: "andrei.singeorzan" Date: Mon, 10 Aug 2026 12:43:48 +0300 Subject: [PATCH] fix: deliver a completed response after the request timeout expires A handler that takes no CancellationToken keeps running past the request timeout, so `response` is non-null by the time SendResponse is reached. Sending it on the already-canceled token throws in Connection.SendMessage before a byte reaches the wire, and the `when (response is null)` filter does not match, so no Response.Fail is sent either. The caller is told nothing and waits forever on a healthy connection. Send the completed response on `default` instead, as OnError already does. This is narrow: Connection.SendMessage already writes with CancellationToken.None once it holds the send lock, so the token only ever gated acquiring that lock. Adds RequestTimeoutTests over named pipes, plus an ISlowService whose method deliberately declares no CancellationToken - no existing test service had that shape, which is why this had no coverage. Co-Authored-By: Claude Opus 5 (1M context) --- .../RequestTimeoutTests.cs | 100 ++++++++++++++++++ .../RequestTimeoutTestsOverNamedPipes.cs | 22 ++++ .../Services/ISlowService.cs | 14 +++ .../Services/SlowService.cs | 39 +++++++ src/UiPath.CoreIpc/Server/Server.cs | 9 +- 5 files changed, 183 insertions(+), 1 deletion(-) create mode 100644 src/UiPath.CoreIpc.Tests/RequestTimeoutTests.cs create mode 100644 src/UiPath.CoreIpc.Tests/RequestTimeoutTestsOverNamedPipes.cs create mode 100644 src/UiPath.CoreIpc.Tests/Services/ISlowService.cs create mode 100644 src/UiPath.CoreIpc.Tests/Services/SlowService.cs 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) {