Unusable `requests` in main and forked processes (`rq` worker script)

This is a follow up from https://github.com/kennethreitz/requests/issues/2399#issuecomment-69675695

As stated there, this is a problem which has to do with `requests` being used in both a main process and forked processes -- the `rq` worker script. If the network goes down even for a short while, `requests` raises few exceptions (ConnectionError) then it becomes unusable and the forked processes get killed instantly if they try to use it (requests.get). The issue is described on the `rq` side as well: https://github.com/nvie/rq/issues/473

Sorry if this not very clear, tired now and I'm struggling with this issue for few weeks already...

I've put up a gist to reproduce it (https://gist.github.com/ducu/ee8c0b1028775df6c72e), but please let me know if I can help. Thanks a lot for your support, cheers


Does requests misbehave if you pull the link down without forking? That is, if you have a single ordinary script, no forking or workers, using requests, does it hang if you run `ifconfig en0 down` in the same way?


Nope, only when forking. 

If you call `count_words_at_url` in a single process for loop it works properly raising exception while the network is down and recovering (performing requests) when gets back up. 

—
Sent from Mailbox

On Tue, Jan 13, 2015 at 8:28 AM, Cory Benfield notifications@github.com
wrote:

> ## Does requests misbehave if you pull the link down without forking? That is, if you have a single ordinary script, no forking or workers, using requests, does it hang if you run `ifconfig en0 down` in the same way?
> 
> Reply to this email directly or view it on GitHub:
> https://github.com/kennethreitz/requests/issues/2406#issuecomment-69705464


Well that's utterly bizarre. What platform are you running on?


I'm using Python 2.7.7 on OS X, will try this on Ubuntu today see if it behaves the same way.

—
Sent from Mailbox

On Tue, Jan 13, 2015 at 8:36 AM, Cory Benfield notifications@github.com
wrote:

> ## Well that's utterly bizarre. What platform are you running on?
> 
> Reply to this email directly or view it on GitHub:
> https://github.com/kennethreitz/requests/issues/2406#issuecomment-69706103


@ducu Thanks for doing that investigation, it'll be helpful (I don't have any machines with Redis installed atm).

While we're waiting on that I can infodump a few things. Firstly, requests has little-to-no global state. We certainly don't persist any of our own objects at the top-level, though I can't guarantee right now that none of the import machinery has anything to do with anything.

Garbage collection _should_ ensure that the socket you created initially is cleaned up because you aren't using a Session object. This is good, as it means that you shouldn't be accidentally re-using an invalid file handle (I think).

Unfortunately, right now I'm all out of ideas, so I'd like to see if we can get a consistent repro on multiple platforms to exclude single-platform weirdness before I dive in further. We may need to get some serious debugging tools onto this task.


@Lukasa Sure, I hope we can get to the bottom of this.

For now I'm running the gist on an AWS instance with ubuntu-trusty-14.04-amd64-server-20140927 (ami-f0b11187) via SSH. This means I cannot disable the network adapter (can't do `sudo ifconfig en0 down`), so I thought to use iptables to block outgoing http traffic (`sudo iptables -A OUTPUT -p tcp --dport 80 -j REJECT`) which is not exactly the same.. 

By doing this I cannot reproduce the issue, `requests` behaves properly -- it raises ConnectionError: ('Connection aborted.', error(111, 'Connection refused')) when traffic is rejected by the firewall, and recovers to running normally when the rule is deleted (`sudo iptables -D OUTPUT -p tcp --dport 80 -j REJECT`).

Python 2.7.6 (default, Mar 22 2014, 22:59:56) [GCC 4.8.2] on linux2

Please let me know if I'm off-track here..
I will try doing the same iptables trick on my Mac tonight and see if there's any difference.


## Can you give us more detail about the ConnectionError you originally described?

Sent from my Android device with K-9 Mail. Please excuse my brevity.


Omw home to get the Mac, be back shortly and give all the details

On Tue, Jan 13, 2015 at 2:20 PM, Ian Cordasco notifications@github.com
wrote:

> Can you give us more detail about the ConnectionError you originally
> 
> ## described?
> 
> Sent from my Android device with K-9 Mail. Please excuse my brevity.
> 
> —
> Reply to this email directly or view it on GitHub
> https://github.com/kennethreitz/requests/issues/2406#issuecomment-69742693
> .


