Incorrect response time logged

[jasonkaisersmith]

Describe the bug While using an API REST controller with logging to Console the webserver logs responses to requests. This log information includes the response time in ms.

This response time is however incorrect and does not correspond to the actual response time the client experiences.

While performing tests using Postman as the client, then Postman reported responses between 9ms and 15ms for all the requests below.

The first request appears correct. The rest are totally wrong.

6:51:48.696 INF >> [WebServer] [Mx5kSDSNa0Op7I81+cqHWw] GET /api/statistics: "200 OK" sent in 9ms (chunked) 06:51:54.515 INF >> [WebServer] [aUwmWPbUcEeRAd3VGg8i1A] GET /api/statistics: "200 OK" sent in 5819ms (chunked) 06:51:57.526 INF >> [WebServer] [wUB7HO9icUCH5BZ88OGC6A] GET /api/statistics: "200 OK" sent in 3012ms (chunked) 06:51:59.218 INF >> [WebServer] [02I89cPg1E6byBihzb0SKQ] GET /api/statistics: "200 OK" sent in 1694ms (chunked) 06:52:00.652 INF >> [WebServer] [aFzm4L8t9EurksOy16ejOg] GET /api/statistics: "200 OK" sent in 1434ms (chunked) 06:52:01.733 INF >> [WebServer] [dn/De84W/EuW7VH+rN/eNw] GET /api/statistics: "200 OK" sent in 1082ms (chunked) 06:52:03.530 INF >> [WebServer] [SpGKCvoedkOmPY9zsCrvSg] GET /api/statistics: "200 OK" sent in 1797ms (chunked) 06:52:05.244 INF >> [WebServer] [2qhCnXtCxkeuwXnxhx+H5A] GET /api/statistics: "200 OK" sent in 1714ms (chunked) 06:52:06.133 INF >> [WebServer] [oKkgal0KWEua9yDQ7jy9nw] GET /api/statistics: "200 OK" sent in 889ms (chunked) 06:52:07.033 INF >> [WebServer] [eATwdNNDTUW0FKABwKp01g] GET /api/statistics: "200 OK" sent in 901ms (chunked) 06:52:07.871 INF >> [WebServer] [AQNwph8m0USP5bsQiYFRJw] GET /api/statistics: "200 OK" sent in 838ms (chunked) 06:52:08.705 INF >> [WebServer] [5E6Z4Ar4GUyeheH6GhHgQA] GET /api/statistics: "200 OK" sent in 835ms (chunked) 06:52:09.533 INF >> [WebServer] [4/tDJNYKO0+1Dg1iLup6SA] GET /api/statistics: "200 OK" sent in 828ms (chunked) 06:52:10.495 INF >> [WebServer] [Lvn53EZBZ0aUXKYJCn4jsg] GET /api/statistics: "200 OK" sent in 963ms (chunked) 06:52:11.306 INF >> [WebServer] [Fp2vr0+4G0+Mwxixq/sudg] GET /api/statistics: "200 OK" sent in 811ms (chunked)

I have also seen examples where the response time is quoted as 10 - 17 seconds but the reality was just a few ms.

To Reproduce Steps to reproduce the behavior:

1. Go to '...'
2. Click on '....'
3. Scroll down to '....'
4. See error

Expected behavior

The response times should correspond to reality.

Screenshots See log output above

Desktop (please complete the following information):

• OS: Windows 10 64-Bit running DotNet Core 3.0
• Browser: Postman
• Version 3.1.3

Smartphone (please complete the following information):

• Device: [e.g. iPhone6]
• OS: [e.g. iOS8.1]
• Browser [e.g. stock browser, safari]
• Version [e.g. 22]

Additional context

[geoperez]

I did a quick test against the Sample App but I couldn't reproduce the bug.

Can you post a snippet of your WebAPI?

[jasonkaisersmith]

Below are extracts of the code;

 [Route(HttpVerbs.Get, "/statistics")]
        public async Task GetStatistics()
        {
            try
            {
                await HttpContext.SendDataAsync(new RespObject(ApiCoord.Instance.GetStatistics()));
            }
            catch (Exception ex)
            {
                ApiCoord.Log(LogLevel.Error, "GetStatistics::" + ex.Message, ex);
                throw HttpException.InternalServerError("GetStatistics::" + ex.Message, ex.StackTrace);
            }
        }

The webserver is started as follows:

        int port = 33333;
             string url = "http://localhost:" + port;

             this.Webserver = new WebServer(o => o
                 .WithUrlPrefix(url)
                 .WithMode(HttpListenerMode.EmbedIO))
                 .WithLocalSessionManager()
                 .WithWebApi("/api", m => m
                 .WithController<ApiController>());

             this.Cts = new CancellationTokenSource();
             var task = Webserver.RunAsync(Cts.Token);

GetStatistics() returns a cached Object, or retrieves it from the DB if it is timed out (not in any of the examples above). RespObject is a simple object with a few fields and includes a JSON string serialised version of the cached Statistics object.

Sometimes the timing appears totally wrong as I have even got reports of 10, 12, 18 second response times when it is clear that my client is getting a response in just a few ms..

[geoperez]

Alright, I'll take a look at your sample code. Thanks!

[rdeago]

Hello @JasonKaisersmith, thanks for using EmbedIO!

Also hello @geoperez of course... and sorry for the delay. Quite a busy period here.

The relevant log entry is generated here in WebServerBase<TOptions>.DoHandleContextAsync, after flushing the response stream and closing the HTTP context.

The first question to ask IMHO is: what is taking so darn long? Let's make some hypotheses and verify them:

1. The FlushAsync method of whatever type implements the response stream (in this case EmbedIO.Net.Internal.ResponseStream) could return after the TCP closing handshake has completed. In this case, the client would probably see the response data well before the Task returned by FlushAsync completes; the delay would mainly depend upon environmental factors, such as network speed and CPU speed. If this is the case, there's very little we can do about it, but let's keep it as a possibility.

2. The Close method of the type implementing the HTTP context could be to blame; in this case, EmbedIO.Net.Internal.HttpListenerContext.Close. After closing the response, which we can assume takes little time, since the output stream has already been flushed, this method calls all callbacks registered via IHttpContext.OnClose. There's actually only one such callback in all EmbedIO: it's EmbedIO.Sessions.LocalSessionManager.OnContextClose, only called if there is a LocalSessionManager involved... which is actually the case. Hence, one test we can do involves removing session management and see whether logged response times are still crazy. @JasonKaisersmith, can you try this?

3. Finally, just for the sake of completeness, we could just be affected by how the SWAN library handles log entries. We'll have to wait and use an updated version of SWAN to see whether this issue disappears.

If I had to point a finger, I'd go for hypothesis 2, because we can see a difference between the first request, when the session is created, and subsequent requests, when the session already exists. It's little more than a gut feeling, to tell the truth, but it's also the easiest hypothesis to test.

[geoperez]

@rdeago do you get a chance to check my last PR in SWAN?

[rdeago]

@geoperez I did. Still waiting to see whether @JasonKaisersmith has had a chance of testing point 2, and what he found out.

[jasonkaisersmith]

@rdeago Sorry, it has taken me a while to get back to this.

I removed the .WithLocalSessionManager() from the code and I still had the same problem.

Interestingly I have noticed that the time reported back seems to be roughly the amount of time between my REST calls (I have not tested this scientifically), up to maybe 15 secs, when it then goes back to zero

[rdeago]

@JasonKaisersmith I'm going to do some tests on this today.

@geoperez this issue would be a good candidate for the v4.0 milestone too.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.