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"?

[binki]

@ning51 I’m not sure if there’s a concise way to clearly convey what’s going on. I’d much prefer to change the event which triggers the log from an output flush to output close or error and continue using the existing “Request ended” text. I’m not sure what layer you’re working at—with keepalive requests the connection itself would still be open and you’d need to trigger off of the logical response message coming to an end.

If the event triggering the logging can’t be changed, then I’d rather the message say “Flushing response stream”: I think that would at least be honest and not misleading.

I’m not sure any of these options would be acceptible, though.

@dougbu I haven’t had time to check yet but I’m just basing my statement off of @ning51’s description of why there are multiple messages. I don’t know how an IIS static files module can stream a large file without sending multiple RQ_SEND_RESPONSE notifications myself, but if .net’s StreamContent can be changed to not send that multiple times per request then the issue would appear to be resolved because then IIS Express would only log the message once the request is actually complete. Unfortunately, I don’t understand the system very well and have not had a chance to try to debug it so I am likely extrapolating wrong.

I can at least verify that IIS Express gives me multiple “Request ended” messages per 4096 byte chunk when using StreamContent but not when plopping a large (333KB) JPEG into my web directory and directly downloading it with my browser (which uses the static files IIS module I assume).

[dougbu]

@binki from what I can see in .NET Core 2.1 e.g. in the StreamContent implementation, that class does not itself Flush() and neither does its StreamToStreamCopy helper.

What specific Stream subclass does GetStreamFromSomewhere()` return. The flushing may be done there.

Alternatively, the destination Stream may be the response body and it may be logging whenever a large WriteAsync(...) completes. To check this, suggest calling the StreamContent constructor with an explicit bufferSize to override whatever the default size is in the Stream passed to StreamContent. (At least in the base Stream class, that default is 81920 bytes.) Let us know if raising or lowering the buffer size decreases or increases the number of messages logged.

Side note: None of these classes are in this repo. I'm trying to narrow things down in case we need to file a .NET Core issue.

[dougbu]

… and a .NET Framework issue (which is somewhat separate).

[dougbu]

@binki thank you for your feedback. We're closing this issue as no updates have been provided in a timely manner to my most recent questions and your questions have been answered. If you have more details and are encountering this issue please add a new reply and re-open the issue.