sanic.exceptions.RequestTimeout: Request Timeout

Created on 21 Aug 2017 · 15Comments · Source: sanic-org/sanic

I glanced at the issues(61), and did not found the problem I encounter.
I find the problem more than one time. There is a example to show the problem.

In the module method_sanic.py, there is just one url. After I run the server by python method_sanic.py, I get the response through type http://[ip]:8001/get.

But, few seconds later, the backend throw an exception, sanic.exceptions.RequestTimeout: Request Timeout.

I try it few times, the problem is not occur every time.

##### filename: method_sanic.py
# -*- coding: utf-8 -*-

from sanic import Sanic
from sanic.response import text

app = Sanic()

@app.get('/get')
async def get_handler(request):
    return text('GET request - {}'.format(request.args))

if __name__ == "__main__":
    app.run(host="0.0.0.0", port=8001)

$ python method_sanic.py
2017-08-21 20:28:00 - (sanic)[DEBUG]:
                 ▄▄▄▄▄
        ▀▀▀██████▄▄▄       _______________
      ▄▄▄▄▄  █████████▄  /                 \
     ▀▀▀▀█████▌ ▀▐▄ ▀▐█ |   Gotta go fast!  |
   ▀▀█████▄▄ ▀██████▄██ | _________________/
   ▀▄▄▄▄▄  ▀▀█▄▀█════█▀ |/
        ▀▀▀▄  ▀▀███ ▀       ▄▄
     ▄███▀▀██▄████████▄ ▄▀▀▀▀▀▀█▌
   ██▀▄▄▄██▀▄███▀ ▀▀████      ▄██
▄▀▀▀▄██▄▀▀▌████▒▒▒▒▒▒███     ▌▄▄▀
▌    ▐▀████▐███▒▒▒▒▒▐██▌
▀▄▄▄▄▀   ▀▀████▒▒▒▒▄██▀
          ▀▀█████████▀
        ▄▄██▀██████▀█
      ▄██▀     ▀▀▀  █
     ▄█             ▐▌
 ▄▄▄▄█▌              ▀█▄▄▄▄▀▀▄
▌     ▐                ▀▀▄▄▄▀
 ▀▀▄▄▀

2017-08-21 20:28:00 - (sanic)[INFO]: Goin' Fast @ http://0.0.0.0:8001
2017-08-21 20:28:00 - (sanic)[INFO]: Starting worker [4514]
2017-08-21 20:28:08 - (network)[INFO][172.31.246.188:54142]: GET http://172.28.32.49:8001/get  200 16
2017-08-21 20:29:09 - (sanic)[ERROR]: Traceback (most recent call last):
  File "/root/.virtualenvs/py3.6.1env/lib/python3.6/site-packages/sanic/server.py", line 143, in connection_timeout
    raise RequestTimeout('Request Timeout')
sanic.exceptions.RequestTimeout: Request Timeout

^C2017-08-21 20:29:24 - (sanic)[INFO]: Stopping worker [4514]
2017-08-21 20:29:24 - (sanic)[INFO]: Server Stopped

2017-08-21 21:24:02 - (sanic)[INFO]: Goin' Fast @ http://0.0.0.0:8001
2017-08-21 21:24:02 - (sanic)[INFO]: Starting worker [4543]



2017-08-21 21:24:09 - (network)[INFO][172.31.246.188:56531]: GET http://172.28.32.49:8001/get  200 16


###### another attempt：
----

2017-08-21 21:24:19 - (network)[INFO][172.31.246.188:56531]: GET http://172.28.32.49:8001/get  200 16
2017-08-21 21:24:21 - (network)[INFO][172.31.246.188:56531]: GET http://172.28.32.49:8001/get  200 16
2017-08-21 21:25:21 - (sanic)[ERROR]: Traceback (most recent call last):
  File "/root/.virtualenvs/py3.6.1env/lib/python3.6/site-packages/sanic/server.py", line 143, in connection_timeout
    raise RequestTimeout('Request Timeout')
sanic.exceptions.RequestTimeout: Request Timeout

2017-08-21 21:25:22 - (sanic)[ERROR]: Traceback (most recent call last):
  File "/root/.virtualenvs/py3.6.1env/lib/python3.6/site-packages/sanic/server.py", line 143, in connection_timeout
    raise RequestTimeout('Request Timeout')
