IISExpress logs multiple “Request ended” per request when using HttpResponseMessage with StreamContent

[binki]

When I have an action that returns HttpResponseMessage with Content set to a StreamContent and run it in OWIN on IIS Express, I get multiple “Request ended” messages per request. There are more extra lines if the Stream I pass is longer. I assume that I should only ever see one such message in IIS Express. Since this happens when using this particular stack, I assume the issue is with how Web API or OWIN SystemWeb interacts with IIS Express and not an issue with IIS Express itself.

To get this behavior, I have an action handler which returns an HttpResponseMessage with a StreamContent:

public HttpResponseMessage Get() {
  var response = Request.CreateResponse();
  response.Content = new StreamContent(GetStreamFromSomewhere());
  return response;
}

I have my app configured with an OWIN runner:

[assembly: OwinStartup(typeof(WebApplication1.Startup1))]

namespace WebApplication1
{
    public class Startup1
    {
        public void Configuration(IAppBuilder app)
        {
            var httpConfiguration = new HttpConfiguration();
            httpConfiguration.Routes.MapHttpRoute("DefaultApi", "api/{controller}/{id}", new
            {
                id = RouteParameter.Optional,
            });

            app.UseWebApi(httpConfiguration);
        }
    }
}

Configured to be served by IISExpress in applicationhost.config:

<site name="WebApplication1" id="2">
    <application path="/">
        <virtualDirectory path="/" physicalPath="%USERPROFILE%\source\repos\WebApplication1\WebApplication1" />
    </application>
    <bindings>
        <binding protocol="http" bindingInformation=":8080:localhost" />
    </bindings>
</site>

And then run IISExpress:

C:\Users\binki>"\Program Files\IIS Express\iisexpress.exe" /Site:WebApplication1
Starting IIS Express ...
Successfully registered URL "http://localhost:8080/" for site "WebApplication1" application "/"
Registration completed for site "WebApplication1"
IIS Express is running.
Enter 'Q' to stop IIS Express

And make a single request with curl:

$ curl -sS -o/dev/null http://localhost:8080/api/values

Then IISExpress logs multiple “Request ended” lines (at least two per response, more if the stream is longer):

Request started: "GET" http://localhost:8080/api/values
Request ended: http://localhost:8080/api/values with HTTP status 200.0
Request ended: http://localhost:8080/api/values with HTTP status 200.0
Request ended: http://localhost:8080/api/values with HTTP status 200.0
Request ended: http://localhost:8080/api/values with HTTP status 200.0

I created a demo of the behavior (EDIT: fix URI) which also intercepts calls to Read() and ReadAsync() on the stream and it shows that each extra “Request ended” message occurs after a Read():

Request started: "GET" http://localhost:8080/api/values
Read[+0](, 0, 4096) = 4096
Request ended: http://localhost:8080/api/values with HTTP status 200.0
Read[+4096](, 0, 4096) = 4096
Request ended: http://localhost:8080/api/values with HTTP status 200.0
Read[+8192](, 0, 4096) = 3808
Request ended: http://localhost:8080/api/values with HTTP status 200.0
Read[+12000](, 0, 4096) = 0
Request ended: http://localhost:8080/api/values with HTTP status 200.0

I don’t know where this behavior is coming from. I’m using these versions of things:

Windows 10.0.17723 and Windows 10.0.17728
IISExpress-10.0.14358.1000

   <PackageReference Include="Microsoft.AspNet.WebApi.Owin">
      <Version>5.2.6</Version>
    </PackageReference>
    <PackageReference Include="Microsoft.Owin">
      <Version>4.0.0</Version>
    </PackageReference>
    <PackageReference Include="Microsoft.Owin.Host.SystemWeb">
      <Version>4.0.0</Version>
    </PackageReference>
    <PackageReference Include="Owin">
      <Version>1.0.0</Version>
    </PackageReference>

Also happens with Owin-3.0.x and Microsoft.AspNet.WebApi.Owin-5.2.3.

This behavior is annoying because when I serve larger files via StreamContent, the window IIS Express is running in obscures other requests and falsely reports more request ends than there actually are.

[binki]

@dougbu Given this issue is marked external, is there a better place for me to report it/follow up?

[dougbu]

@binki it's highly unlikely this problem is in Web API. However, we will attempt to route things to the appropriate team (lIS Express). Will respond here when we have more information.

In the future, it may be preferable to file IIS Express issues in the VS Developer Community forums.

/cc @shirhatti

[ning51]

@binki The line "Request ended: ..." is written whenever iisexpress gets a notification of RQ_SEND_RESPONSE, which actually means a response has been sent by iisexpress (not when the request ends). It is a bit misleading, but this tracing is not intended for tracking requests. For more accurate request logging, you should look at iisexpress logs at %USERPROFILE%\Documents\IISExpress\Logs.

[binki]

@ning51 Then why don’t I see a bunch of these messages when using the IIS static file handler with IIS Express? Is it because that’s probably using something like TransmitFile() instead?

[ning51]

@binki From debugging I can see Asp.Net explicitly requests a flush after each read, triggering a RQ_SEND_RESPONSE notification. The static file handler doesn't have such behavior.

[binki]

@ning51 One last thing, even though we now know that “Request ended: ” is not associated with a request ending but is just from flushing, can’t it be considered a bug that the message says that? It’s not just misleading, I think it’s incocrrect. I would expect a message with that text to be associated with the socket/stream being closed rather than flushing. And if a message must be shown when flushing happens, it would make more sense to me for it to be more honest and say that a flush happened.

I wonder if there is a reason for the flush. I think that ASP.NET flushing the output could reduce the throughput because that means ASP.NET will wait for output network buffers to be emptied (assuming IIS actually honors the flush) before it produces/loads more data to write to the output stream. If ASP.NET kept the output stream’s buffers full, it would still have pushback but would reduce the chance that the client needs to wait for ASP.NET to produce/load more data after the flush. If the flush is considered questionable, then maybe it would make sense to change ASP.NET itself to not flush?

Thanks for the insights into this issue and taking the time to debug it! Even if this behavior won’t be changed or considered a fixable bug, it’s interesting to know the cause of the unexpected behavior.

[dougbu]

I think that ASP.NET flushing the output could reduce the throughput because that means ASP.NET will wait for output network buffers to be emptied

This is actually more about making information visible to the user as soon as possible. Many deserializers can display the beginning of a download long before the end is seen.

[ning51]

@binki I am going to log a bug to change the wording (from "Request ended" to "Response sent").

As for why ASP.NET does the flush, I am afraid that I don't have the expertise to comment. @shirhatti any idea?

[dougbu]

@ning51 please see my earlier comment on why ASP.NET flushes:

This is actually more about making information visible to the user as soon as possible. Many deserializers can display the beginning of a download long before the end is seen.

[binki]

@ning51

@binki I am going to log a bug to change the wording (from "Request ended" to "Response sent").

Before you do that, I’m not sure that new language is clear enough. “Response sent” implicitly means “Response fully sent” to me.

@dougbu
I don’t know how it works well enough, but I suspect that flushing on every write reduces the potential maximum throughput.

[dougbu]

I suspect that flushing on every write reduces the potential maximum throughput.

Agreed. Where exactly do you see the framework "flushing on every write"?

[ning51]

@binki how about just "Response"?