为什么我的程序在urllib3日志启动新的HTTPS连接后挂起？

2022-02-27 00:00:00 python django python-requests celery urllib3

问题描述

我正在尝试诊断一个问题，其中我的一些芹菜工作进程似乎挂起了几分钟。我有许多任务需要进行几个IO调用(通常是对第三方API)。在任何给定的工作中，我可能会向各种API发出数千个请求。我看过这些日志，它们没有什么共同之处：它们在urllib3连接到远程url后挂起。

在我的作业结束时(大约需要30分钟)，通常有几个任务处于挂起状态。

以下是我用来得出urllib3是罪魁祸首的日志示例：

Jul 08 04:46:26 app/worker.1:  [INFO/MainProcess] [???(???)] celery.worker.strategy: Received task: my_celery_task[734a49f6-bf6b-4423-9146-1c48366ba897] 
Jul 08 04:46:28 app/worker.1:  [DEBUG/Worker-11] [my_celery_task(734a49f6-bf6b-4423-9146-1c48366ba897)] src.aggregates.prospect.services.prospect_service: Beginning: Get social account data. provider_name: twitter, account_uid: some_user 
Jul 08 04:46:28 app/worker.1:  [INFO/Worker-11] [my_celery_task(734a49f6-bf6b-4423-9146-1c48366ba897)] requests.packages.urllib3.connectionpool: Starting new HTTPS connection (1): api.some_api.com

然后就这样了。Starting new HTTPS connection语句之后没有记录任何内容。

这是我重新启动Worker的位置：

Jul 08 05:09:18 app/worker.1:  [INFO/MainProcess] [???(???)] celery.worker.strategy: Received task: my_celery_task[734a49f6-bf6b-4423-9146-1c48366ba897] 
Jul 08 05:09:19 app/worker.1:  [DEBUG/Worker-4] [my_celery_task(734a49f6-bf6b-4423-9146-1c48366ba897)] src.aggregates.prospect.services.prospect_service: Beginning: Get social account data. provider_name: twitter, account_uid: some_user 
Jul 08 05:09:19 app/worker.1:  [DEBUG/Worker-4] [my_celery_task(734a49f6-bf6b-4423-9146-1c48366ba897)] requests.packages.urllib3.connectionpool: "GET /v2/api_call.json?username=some_user HTTP/1.1" 403 170
Jul 08 05:09:19 app/worker.1:  [INFO/Worker-4] [my_celery_task(734a49f6-bf6b-4423-9146-1c48366ba897)] requests.packages.urllib3.connectionpool: Starting new HTTPS connection (1): api.some_api.com 
Jul 08 05:09:19 app/worker.1:  [INFO/MainProcess] [???(???)] celery.worker.job: Task my_celery_task[734a49f6-bf6b-4423-9146-1c48366ba897] succeeded in 2.265356543008238s: 32345

在这种情况下，我收到403状态代码。所以这可能是潜在的罪魁祸首。但是，我在日志中看到，状态代码200也发生了这种情况。

顺便说一下，我也经常在日志中看到Resetting dropped connection: api.twitter.com。

我已确保在使用requests库发出请求的任何地方提供timeout10秒。

所以看起来请求已经发出，但随后就挂起了。远程服务器可能以非常慢的速度响应，因此实际上从未发生过超时，但我发现这不太可能，因为我的问题不只发生在一个特定的域中。

我用的是兔子3.1.3芹菜：3.1.11(Cipater)昆布：3.0.16 Py：3.4.0台球：3.3.0.17 Py-AMQP：1.4.5。我正在使用预叉。

我使用的是Requests==2.3.0。

那么为什么urllib3记录Starting new HTTPS connection语句后我的任务似乎挂起？

编辑：我添加了大量日志记录，并在下面提供了进一步的上下文

