Sanic appears to terminate the connection early when downloading on a slow connection

[nfergu]

Is there an existing issue for this?

• I have searched the existing issues

Describe the bug

When downloading 20MB of data on a slow connection, Sanic appears to terminate the connection early. When running a simple Sanic test server, if I run the following curl command:

curl -v --limit-rate 100k --output /tmp/output.zip "http://127.0.0.1:8000/foo"

I get the following error:

curl: (18) transfer closed with 17261364 bytes remaining to read

after some time (between 30 seconds and one minute typically).

Code snippet

Run the following Python code:

from sanic import Sanic
from sanic.response import raw

app = Sanic("MyHelloWorldApp")


@app.get("/foo")
async def foo_handler(request):
    data = open("/dev/urandom", "rb").read(20 * 1024 * 1024)
    return raw(data)

if __name__ == "__main__":
    app.run(debug=True)

And then execute this command on the command-line:

curl -v --limit-rate 100k --output /tmp/output.zip "http://127.0.0.1:8000/foo"

Expected Behavior

I would expect the download to complete and all data should be saved to the file at /tmp/output.zip. However, instead I get an error. Full output from curl:

curl -v --limit-rate 100k --output /tmp/output.zip "http://127.0.0.1:8000/foo"
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0*   Trying 127.0.0.1:8000...
* Connected to 127.0.0.1 (127.0.0.1) port 8000 (#0)
> GET /foo HTTP/1.1
> Host: 127.0.0.1:8000
> User-Agent: curl/7.77.0
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< content-length: 20971520
< connection: keep-alive
< alt-svc:
< content-type: application/octet-stream
<
{ [102280 bytes data]
 21 20.0M   21 4399k    0     0   102k      0  0:03:20  0:00:43  0:02:37   99k* transfer closed with 16411112 bytes remaining to read
 21 20.0M   21 4453k    0     0   102k      0  0:03:20  0:00:43  0:02:37   99k
* Closing connection 0
curl: (18) transfer closed with 16411112 bytes remaining to read

How do you run Sanic?

Script

Operating System

Mac OS 12.2.1 (also appears to happen on Linux in our production system)

Sanic Version

22.9.1 (also tried 21.12.1 and it happens there too)

Additional context

This does not seem to happen in the previous version we used (19.x). I just tried on 19.12.5 and it does not happen.

[nfergu]

This seems fixable by setting the value of KEEP_ALIVE_TIMEOUT to a large value. For example, if I throttle the download speed to 200k, a value of 75 seconds for KEEP_ALIVE_TIMEOUT results in a successful download.

However, as I understand it, this shouldn't be necessary. My understanding is that, along as the client is still downloading data, KEEP_ALIVE_TIMEOUT should not be relevant. But perhaps I've misunderstood how this is supposed to work.

[ahopkins]

What you really want is REQUEST_TIMEOUT. https://sanic.dev/en/guide/deployment/configuration.html#request-timeout

[nfergu]

Hi @ahopkins. Thanks for your response. The issue still occurs when setting a very large REQUEST_TIMEOUT (and RESPONSE_TIMEOUT). For example if I run the following Python code:

from sanic import Sanic
from sanic.response import raw

app = Sanic("MyHelloWorldApp")
app.config.REQUEST_TIMEOUT = 2000
app.config.RESPONSE_TIMEOUT = 2000


@app.get("/foo")
async def foo_handler(request):
    data = open("/dev/urandom", "rb").read(20 * 1024 * 1024)
    return raw(data)

if __name__ == "__main__":
    app.run(debug=True)

And then run this on the command line:

curl -v --limit-rate 100k --output /tmp/output.zip "http://127.0.0.1:8000/foo"

The problem still occurs.

[nfergu]

Here's a pure Python reproduction of the issue (without using curl). As above, run a Sanic server:

from sanic import Sanic
from sanic.response import raw

app = Sanic("MyHelloWorldApp")
app.config.REQUEST_TIMEOUT = 2000
app.config.RESPONSE_TIMEOUT = 2000


@app.get("/foo")
async def foo_handler(request):
    data = open("/dev/urandom", "rb").read(20 * 1024 * 1024)
    return raw(data)

if __name__ == "__main__":
    app.run(debug=True)

And then in a separate process, run this:

from time import sleep

import requests
import logging

logging.basicConfig(level=logging.DEBUG)

url = 'http://127.0.0.1:8000/foo'
s = requests.Session()
r = s.get(url, stream=True)

total = 0
for chunk in r.iter_content(chunk_size=1024 * 1024):
    total += len(chunk)
    sleep(10)

assert total == 20 * 1024 * 1024

In Sanic version 19.12.5 this succeeds, but in Sanic 22.9.1 this fails with this error:

Traceback (most recent call last):
  File ".../dorequest.py", line 20, in <module>
    assert total == 20 * 1024 * 1024
AssertionError

I believe this is because the connection is closed before all of the data is downloaded.