HttpForwarder.SendAsync doesn't set Response.StatusCode on certain timeouts?

[simendsjo]

I'm using YARP 1.1 for several applications for implementing blue/green deploy
on IIS. It's been working great, but on Monday, we experienced a strange thing.

The underlying service stopped working properly, but YARP still responded 200
rather than something like 504. It looks like a timeout after 100 seconds,
probably because the service hung during the requests, but the response is 200.

It looks like the HttpForwarder always tries setting a response code, even in
case anything goes wrong. But it seems there's some code path where it isn't
set? And when the call to the proxy returns, it's set as 200?

I couldn't find out where ResponseCode isn't set, but I guess it's in some error
case I'm unable to find. By looking at the source, I could only see a single
place, but I don't think this is what's going on:

// First the SendAsync has to throw
destinationResponse = await httpClient.SendAsync(destinationRequest, activityCancellationSource.Token);
// to get us into HandleRequestFailureAsync
// The exception cannot be an OperationCanceledException
// and requestContent?.ConsumptionTask.IsCompleted == true

// Then the StreamCopyResult cannot be a success
var (requestBodyCopyResult, requestBodyException) = requestContent.ConsumptionTask.Result;
if (requestBodyCopyResult != StreamCopyResult.Success)

// Then within HandleRequestBodyFailure, the context.Response.HasStarted has to be
// true. In that case, I cannot see context.Response.StatusCode being set. But in
// that case it looks like it tries to abort the context which shouldn't set 200 ok?

But it really looks like ResponseCode isn't set by YARP in some timeout case,
and that we end up with 200 because our endpoint returns.

In the image, you can see YARP is W3SVC124, and the underlying application is
W3SVC125. It starts off by the underlying service returning 200, then YARP
returning 200. Then at 08:03:47, YARP starts returning 200 after 100 seconds,
and the underlying service never returns. The application later starts failing,
probably because the W3SVC124 worker process fails to contact the OutOfProcess
Kestrel application as it has really gone down, and this is correctly reported
as 502. We haven't encountered any other issues with YARP after running it in
various environments on various applications for a long time.

Any idea how to go forward on this? Any tips on what might be wrong? I didn't
feel like adding an issue for it as I have so little information.

Our code is very straight forward, and pretty much just looks like the following:

builder.Services.AddHttpForwarder();
// ... snip ...
app.UseEndpoints(endpoints => {
    var forwarder = app.Services.GetRequiredService<IHttpForwarder>();

    var httpClient = new HttpMessageInvoker(new SocketsHttpHandler {
        UseProxy = false,
        AllowAutoRedirect = false,
        AutomaticDecompression = DecompressionMethods.None,
        UseCookies = false,
        ActivityHeadersPropagator = new ReverseProxyPropagator(DistributedContextPropagator.Current)
    });

    var requestConfig = new ForwarderRequestConfig {
        ActivityTimeout = TimeSpan.FromMinutes(5)
    };

    endpoints.Map("/{**catch-all}", async httpContext => {
         await forwarder.SendAsync(httpContext, "https://the-application:48666", httpClient, requestConfig);
    });
});

[simendsjo]

I'm able to trigger something similar with the following testcode

app.MapGet("/write-some-then-block", async (HttpContext context) => {
    var delay = TimeSpan.FromMinutes(10.0);
    await context.Response.Body.WriteAsync(Encoding.UTF8.GetBytes($"We're blocking for {delay}"));
    await Task.Delay(delay);
    await context.Response.Body.WriteAsync(Encoding.UTF8.GetBytes($"Blocked for {delay}"));
});

It will get a partial response, but 200 OK.

It times out after 5m as I specified in YARP:

The default timeout is 100 seconds, but I don't understand how we could see this
in our environment rather than the 5 minutes though..

/// <summary>
/// How long a request is allowed to remain idle between any operation completing, after which it will be canceled.
/// The default is 100 seconds. The timeout will reset when response headers are received or after successfully reading or
/// writing any request, response, or streaming data like gRPC or WebSockets. TCP keep-alives and HTTP/2 protocol pings will
/// not reset the timeout, but WebSocket pings will.
/// </summary>
public TimeSpan? ActivityTimeout { get; init; }

But if I change ActivityTimeout to 1 second, I get a timeout after 1 second as expected, but this time with a 504 Gateway Timeout as expected. So it's somehow related to how long we're waiting...?

[Tratcher]

The status code can't be changed after the first write to the response body, the status and headers have already been sent to the client. That's what's happening in your sample, and it sounds like what's happening in your issue?

[simendsjo]

Makes sense. Let's see if I understand this correctly.

The underlying site starts writing, thus returns 200, and YARP sets the status code and starts writing further to the client. Then later some timeout happens (not ActivityTimeout), causing a disconnect. YARP states this in it's error response, but everything is still written to the client.

And thus, the same would happen even without YARP in the front given that a timeout still happened.

[Tratcher]

Right. Errors encountered after the status and headers are sent can only be reported by aborting the response/connection.

[simendsjo]

Thanks! I'll look into how I can best handle these cases without causing confusion.