2014-07-16T02:43:53.140381+00:00 app[worker.1]: [INFO/MainProcess/2] [???(???)] celery.worker.strategy: Received task: [973c1361-43c3-41a2-9bcd-6ef850c41fcc]
2014-07-16T02:43:56.951211+00:00 app[worker.1]: [1;34m[DEBUG/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] : twitter, account_uid: some_user[0m
2014-07-16T02:43:56.951876+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.sessions: complete: request: about to get request
2014-07-16T02:43:56.952005+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.sessions: begin: request: about to prep request
2014-07-16T02:43:56.952897+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.sessions: complete: request: about to prep request
2014-07-16T02:43:56.954133+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.adapters: begin: send: about to get response not chunked
2014-07-16T02:43:56.954249+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: begin: urlopen: about to get a conn from the pool
2014-07-16T02:43:56.954360+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: begin: _get_conn: about to get a conn from the pool
2014-07-16T02:43:56.954482+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: complete: _get_conn: about to get a conn from the pool
2014-07-16T02:43:56.954587+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: begin: returning conn or self new conn
2014-07-16T02:43:56.951725+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.sessions: begin: request: about to get request
2014-07-16T02:43:56.954692+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: Starting new HTTPS connection (1): api.fullcontact.com
2014-07-16T02:43:56.954817+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: begin: create connection class
2014-07-16T02:43:56.954948+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: complete: just about to create connection class
2014-07-16T02:43:56.955062+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: complete: returning conn or self new conn
2014-07-16T02:43:56.955166+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: complete: urlopen: about to get a conn from the pool
2014-07-16T02:43:56.955290+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: begin: _make_request: about to call request
2014-07-16T02:43:56.955396+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: httpconection: send req
2014-07-16T02:43:56.953410+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.sessions: begin: request: about to send
2014-07-16T02:43:56.953554+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.adapters: begin: send: about to get conn
2014-07-16T02:43:56.953986+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.adapters: complete: send: about to get conn
2014-07-16T02:43:56.956014+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: httpconection: _send_output
2014-07-16T02:43:56.955517+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: httpconection: put req
2014-07-16T02:43:56.955715+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: completed: httpconection: put req
2014-07-16T02:43:56.956146+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: httpconection: send
2014-07-16T02:43:56.956309+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: https verified conection: connect
2014-07-16T02:43:56.959157+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: completed: https verified : connect: set socket
2014-07-16T02:43:56.959045+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: https verified : connect: set socket
2014-07-16T02:43:56.959295+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: https verified : connect: resolve cert reqs
2014-07-16T02:43:56.959402+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: completed: https verified : connect: resolve cert reqs
2014-07-16T02:43:56.959508+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: https verified : connect: resolve ssl ver
2014-07-16T02:43:56.959613+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: complete: https verified : connect: resolve ssl ver
2014-07-16T02:43:56.959715+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: https verified : connect: ssl_wrap_socket
2014-07-16T02:43:56.959827+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.util.ssl_: begin: ssl_wrap_socket: about to get ssl context
2014-07-16T02:43:56.960012+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.util.ssl_: complete: ssl_wrap_socket: about to get ssl context
2014-07-16T02:43:56.960119+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.util.ssl_: begin: ssl_wrap_socket: load verify locations


# *******************************************
# *******************************************
# This is when I restarted the job. It processed the same exact task, same parameters, same https url, etc in under 1 second.
# *******************************************
# *******************************************



2014-07-16T03:00:21.885531+00:00 app[worker.1]: [INFO/MainProcess/2] [???(???)] celery.worker.strategy: Received task: [973c1361-43c3-41a2-9bcd-6ef850c41fcc]
2014-07-16T03:00:22.009616+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.sessions: begin: request: about to get request
2014-07-16T03:00:22.010313+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.sessions: begin: request: about to prep request
2014-07-16T03:00:22.016669+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.sessions: begin: request: about to send
2014-07-16T03:00:22.018419+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.adapters: complete: send: about to get conn
2014-07-16T03:00:22.051267+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: completed: httpconection: put req
2014-07-16T03:00:22.051744+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: httpconection: send
2014-07-16T03:00:22.051879+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: https verified conection: connect
2014-07-16T03:00:22.072346+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: https verified : connect: set socket
2014-07-16T03:00:22.103234+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.util.ssl_: begin: ssl_wrap_socket: wrap socket with host name
2014-07-16T03:00:22.007638+00:00 app[worker.1]: [1;34m[DEBUG/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] : : twitter, account_uid: some_user[0m
2014-07-16T03:00:22.009969+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.sessions: complete: request: about to get request
2014-07-16T03:00:22.012954+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.sessions: complete: request: about to prep request
2014-07-16T03:00:22.017254+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.adapters: begin: send: about to get conn
2014-07-16T03:00:22.049101+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.adapters: begin: send: about to get response not chunked
2014-07-16T03:00:22.049241+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: begin: urlopen: about to get a conn from the pool
2014-07-16T03:00:22.049361+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: begin: _get_conn: about to get a conn from the pool
2014-07-16T03:00:22.049528+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: complete: _get_conn: about to get a conn from the pool
2014-07-16T03:00:22.049639+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: begin: returning conn or self new conn
2014-07-16T03:00:22.049756+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: Starting new HTTPS connection (1): api.fullcontact.com
2014-07-16T03:00:22.049918+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: begin: create connection class
2014-07-16T03:00:22.050197+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: complete: just about to create connection class
2014-07-16T03:00:22.050318+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: complete: returning conn or self new conn
2014-07-16T03:00:22.050425+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: complete: urlopen: about to get a conn from the pool
2014-07-16T03:00:22.050587+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: begin: _make_request: about to call request
2014-07-16T03:00:22.050777+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: httpconection: send req
2014-07-16T03:00:22.050946+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: httpconection: put req
2014-07-16T03:00:22.051546+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: httpconection: _send_output
2014-07-16T03:00:22.072581+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: completed: https verified : connect: set socket
2014-07-16T03:00:22.072721+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: https verified : connect: resolve cert reqs
2014-07-16T03:00:22.072911+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: completed: https verified : connect: resolve cert reqs
2014-07-16T03:00:22.073044+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: https verified : connect: resolve ssl ver
2014-07-16T03:00:22.073179+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: complete: https verified : connect: resolve ssl ver
2014-07-16T03:00:22.073311+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: https verified : connect: ssl_wrap_socket
2014-07-16T03:00:22.073445+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.util.ssl_: begin: ssl_wrap_socket: about to get ssl context
2014-07-16T03:00:22.073814+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.util.ssl_: complete: ssl_wrap_socket: about to get ssl context
2014-07-16T03:00:22.073979+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.util.ssl_: begin: ssl_wrap_socket: load verify locations
2014-07-16T03:00:22.092134+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.util.ssl_: complete: ssl_wrap_socket: load verify locations
2014-07-16T03:00:22.138197+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.util.ssl_: complete: ssl_wrap_socket: wrap socket with host name
2014-07-16T03:00:22.138207+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: complete: https verified : connect: ssl_wrap_socket
2014-07-16T03:00:22.138209+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: https verified : connect: match hostname
2014-07-16T03:00:22.138211+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: complete: https verified : connect: match host name
2014-07-16T03:00:22.138212+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: completed: https verified conection: connect
2014-07-16T03:00:22.138214+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: begin: httpconection: send: before sock.sendall
2014-07-16T03:00:22.138743+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: completed: httpconection: send: before sock.sendall
2014-07-16T03:00:22.138748+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: completed: httpconection: send
2014-07-16T03:00:22.138796+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: completed: httpconection: _send_output
2014-07-16T03:00:22.139094+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connection: completed: httpconection: send req
2014-07-16T03:00:22.139207+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: complete: _make_request: about to call request
2014-07-16T03:00:22.139321+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: begin: _make_request: conn.get reponse with buffer
2014-07-16T03:00:22.139925+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: begin: _make_request: conn.get reponse with no buffer
2014-07-16T03:00:22.288112+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.sessions: completest: about to send
2014-07-16T03:00:22.286453+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: complete: _make_request: conn.get reponse with no buffer
2014-07-16T03:00:22.286596+00:00 app[worker.1]: [1;34m[DEBUG/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: "GET /v2/person.json?twitter=some_user&apiKey=5eeaece3982efd1d&style=dictionary HTTP/1.1" 403 170[0m
2014-07-16T03:00:22.286720+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: begin: urlopen: about to get response from httplib
2014-07-16T03:00:22.287050+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.connectionpool: complete: urlopen: about to get response from httplib
2014-07-16T03:00:22.287170+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.adapters: complete: send: about to get response not chunked
2014-07-16T03:00:22.287279+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.adapters: begin: send: about to build response
2014-07-16T03:00:22.287738+00:00 app[worker.1]: [INFO/Worker-9/23] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.adapters: complete: send: about to build response
2014-07-16T03:00:24.342182+00:00 app[worker.1]: [INFO/MainProcess/2] [???(???)] celery.worker.job: Task [973c1361-43c3-41a2-9bcd-6ef850c41fcc] succeeded in 2.4521394340554252s: 44508

最后记录的条目是

2014-07-16T02:43:56.960119+00:00 app[worker.1]: [INFO/Worker-28/99] [(973c1361-43c3-41a2-9bcd-6ef850c41fcc)] requests.packages.urllib3.util.ssl_: begin: ssl_wrap_socket: load verify locations

根据我的日志语句，the culprit is load_verify_locations。

这是requests库中对应的代码：

if ca_certs:
    try:
        context.load_verify_locations(ca_certs)
    # Py32 raises IOError
    # Py33 raises FileNotFoundError
    except Exception as e:  # Reraise as SSLError
        raise SSLError(e)

因此，似乎是context.load_verify_locations(ca_certs)导致此操作挂起。为什么？

解决方案

您是否在使用multiprocessing.dummy模块？即线程池？

multiprocessing.dummy或urllib3的Pool模块中似乎存在错误，这似乎会导致随机HTTP连接在建立后(即TCP SYN-ACK周期完成后)挂起。

当您使用Wireshark跟踪TCP请求/响应时，您会看到一个成功的TCP连接正在建立，然后在几分钟后出现TCP RST，并且在这两个连接之间没有应用程序协议通信，这就是发生此错误的迹象。

您可能希望尝试将多处理池代码切换为基于进程，即使用多处理而不是多处理.dummy。

即代替

from multiprocessing.dummy import Pool as ThreadPool

使用

from multiprocessing import Pool as ProcessPool

以上对我有效，错误消失了。

相关文章