uwsgi cannot process request longer than one minute

Question

I have a Django application that is served within docker container via uwsgi. I have prepared a custom view just to reproduce the issue I'm mentioning. It looks exactly like below:

def get(self, request):
    logger = logging.getLogger('ReleaseReport')
    logger.critical('Entering and sleeping')
    time.sleep(180)
    logger.critical('Awaking')

    return Response({'response': 'anything'})

The only thing it does (intentionally) is to log message, sleep for 3 minutes, and log another message afterwards.

Here is how the log file works after I try to visit the view from Firefox / Chrome / PyCharm's rest API client:

spawned uWSGI worker 9 (pid: 14, cores: 1)
spawned uWSGI worker 10 (pid: 15, cores: 1)
spawned uWSGI http 1 (pid: 16)
CRITICAL 2018-08-31 12:10:37,658 views Entering and sleeping
CRITICAL 2018-08-31 12:11:37,742 views Entering and sleeping
CRITICAL 2018-08-31 12:11:38,687 views Awaking
[pid: 10|app: 0|req: 1/1] 10.187.133.2 () {36 vars in 593 bytes} [Fri Aug 31 12:10:37 2018] GET /api/version/ => generated 5156 bytes in 61229 msecs (HTTP/1.1 200) 4 headers in 137 bytes (1 switches on core 0)
CRITICAL 2018-08-31 12:12:37,752 views Entering and sleeping
CRITICAL 2018-08-31 12:12:38,784 views Awaking
[pid: 15|app: 0|req: 1/2] 10.187.133.2 () {36 vars in 593 bytes} [Fri Aug 31 12:11:37 2018] GET /api/version/ => generated 5156 bytes in 61182 msecs (HTTP/1.1 200) 4 headers in 137 bytes (1 switches on core 0)
CRITICAL 2018-08-31 12:13:38,020 views Entering and sleeping
CRITICAL 2018-08-31 12:13:38,776 views Awaking
[pid: 10|app: 0|req: 2/3] 10.187.133.2 () {36 vars in 593 bytes} [Fri Aug 31 12:12:37 2018] GET /api/version/ => generated 5156 bytes in 61034 msecs (HTTP/1.1 200) 4 headers in 137 bytes (1 switches on core 0)

After one minute, the view seems to be executed again, and after another minute the third time is executed. Moreover, the log says it is HTTP 200, but the client doesn't receive the data and just says it cannot load it after few more minutes (depends on client). However the first HTTP 200 in log occurs much earlier before client gives up.

Any clues what may be causing that issue? Here is my uwsgi.ini:

[uwsgi]

http = 0.0.0.0:8000
chdir = /app
module = web_server.wsgi:application
pythonpath = /app

static-map = /static=/app/static

master = true
processes = 10
vacuum = true

The Dockerfile command is as following:

/usr/local/bin/uwsgi --ini /app/uwsgi.ini

In my real application, it causes that client thinks the request failed, but since it was actually executed and finished 3 times, there are 3 records in a database. Changing worker processes number to 1 doesn't change much. Instead of waitin one minute to spawn view again, it is spawned after previous one finishes.

What's wrong with my configuration?

EDIT:

I have changed my view a bit, it now accepts sleep time parameter and looks like this:

def get(self, request, minutes=None):
    minutes = int(minutes)
    original_minutes = minutes
    logger = logging.getLogger(__name__)
    while minutes > 0:
        logger.critical(f'Sleeping, {minutes} more minutes...')
        time.sleep(60)
        minutes -= 1

    logger.critical(f'Slept for {original_minutes} minutes...')
    return Response({'slept_for': original_minutes})

Now, curling:

> curl http://test-host/api/test/0
{"slept_for":0}

> curl http://test-host/api/test/1
{"slept_for":1}

> curl http://test-host/api/test/2
curl: (52) Empty reply from server

In log:

