KeepAlive Timeout: what is it?

[smlbiobot]

Since upgrading from 0.5.0 to 0.7.0 I am seeing a lot of these in my logs:

[2018-01-18 17:37:16 +0800] [5425] [INFO] KeepAlive Timeout. Closing connection.
[2018-01-18 17:37:16 +0800] [5425] [INFO] KeepAlive Timeout. Closing connection.
[2018-01-18 17:37:16 +0800] [5425] [INFO] KeepAlive Timeout. Closing connection.
[2018-01-18 17:37:16 +0800] [5425] [INFO] KeepAlive Timeout. Closing connection.
[2018-01-18 17:37:16 +0800] [5425] [INFO] KeepAlive Timeout. Closing connection.
[2018-01-18 17:37:16 +0800] [5425] [INFO] KeepAlive Timeout. Closing connection.

What are these and are they normal or is there something in my code that I need to fix?

[arthurlenoir]

Same here but everything's going well anyway. ¯\(ツ)/¯

[frnkvieira]

They are perfectly normal (in most cases). In HTTP/1.1 connections are keep-alive by default which means your browser keeps the connection open after it made all the requests. After some time if you don't request a new page this connection will timeout. Not sure why Sanic devs log such thing in INFO mode. IMHO this would be a DEBUG level since most users don't even understand what's going on.

[smlbiobot]

Also, I kept on getting these, which also didn’t use to happen:

WARNING:asyncio:Executing <Handle <TaskWakeupMethWrapper object at 0x108fbf2e8> created at /usr/local/Cellar/python3/3.6.4_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/tasks.py:639> took 0.828 seconds

What am I being warned about exactly? The site runs fine and I don’t quite understand what I am supposed to fix.

[arnulfojr]

As @frnkvieira said, this are perfectly normal messages, you can take a look into the docs for more information.
I would only disagree in the logging level that frnkviera says, as this is configurable (can be switched off) makes sense to have it in INFO level, also because it is connection-related information.

I would suggest to keep it on, if the client requesting will request several "resources" (i.e. frontend client) but if you're only dealing with a single API call from time to time then you can switch it off (if you want to ignore it it's ok but you can switch it off while developing).

hope it helps :) (if so then please don't forget to close the issue)

[yunstanford]

I'm also thinking this could be DEBUG level

[xen]

@smlbiobot this is a notification that you have some code that runs longer than expected by Sanic.

[smlbiobot]

ah ok thanks very much — that is helpful. If I encounter many of those, am I supposed to add in some asyncio.sleep(0) every now and then?

[zjuchenyuan]

documentation here:

http://sanic.readthedocs.io/en/latest/sanic/config.html#what-is-keep-alive-and-what-does-the-keep-alive-timeout-value-do

[ashleysommer]

@smlbiobot Theres some confusion and misunderstanding in this thread that I'd like to clear up.
And some useful points to discuss.

Some background:
Last year, sanic did not have Response Timeout nor Keepalive Timeout. It only had a Request Timeout.
But that request timeout was used to indicate three different things.

1. A request took too long to arrive from the client to the server.
2. A response took too long to be generated by the server app, or too long to send back to the client.
3. The Keep-Alive feature was used, and the keep alive timer timed out.

The Request Timeout variable was default to 60 seconds.
In all three of these cases a RequestTimeout exception was thrown if this timeout triggered, and a HTTP Client Error response was generated by the server with code 403 "RequestTimeout" and was sent back to the client.

This was correct behaviour for scenario 1, but not for 2 or 3. The biggest problem was that every time a client connected using the KeepAlive function, we would see an unexplainable RequestTimeout Exception thrown by the server 60 seconds later, logged to the console, and 403 response sent to the client, as reported in Issue #902.

In response to that, in PR #939 I wrote some code to split the Request Timeout into three different timeouts. Each with their own configurable timeout length in seconds. Read about them in the docs as pointed out by @arnulfojr and @zjuchenyuan here:
http://sanic.readthedocs.io/en/latest/sanic/config.html#what-is-keep-alive-and-what-does-the-keep-alive-timeout-value-do

The biggest change #939 introduced is that we are no longer treating KeepAliveTimeout as an error. It is a normal thing to happen. Every KeepAlive-enabled connection is expected to timeout at some point after it is created. So rather than throwing an exception (as per previous behaviour), it now simply logs it using the normal server-level logging output. So rather than seeing logs polluted with RequestTimeout exceptions as per #902, we are now seeing logs polluted with KeepAlive Timeout notifications, as per OP's issue here.

@xen

this is a notification that you have some code that runs longer than expected by Sanic

This is not correct. You are thinking of a ResponseTimeout exception.

@frnkvieira @arnulfojr @yunstanford
My decision to make this INFO level was quite arbitrary. It is certainly not at ERROR level nor WARNING, but I also consider it to be more important than DEBUG level. So I landed on INFO level.

After seeing this Issue thread, and the confusion that it is causing some users, I think perhaps it is better to move it to DEBUG level, but I want the opinion of others on that matter too.

[ashleysommer]

@smlbiobot

WARNING:asyncio:Executing <Handle <TaskWakeupMethWrapper object at 0x108fbf2e8> created at /usr/local/Cellar/python3/3.6.4_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/tasks.py:639> took 0.828 seconds

This is a python asyncio module output message. It is not related to Sanic.

It is indication that an asynchronous task was executed on the event loop and later returned a value after being awaited for a period of time. I'm not sure why it is logged at WARNING level.

[smlbiobot]

@ashleysommer

Thanks for your detailed response — it is rather unexpected but very helpful indeed. I have in fact encountered those same mysterious errors you have referenced in #902 and am very happy to know that they are in fact not errors. It took me a while to debug what is going on — but since I could not find anything wrong with my app, I just moved on and ignored them. Your explanation makes a lot of sense and I am happy that this is normal.

As per the asyncio warning, you are right, it appears that I have some rather complex logic stuck in those code blocks that require extra processing. I have taken the approach read on the web and inserted await asyncio.sleep(0) or await asyncio.sleep(0.1) here and here and those warnings are gone. I guess they are good indicators to make sure that the web app won’t get tied down to these process.

All in all — thanks for your help and it is very much appreciated.

I shall close this issue now since you have more than answered my questions.

[garyo]

If it makes a difference, I'd like the KeepAlive Timeout messages to be switched to debug level.

[zagfai]

Dame it