I'm inclined to believe you really do have to bring the adapter down for this to be a problem. The nature of the error will be very different: for example, without an adapter the `bind` call should fail, whereas with the iptables solution it'll just hang without receiving messages.


Yep it seems so, there's a different exception I get when taking the network down:
ConnectionError: ('Connection aborted.', gaierror(8, 'nodename nor servname provided, or not known'))

Unfortunately I don't have a linux box to try this locally by disabling the adapter, but on my Mac it definitely happens. Below you can see the relevant output of the script.

First it calls `print count_words_at_url('http://python-rq.org/')` from within the main process, which causes the problem later. If this [line](https://gist.github.com/ducu/ee8c0b1028775df6c72e#file-_test_rq_requests-py-L23) is commented the issue doesn't appear.

```
Last login: Tue Jan 13 15:10:16 on ttys015
ducusmac:temp Ducu$ . env/bin/activate
(env)ducusmac:temp Ducu$ python -c "from _test_rq_requests import custom_worker; custom_worker()"
489 
```

Worker starts properly..

```
15:13:57 RQ worker started, version 0.4.6
15:13:57 
15:13:57 *** Listening on test...
15:13:57 test: _test_rq_requests.count_words_at_url('http://onion.com/1A1cSXV') (b7400d86-015d-4229-ae32-f9d73c842652)
15:13:58 Job OK, result = 2431
15:13:58 Result is kept for 500 seconds.
15:13:58 
15:13:58 *** Listening on test...
15:13:58 test: _test_rq_requests.count_words_at_url('http://lifehac.kr/zjndlpn') (65c08d69-23de-48b3-b687-9412f05b46a6)
15:14:01 Job OK, result = 3752
15:14:01 Result is kept for 500 seconds.
15:14:01 
15:14:01 *** Listening on test...
15:14:01 test: _test_rq_requests.count_words_at_url('https://medium.com/@micah/conan-what-is-best-in-life-16d832026724') (376d86f7-9b63-41ff-9e0a-1fef2cfaa79b)
15:14:02 Job OK, result = 3036
15:14:02 Result is kept for 500 seconds.
15:14:02 
```

And at this time I'm doing `ifconfig en0 down` in a separate Terminal window taking the network down

```
15:14:02 *** Listening on test...
15:14:02 test: _test_rq_requests.count_words_at_url('http://huff.to/1Bap2xl') (c99c2681-2c2e-4eb3-86e0-271890377c71)
15:14:04 ConnectionError: ('Connection aborted.', gaierror(8, 'nodename nor servname provided, or not known'))
Traceback (most recent call last):
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/rq/worker.py", line 543, in perform_job
    rv = job.perform()
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/rq/job.py", line 482, in perform
    self._result = self.func(*self.args, **self.kwargs)
  File "_test_rq_requests.py", line 18, in count_words_at_url
    resp = requests.get(url, timeout=3)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/api.py", line 65, in get
    return request('get', url, **kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/api.py", line 49, in request
    response = session.request(method=method, url=url, **kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/sessions.py", line 461, in request
    resp = self.send(prep, **send_kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/sessions.py", line 573, in send
    r = adapter.send(request, **kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/adapters.py", line 415, in send
    raise ConnectionError(err, request=request)
ConnectionError: ('Connection aborted.', gaierror(8, 'nodename nor servname provided, or not known'))
Traceback (most recent call last):
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/rq/worker.py", line 543, in perform_job
    rv = job.perform()
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/rq/job.py", line 482, in perform
    self._result = self.func(*self.args, **self.kwargs)
  File "_test_rq_requests.py", line 18, in count_words_at_url
    resp = requests.get(url, timeout=3)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/api.py", line 65, in get
    return request('get', url, **kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/api.py", line 49, in request
    response = session.request(method=method, url=url, **kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/sessions.py", line 461, in request
    resp = self.send(prep, **send_kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/sessions.py", line 573, in send
    r = adapter.send(request, **kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/adapters.py", line 415, in send
    raise ConnectionError(err, request=request)
ConnectionError: ('Connection aborted.', gaierror(8, 'nodename nor servname provided, or not known'))
15:14:04 Moving job to failed queue.
15:14:04 

*[Moving job to failed queue approx. 130 times]*

15:14:13 
15:14:13 *** Listening on test...
15:14:13 test: _test_rq_requests.count_words_at_url('http://bit.ly/13ErUHj') (40f5086d-dbc8-4cdc-bf02-a2ee0531edf0)
15:14:13 ConnectionError: ('Connection aborted.', gaierror(8, 'nodename nor servname provided, or not known'))
Traceback (most recent call last):
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/rq/worker.py", line 543, in perform_job
    rv = job.perform()
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/rq/job.py", line 482, in perform
    self._result = self.func(*self.args, **self.kwargs)
  File "_test_rq_requests.py", line 18, in count_words_at_url
    resp = requests.get(url, timeout=3)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/api.py", line 65, in get
    return request('get', url, **kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/api.py", line 49, in request
    response = session.request(method=method, url=url, **kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/sessions.py", line 461, in request
    resp = self.send(prep, **send_kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/sessions.py", line 573, in send
    r = adapter.send(request, **kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/adapters.py", line 415, in send
    raise ConnectionError(err, request=request)
ConnectionError: ('Connection aborted.', gaierror(8, 'nodename nor servname provided, or not known'))
Traceback (most recent call last):
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/rq/worker.py", line 543, in perform_job
    rv = job.perform()
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/rq/job.py", line 482, in perform
    self._result = self.func(*self.args, **self.kwargs)
  File "_test_rq_requests.py", line 18, in count_words_at_url
    resp = requests.get(url, timeout=3)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/api.py", line 65, in get
    return request('get', url, **kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/api.py", line 49, in request
    response = session.request(method=method, url=url, **kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/sessions.py", line 461, in request
    resp = self.send(prep, **send_kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/sessions.py", line 573, in send
    r = adapter.send(request, **kwargs)
  File "/Users/Ducu/Developer/Svven/tests/temp/env/lib/python2.7/site-packages/requests/adapters.py", line 415, in send
    raise ConnectionError(err, request=request)
ConnectionError: ('Connection aborted.', gaierror(8, 'nodename nor servname provided, or not known'))
15:14:13 Moving job to failed queue.
15:14:13 
```

Then suddenly `requests` becomes unusable, doesn't raise exceptions anymore and kills forked processes thus leaving the jobs in the 'started' status. It's like the worker goes into this "strike mode" and it never recovers not even if the network gets back up.

```
15:14:13 *** Listening on test...
15:14:13 test: _test_rq_requests.count_words_at_url('http://ow.ly/EUAk9') (08cfa2cb-cde3-4567-acfa-86a49eb6dcb9)
15:14:13 
15:14:13 *** Listening on test...
15:14:13 test: _test_rq_requests.count_words_at_url('http://ow.ly/2SEzc6') (e754bb36-c820-4634-b03c-3741521c23af)
15:14:14 
15:14:14 *** Listening on test...
15:14:14 test: _test_rq_requests.count_words_at_url('http://allday.com/g/bomb') (7918ceda-2e33-4c8d-8fa5-d380dd82eb2c)
15:14:14 

*[The same output getting job after job and leaving them unprocessed until worker is shut down]*

15:14:27 *** Listening on test...
15:14:27 test: _test_rq_requests.count_words_at_url('http://www.producthunt.com/posts/nugget') (ca292ec8-e06a-4aa8-872a-458652dfd037)
^C15:14:27 Warm shut down requested.
15:14:28 Stopping on request.
(env)ducusmac:temp Ducu$ 
```

I hope this clarifies a bit the behaviour. I know this is also a `rq` problem but it's the only way I could reproduce the issue. This is my OS X environment 

(env)ducusmac:temp Ducu$ python
Python 2.7.7 (default, Jun  2 2014, 18:55:26) 
[GCC 4.2.1 Compatible Apple LLVM 5.1 (clang-503.0.40)] on darwin

It would be great if any of you guys would try to run the script on a linux machine locally. If you have any other ideas please let me know.


So that error is related to DNS (which is why a simple `iptables` example doesn't work). I'm surprised this continues after the interface comes back up. I would think TTLs would prevent the DNS cache from being poisoned and causing issues, but DNS caching issues seem like the next logical problem. I wonder if the developers of `rq` have any ideas. This is certainly something I've never seen happen with plain `requests`.


@sigmavirus24 I suspected it's because of forking.

As I mentioned previously, having a single process with a simple loop to perform `count_words_at_url` doesn't cause this issue.. as `requests` recovers after the network gets back up.


@sigmavirus24 But even using the `rq`..
It also recovers if `requests.get` is **not** called before forking -- comment that [line](https://gist.github.com/ducu/ee8c0b1028775df6c72e#file-_test_rq_requests-py-L23) and there's no issue.


@ducu Is this a personal mac machine or one running OS X server?


Actually, regardless, I think it's critical to try to find a Linux repro, because I wouldn't be at all surprised to find this is the fault of [discoveryd](http://arstechnica.com/apple/2015/01/why-dns-in-os-x-10-10-is-broken-and-what-you-can-do-to-fix-it/).


I have a personal Mac, not a server. Yeah should find a Linux to test this.. sorry but I don't have it (I'm not much of a Linux connaisseur either). For my use case the workaround would be -- not to use `requests` in the main worker process but only in the forks. This works fine so I can go on..

But please let me know if I can help fixing this in any other way. Cheers

—
Sent from Mailbox


Ok guys, I managed to test this on Ubuntu via VirtualBox and no issue there..

The exception being raised when disabling the network is

> ConnectionError: ('Connection aborted.', gaierror(-2, 'Name or service not known'))

different than what I get on the Mac

> ConnectionError: ('Connection aborted.', gaierror(8, 'nodename nor servname provided, or not known'))

The script goes on properly after the network gets back up, so `requests` is getting responses. I guess I can close this ticket, may be what @Lukasa is suggesting, something to do with the OS X DNS service.

Thanks a lot for your support, cheers


@ducu No problem! I hope this does get resolved, though it looks like discoveryd is ruining a lot of people's days at the minute.


I'm experiencing the same behavior on a worker within a Docker running Ubuntu. I'm considering using urllib2 instead of requests. Did anybody try that as a work-around?


@erdillon What specific behaviour is that? There is a quite lengthy debugging discussion in this issue: how much of that have you seen?


@Lukasa I'm currently chasing rq forked child processes that die on my without notice on a larger POST request. No exception, nothing to be found. I've tracked it down to the actual POST. 


So that makes this somewhat unlike the original issue, which did see exceptions from requests. Are you interested in trying to dive in and see if we can work out what is going wrong?


I came to this thru nvie/rq#473. I just re-read this thread and you are right. I'm not seeing ANY exception. The worker goes away with no warning. 


So this is at least somewhat different. What you need to do, I think, is to investigate what's happening when the worker dies. You may need to attach something like strace to the worker to get that insight.


@erdillon I believe I'm seeing the same sort of problem -- did you ever figure it out?


@jjwon0 I did not figure it out. But in the meantime i've seen similar behavior go away after upgrading to the latest versions on the requests package. Are you up2date on all the libs?


just reposting an issue I've been having related to this:

Hey guys, @selwin @ducu  @Lukasa @erdillon 

I've got an issue related to this (i think). But it's actually really easy to replicate. When making a request from a worker fails, the worker just dies, but no errors are reported nor is the job sent to the failed queue. 

my example:

```
def make_request():
    print "making response"
    response = requests.get("https://some.madeup.url")
    print "got response"

if __name__ == "__main__":
    make_request()
```

When I queue `make_request` the process just quits when making the request. Whereas a traceback is thrown when I execute the script directs. Took me a while to track this down, is there a fix or something I may be doing wrong?


Forgot to comment with the solution we came up with, hope it's helpful to someone.

Our problem was that we had a retry manager which would try making requests a few times on an `IOLoop`.  It was failing because RQ was just aggressively killing the process once something was queued on the `IOLoop` because nothing was running.

Our solution was for the function sent to RQ to generate a `Future` from the retry manager which only resolved when it was done, and waiting on this future before returning.


@dflatow See @jjwon0. However, the fact that it was causing a traceback in the main thread suggests the issue is with RQ, not requests. 


@erdillon see nvie/rq#702 and nvie/rq#710 for the issue of rq not properly handling the killing of the python process of  a worker.