CRITICAL 2018-08-31 14:23:36,200 views Slept for 0 minutes...
[pid: 10|app: 0|req: 1/14] 10.160.43.172 () {28 vars in 324 bytes} [Fri Aug 31 14:23:35 2018] GET /api/test/0 => generated 15 bytes in 265 msecs (HTTP/1.1 200) 4 headers in 129 bytes (1 switches on core 0)
CRITICAL 2018-08-31 14:23:42,878 views Slept for 0 minutes...
[pid: 10|app: 0|req: 2/15] 10.160.43.172 () {28 vars in 324 bytes} [Fri Aug 31 14:23:42 2018] GET /api/test/0 => generated 15 bytes in 1 msecs (HTTP/1.1 200) 4 headers in 129 bytes (1 switches on core 0)
CRITICAL 2018-08-31 14:23:46,370 views Sleeping, 1 more minutes...
CRITICAL 2018-08-31 14:24:46,380 views Slept for 1 minutes...
[pid: 10|app: 0|req: 3/16] 10.160.43.172 () {28 vars in 324 bytes} [Fri Aug 31 14:23:46 2018] GET /api/test/1 => generated 15 bytes in 60011 msecs (HTTP/1.1 200) 4 headers in 129 bytes (1 switches on core 0)
CRITICAL 2018-08-31 14:27:06,903 views Sleeping, 2 more minutes...
CRITICAL 2018-08-31 14:28:06,963 views Sleeping, 1 more minutes...
CRITICAL 2018-08-31 14:29:06,995 views Slept for 2 minutes...
[pid: 9|app: 0|req: 1/17] 10.160.43.172 () {28 vars in 324 bytes} [Fri Aug 31 14:27:06 2018] GET /api/test/2 => generated 15 bytes in 120225 msecs (HTTP/1.1 200) 4 headers in 129 bytes (1 switches on core 0)

If I use the same command to test server running with manage.py runserver, it does answer every time - no matter if I sleep 2 minutes or 10. So it is not the client fault. I've changed harakiri to 3600, no change.

EDIT2 (my Dockerfile):

FROM python:3.7.0-alpine

ADD . /app

RUN set -ex \
    && apk add mysql-dev \
               pcre-dev \
    && apk add --no-cache --virtual .build-deps \
            gcc \
            make \
            libc-dev \
            musl-dev \
            linux-headers \
            libffi-dev \
    && pip install --no-cache-dir -r /app/requirements.txt \
    && runDeps="$( \
            scanelf --needed --nobanner --recursive /venv \
                    | awk '{ gsub(/,/, "\nso:", $2); print "so:" $2 }' \
                    | sort -u \
                    | xargs -r apk info --installed \
                    | sort -u \
    )" \
    && apk add --virtual .python-rundeps $runDeps \
    && apk del .build-deps

WORKDIR /app

RUN mkdir -p static
RUN python manage.py collectstatic --clear --noinput

EXPOSE 8000

CMD ["/usr/local/bin/uwsgi", "--ini", "/app/uwsgi.ini"]

After a while browsers "give up" and no longer listen to a response, regardless whether the server will provide one or not. Furthermore Django works with a pool of workers that handle requests if I recall correctly. So it will throttle the number of requests that are executed concurrently. — Willem Van Onsem, Aug 31 '18 at 12:24
I did tried different clients, including PyCharm's built in and Insomnia — Djent, Aug 31 '18 at 12:29
But your point is right. It seems like browser and clients are retrying. It seems like they cannot read the HTTP response and just are trying again. Curl doesn't, it just says `Empy reply from server`. — Djent, Aug 31 '18 at 12:37

score 0 · Accepted Answer · answered Sep 03 '18 at 14:31

It actually was the Dockerfile issue. Previously I had uWSGI in my requirements.txt, so it was installed by pip install.
When I've removed it and added uwsgi-python3 to apk add, now everything is fine.

No idea why it matters (everything else was working fine), but it solved my issue.

uwsgi cannot process request longer than one minute

1 Answers1