uwsgi 无法处理超过一分钟的请求
uwsgi cannot process request longer than one minute
我有一个 Django 应用程序,它通过 uwsgi 在 docker 容器中提供服务。我准备了一个自定义视图来重现我提到的问题。它看起来完全像下面:
def get(self, request):
logger = logging.getLogger('ReleaseReport')
logger.critical('Entering and sleeping')
time.sleep(180)
logger.critical('Awaking')
return Response({'response': 'anything'})
它(有意)做的唯一一件事就是记录消息,休眠 3 分钟,然后再记录另一条消息。
以下是我尝试从 Firefox/Chrome/PyCharm 的其余 API 客户端访问视图后日志文件的工作方式:
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)
一分钟后好像又执行了一次视图,又过了一分钟第三次执行了。此外,日志显示它是 HTTP 200,但客户端没有收到数据,只是说它无法在几分钟后加载数据(取决于客户端)。然而,日志中的第一个 HTTP 200 在客户端放弃之前发生得更早。
任何可能导致该问题的线索?这是我的 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
Dockerfile
命令如下:
/usr/local/bin/uwsgi --ini /app/uwsgi.ini
在我的实际应用中,导致客户端认为请求失败,但由于实际执行了并完成 3次,所以数据库中有3条记录。将工作进程数更改为 1 并没有太大变化。它不是等待一分钟再次生成视图,而是在前一个视图完成后生成。
我的配置有什么问题?
编辑:
我稍微改变了我的看法,它现在接受睡眠时间参数,看起来像这样:
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})
现在,冰壶:
> 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
在日志中:
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)
如果我使用相同的命令测试服务器 运行 manage.py runserver
,它每次都会响应 - 无论我睡 2 分钟还是 10 分钟。所以这不是客户端的错。
我已经把切腹改成3600了,没有变化。
EDIT2(我的 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:", ); print "so:" }' \
| 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"]
原来是Dockerfile的问题。之前我的 requirements.txt 中有 uWSGI,所以它是由 pip install
安装的。
当我删除它并将 uwsgi-python3
添加到 apk add
时,现在一切都很好。
不知道它为什么重要(其他一切正常),但它解决了我的问题。
我有一个 Django 应用程序,它通过 uwsgi 在 docker 容器中提供服务。我准备了一个自定义视图来重现我提到的问题。它看起来完全像下面:
def get(self, request):
logger = logging.getLogger('ReleaseReport')
logger.critical('Entering and sleeping')
time.sleep(180)
logger.critical('Awaking')
return Response({'response': 'anything'})
它(有意)做的唯一一件事就是记录消息,休眠 3 分钟,然后再记录另一条消息。
以下是我尝试从 Firefox/Chrome/PyCharm 的其余 API 客户端访问视图后日志文件的工作方式:
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)
一分钟后好像又执行了一次视图,又过了一分钟第三次执行了。此外,日志显示它是 HTTP 200,但客户端没有收到数据,只是说它无法在几分钟后加载数据(取决于客户端)。然而,日志中的第一个 HTTP 200 在客户端放弃之前发生得更早。
任何可能导致该问题的线索?这是我的 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
Dockerfile
命令如下:
/usr/local/bin/uwsgi --ini /app/uwsgi.ini
在我的实际应用中,导致客户端认为请求失败,但由于实际执行了并完成 3次,所以数据库中有3条记录。将工作进程数更改为 1 并没有太大变化。它不是等待一分钟再次生成视图,而是在前一个视图完成后生成。
我的配置有什么问题?
编辑:
我稍微改变了我的看法,它现在接受睡眠时间参数,看起来像这样:
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})
现在,冰壶:
> 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
在日志中:
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)
如果我使用相同的命令测试服务器 运行 manage.py runserver
,它每次都会响应 - 无论我睡 2 分钟还是 10 分钟。所以这不是客户端的错。
我已经把切腹改成3600了,没有变化。
EDIT2(我的 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:", ); print "so:" }' \
| 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"]
原来是Dockerfile的问题。之前我的 requirements.txt 中有 uWSGI,所以它是由 pip install
安装的。
当我删除它并将 uwsgi-python3
添加到 apk add
时,现在一切都很好。
不知道它为什么重要(其他一切正常),但它解决了我的问题。