sanic.exceptions.RequestTimeout: Request Timeout

^C2017-08-21 21:25:33 - (sanic)[INFO]: Stopping worker [4543]
2017-08-21 21:25:33 - (sanic)[INFO]: Server Stopped

##### filename: sanic/server.py
    130     def connection_timeout(self):
    131         # Check if
    132         time_elapsed = current_time - self._last_request_time
    133         if time_elapsed < self.request_timeout:
    134             time_left = self.request_timeout - time_elapsed
    135             self._timeout_handler = (
    136                 self.loop.call_later(time_left, self.connection_timeout))
    137         else:
    138             if self._request_stream_task:
    139                 self._request_stream_task.cancel()
    140             if self._request_handler_task:
    141                 self._request_handler_task.cancel()
    142             try:
    143                 raise RequestTimeout('Request Timeout')
    144             except RequestTimeout as exception:
    145                 self.write_error(exception)

Now, the problem is a bug in sanic? I use it in a wrong way?

Any response is gratitude.

Source

jiaxiaolei

👍20 😕1

Most helpful comment

I've been seeing this error behaviour with every Sanic app I've written in the last month or two.
I get a ConnectionTimeout error exactly 60 seconds after receiving a request, even when the request is handled and a HTTPRespose has been sent.

I see it when I use Postman to test my routes, _but also_ when I use Firefox and Chromium.

By reading through the Sanic sourcecode and tracing requests and responses step-by-step, I have determined why this is happening, and it is caused by the fact when using the KeepAlive feature, sanic's default KeepAliveTimeout value is equal to the RequestTimeout value (which is 60 seconds by default).

So the browser upholds its side of the deal by keeping the connection open for 60 seconds after receiving the response. Even though Sanic updates the last_request_time variable when a response is sent, the timer ALWAYS runs out (and throws the TimeoutException) _just_ before the remote client (the browser) closes the connection.

And I _believe_ this is _normal_ and _expected_ behaviour. This is the intended result of the KeepAlive feature expiring correctly and it is being triggered exactly when it should be. The problem is it is reported and logged as an [ERROR], and the name "RequestTimeout" is confusing and misleading. I believe there should some additional logic in place to discern between a _real_ RequestTimeout and the KeepAlive simply expiring, if it is the latter, it should be logged as [INFO] or [DEBUG] because it is not an error.

ashleysommer on 11 Sep 2017

👍21

All 15 comments

Are you, by chance, reproducing this using postman? One reason your connection would keep dropping is if the client wouldn't respect the Connection: keep-alive header. I'm not experiencing those timeouts, as long as the connection was established from the browser, or a robust client such as curl/httpie.

jrocketfingers on 21 Aug 2017

Thanks for your replay. I use chrom to visit the url http://172.28.32.49:8001/get. The information about Header is as follows.

Request Header:

GET /get HTTP/1.1
Host: 172.28.32.49:8001
Connection: keep-alive
Pragma: no-cache
Cache-Control: no-cache
Upgrade-Insecure-Requests: 1
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.101 Safari/537.36
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
Accept-Encoding: gzip, deflate
Accept-Language: zh-CN,zh;q=0.8,en;q=0.6
Cookie: sessionid=9af0ae3o9mdcb8j6tjwyzp2zvrv58oam; csrftoken=cDnA9u2Wy3FRQOxrRmL0E1cYQhj7i8zww06H0wCA0UIhwKRlmhvUjcz1SKfbux91

Response Header:

HTTP/1.1 200 OK
Connection: keep-alive
Keep-Alive: 60
Content-Length: 16
Content-Type: text/plain; charset=utf-8

Should I drop Connection: keep-alive in Request Header?

jiaxiaolei on 22 Aug 2017

I have the same problem in our project. We are using Sanic with Socket.io server implementation.

MaxOvcharov on 1 Sep 2017

@MaxOvcharov Yes, we have the same problem.

@jackfischer Maybe the sanic team should pay attention to the issue.

jiaxiaolei on 2 Sep 2017

@MaxOvcharov could you elaborate your own issue? @jiaxiaolei does not have an actual issue aside from unnecessary exception being raised. I've tried the provided snippet and I'm getting the correct response, along with 200 status code.

