HttpLoggingMiddleware + Websockets/Upgrade

[jkotalik]

We need to verify that we either log the response correctly or disable request and response logging for websocket upgrades.

[Tratcher]

We should be able to log upgrade requests normally (Request.Body is not used for upgrades).

For upgrade responses we'll have to wrap the upgrade feature in order to get a timely notification of the upgrade and log headers. Otherwise the default logging will happen when the middleware eventually exits. No special handling is required for the body, Response.Body is not used for upgrades.

Thanks for contacting us.
We're moving this issue to the Next sprint planning milestone for future evaluation / consideration. Because it's not immediately obvious that this is a bug in our framework, we would like to keep this around to collect more feedback, which can later help us determine the impact of it. We will re-evaluate this issue, during our next planning meeting(s).
If we later determine, that the issue has no community involvement, or it's very rare and low-impact issue, we will close it - so that the team can focus on more important and high impact issues.
To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

We've moved this issue to the Backlog milestone. This means that it is not going to be worked on for the coming release. We will reassess the backlog following the current release and consider this item at that time. To learn more about our issue management process and to have better expectation regarding different types of issues you can read our Triage Process.

[gfr-g]

Hello, I would like to take a look at this issue but it's my first time working with this codebase and I'd appreciate some direction.

From my initial investigation, the issue seems to lie in the way AcceptWebSocketAsync() sends the response to the upgrade request, by "temporarily bypassing" the middleware pipeline. This appears to be as designed, since also the documentation mentions the fact that the middleware pipeline should be kept running, although I'm curious to know why it was designed this way.

From a pure speculative point of view, what I expected to happen is something like:

• AcceptWebSocketAsync() should accept a delegate that handle the messages inside the WebSocket that will eventually be established

• The 101 response is sent using the usual way, by short circuiting the middleware pipeline

• The WebSocket "upgrades" the connection and is tied to it (so it should not be disposed or reused) and not to the request through the HttpContext.

I'd like to hear your thoughts about this. I surely have missed a lot of nuances, and I'm also curious to know if there is a easier way to handle this as @Tratcher mentioned that a possible solution is to "wrap the upgrade feature".

Thank you

[Tratcher]

@gfr-g we tried that design in prior stacks like ASP.NET 4.x and Microsoft.Owin, it had its own tradeoffs. Regardless, that's not a design point we can change at this point without breaking all the current users.

And yes, it should be possible to wrap the IHttpUpgradeFeature similar to how logging wraps the response body today. When UpgradeAsync is called that would trigger the same response header logging as writing to the response body does. We would not want to capture any of the actual websocket traffic.

aspnetcore/src/Http/Http.Features/src/IHttpUpgradeFeature.cs

Line 9 in f08285d

public interface IHttpUpgradeFeature

[gfr-g]

@Tratcher thank you very much for your answer but, unfortunately, I think I'm missing something very obvious because I wasn't able to figure out exactly what you mean.

This part: "And yes, it should be possible to wrap the IHttpUpgradeFeature similar to how logging wraps the response body today. When UpgradeAsync is called that would trigger the same response header logging as writing to the response body does." makes me believe there's an actual system in place that immediately logs the response headers when the response body is written to. I failed to find this wrapping mechanism in the source code and I also failed to make it work with a simple example like this that I believe should show what I think you meant with the sentence above

[...]

app.UseHttpLogging();
app.Use(async (context, next) =>
{
	await next();
	await Task.Delay(10000);
});

app.Run(async (context) =>
{
        // not really necessary 
	context.Response.StatusCode = 200;
	context.Response.Headers.ContentType = "text/html; charset=UTF-8";

        // write to the body
	await context.Response.WriteAsync("test");
});

[...]

I'm not able to see any response headers being logged (I used the console provider and the event source provider) while the middleware pipeline is waiting for the ten seconds delay.

Would you mind to please elaborate further your proposal?