sanic: sanic.exceptions.RequestTimeout: Request Timeout
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.
About this issue
- Original URL
- State: closed
- Created 7 years ago
- Reactions: 21
- Comments: 15 (7 by maintainers)
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_timevariable 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.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.
I’m nearly done writing up some new code to track these timeouts.
Some things I’ve noticed:
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).
In my post above, I was testing on v0.6.0. I just tested again using Sanic from
@masterto 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:
connection_timeout()callbackrequest_timeoutvalue, measured relative to the last response sent[ERROR] RequestTimeoutkeepalive_timeout()callbackkeepalive_timeoutvalue, measured relative to the last response sent[INFO] KeepAlive expiredHowever, that raises some questions:
connection_timeout()? Shouldn’t it be calledrequest_timeout()?_last_request_timevariable 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.