@r0fls you might want to close this issue and the duplicate. Handling Keep-Alive connections does not seem to be standardized, so we might want to run a separate issue as a design draft. Last I've seen, flask does not even support keep-alive on it's own.

jrocketfingers on 3 Sep 2017

Yes, after I do debug=False, log_config=None in create_server everything seems OK. Thank you

MaxOvcharov on 8 Sep 2017

@MaxOvcharov I did debug=False, log_config=None in create_server, but the RequestTimeou remains.

@jrocketfingers you tried the snippet and fount no RequestTimeou. Maybe it's due to my computer or my network, or others is bout me.
The duplicate isssue(903) is closed.
This issue will keep open for some time. Maybe someone else have the same puzzle or question with me, then he can found the issue here.

jiaxiaolei on 9 Sep 2017

I see it when I use Postman to test my routes, _but also_ when I use Firefox and Chromium.

ashleysommer on 11 Sep 2017

👍21

In my post above, I was testing on v0.6.0.
I just tested again using Sanic from @master to see if the current behaviour is any different.
It is identical. I will starting writing a PR.

UPDATE:
Im going to need some input on what is the best approach.
My first thought was to change the connection logic to track _two different_ timeouts:

- first one is the current connection_timeout() callback
- based on request_timeout value, measured relative to the last response sent
- reported and logged as [ERROR] RequestTimeout
- a second timeout: keepalive_timeout() callback
- based on the keepalive_timeout value, measured relative to the last response sent
- reported and logged as [INFO] KeepAlive expired

However, that raises some questions:

What is a RequestTimeout supposed to be used for anyway? Is it a safeguard in case our application takes too long to process a response?
Why is the callback called connection_timeout()? Shouldn't it be called request_timeout()?
Why is _last_request_time variable reset when a Response is sent? Shouldn't it only be based on when last request was received? This to me seems like it was added as a cheap way of using the RequestTimeout as a makeshift KeepAlive timeout. The result being this Issue report.

ashleysommer on 11 Sep 2017

🎉2

I'm nearly done writing up some new code to track these timeouts.

Some things I've noticed:

The term 'RequestTimeout' as used in the Sanic server code is either misunderstood or deliberately used incorrectly. In the Sanic server code, it uses the term 'RequestTimeout' to cover three different Timeouts:
1. RequestTimeout (error 408), which is a timeout that occurs between the point in time when a TCP connection is created, and the the point in time when the entire HTTP request is received.
2. A ResponseTimeout (error 503), which is a timeout that occurs between the point in time when the server starts to process a request, and the point in time when the server delivers a response.
3. A KeepAliveTimeout (not an error), which is a timeout that occurs between the point in time when the server delivers a response, and the point in time when a new request is received on the same TCP connection.
Sanic currently throws a RequestTimeout when _any_ of these three conditions occur, and subsequently delivers a 408 response to the client.
Even more confusting is if you look in the test_receive_timeout.py Test code, the test code injects a delay into the response, causing the response to timeout, then throws, catches, and delivers a 408: Request Timeout. That is hilariously wrong.

Can someone clarify if it was a deliberate design decision to lump RequestTimeout, ResponseTimeout, and KeepAliveTimeout events all into one catch-all callback/exception? Perhaps for performance reasons?

I've currently got some proof-of-concept code that splits these out into _three_ separate timeout handlers with their own timeout callbacks, each with different logic, different logging properties, and different default values, as per what is set out in the HTTP 1.1 specs.

Im currently writing some tests to verify the new functionality, and as part of doing that, I've had to subclass two new Sanic Test Clients, one which can inject a delay between when the TCPConnection is opened and when the request is sent (to test RequestTimeout) and another one which can Reuse an existing open TCP connection (to test KeepAliveTimeout).

ashleysommer on 11 Sep 2017

👍3

Ha, I use Sanic and get a same problem today.
The code seem like a solution for this

@app.exception(exceptions.RequestTimeout)
async def Timeout(request, exception):
    return response.json({"status":"RequestTimeout"})

abersheeran on 16 Apr 2018

Hi folks, just wanted to say I'm still seeing this with 0.7.0. Just started using Sanic the last few days and it's great, but I usually get these RequestTimeout exceptions about a minute after the last request. I do see the KeepAlive timeout prior to that as well. I don't always see the RequestTimeout exceptions though, there's some randomness to it.