socket leak (suspected due to redirection)

It seems requests forgets to properly close a socket when a redirection occurs.
See the following gist for the code that causes the issue (at least here..): 
https://gist.github.com/3313868


Have you tried the latest release? v0.13.6 fixed a bunch of socket leaking


`Session.close()` was added in the new release, so it's possible that there's a problem.

However I forked the gist to do a `lsof` automatically, as in bluehorn's test, and didn't see any problem under the master or develop branches: [https://gist.github.com/3318253]


This is how it looks here, unfortunately :(

$ cat 3318253/gistfile1.txt
import requests
import os
import subprocess
pid = os.getpid()
reqsess = requests.session()
try:
        r = reqsess.get(r'http://www.mouser.com/Search/Refine.aspx?Keyword=test')
        d = r.text
finally:
        reqsess.close()

print 'done, calling lsof'
subprocess.call("lsof -p%d -a -iTCP" % (pid,), shell=True)
print 'done'
$ git clone https://github.com/kennethreitz/requests.git
Cloning into 'requests'...
remote: Counting objects: 8196, done.
remote: Compressing objects: 100% (2795/2795), done.
remote: Total 8196 (delta 5593), reused 7911 (delta 5344)
Receiving objects: 100% (8196/8196), 1.53 MiB | 570 KiB/s, done.
Resolving deltas: 100% (5593/5593), done.
$ PYTHONPATH=requests python ./3318253/gistfile1.txt
done, calling lsof
COMMAND  PID USER   FD   TYPE  DEVICE SIZE/OFF NODE NAME
python  1686 eran    3u  IPv4 1394237      0t0  TCP 192.168.0.107:38028->a92-122-135-23.deploy.akamaitechnologies.com:http (CLOSE_WAIT)
done
$


If you are interested, I will gladly provide access to this machine for experimenting.
Also, if you want me to add some logging in any specific places, let me know.

Thanks!


Using @slingamn's Gist, I can also reproduce the bug.

Using Python with the following build info:

```
Python 2.7.1 (r271:86832, Jun 16 2011, 16:59:05) 
[GCC 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2335.15.00)] on darwin
```

And using the `develop` branch of Requests @ 27b55a7, I get the output:

```
done, calling lsof
COMMAND   PID   USER   FD   TYPE             DEVICE SIZE/OFF NODE NAME
python  12214 lukasa   3u   IPv4 0xffffff8012a634e0      0t0  TCP 192.168.1.4:61042->2.16.231.23:http (CLOSE_WAIT)
done
```


That's really weird; I can't reproduce this under Python 2.6.7 or 2.7.3.

Anyone know if that open socket is to the first server (the one that sent the redirect) or the last server?


debian stable, python v 2.6.6 it works with no leaking. 
On commit 27b55a74d7b9bd2f8c60fd0ee342bcbbf40e0a66
branch develop

According to wireshark:

<pre>
GET /Search/Refine.aspx?Keyword=test HTTP/1.1
Host: www.mouser.com
Accept-Encoding: identity, deflate, compress, gzip
Accept: */*
User-Agent: python-requests/0.13.6 CPython/2.6.6 Linux/2.6.32-5-amd64

HTTP/1.1 302 Moved Temporarily
Content-Type: text/html; charset=utf-8
Location: http://de.mouser.com/Search/Refine.aspx?Keyword=test
X-AspNet-Version: 4.0.30319
X-Powered-By: ASP.NET
Date: Tue, 14 Aug 2012 07:32:08 GMT
Connection: close
Vary: Accept-Encoding
Set-Cookie: ASP.NET_SessionId=12vbkqzdf4o4y502nbwd14vf; domain=.mouser.com; path=/; HttpOnly
Set-Cookie: CARTCOOKIEUUID=84b5edd5-864f-4f48-aea5-e267cd86c0df; domain=.mouser.com; expires=Wed, 14-Aug-2013 07:28:31 GMT; path=/
Set-Cookie: preferences=; domain=.mouser.com; path=/
Set-Cookie: TS604485=55d4f36503ed1bff5312fc5334dfee9022925ff451cc8b8c5029fef836af3f5ef6da005fbefdd30bfdbd1f58fdf092e3ffffffff; Path=/
Cache-Control: private

<html><head><title>Object moved</title></head><body>
<h2>Object moved to <a href="http://de.mouser.com/Search/Refine.aspx?Keyword=test">here</a>.</h2>
</body></html>

</pre>


Then the redirect is followed :

<pre>
GET /Search/Refine.aspx?Keyword=test HTTP/1.1
Host: de.mouser.com
Cookie: CARTCOOKIEUUID=84b5edd5-864f-4f48-aea5-e267cd86c0df; ASP.NET_SessionId=12vbkqzdf4o4y502nbwd14vf; preferences=
Accept-Encoding: identity, deflate, compress, gzip
Accept: */*
User-Agent: python-requests/0.13.6 CPython/2.6.6 Linux/2.6.32-5-amd64

HTTP/1.1 200 OK
Content-Type: text/html; charset=utf-8
X-AspNet-Version: 4.0.30319
X-Powered-By: ASP.NET
Vary: Accept-Encoding
Content-Encoding: gzip
Date: Tue, 14 Aug 2012 07:32:10 GMT
Transfer-Encoding:  chunked
Connection: keep-alive
Connection: Transfer-Encoding
Set-Cookie: preferences=ps=de&pl=de-DE&pc_de=EUR; domain=.mouser.com; path=/
Set-Cookie: TS604485=c6aab6eabd6798c9eb3a18f9f40a1e622b6b6b5dc26917a75029fef9fdf092e3cb3bd022; Path=/
Cache-Control: private
</pre>

... data follows


Ugh. I was wondering if this was an OS X versus Linux issue, so I tested it on my Ubuntu 12.04 LTS box.

Python build info:

```
Python 2.7.3 (default, Aug  1 2012, 05:14:39) 
[GCC 4.6.3] on linux2
```

Using commit [`27b55a7`](https://github.com/kennethreitz/requests/commit/27b55a74d7b9bd2f8c60fd0ee342bcbbf40e0a66) build of Requests, I get:

```
done, calling lsof
lsof: WARNING: can't stat() fuse.gvfs-fuse-daemon file system /var/lib/lightdm/.gvfs
      Output information may be incomplete.
COMMAND  PID   USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
python  6820 lukasa    3u  IPv4  17429      0t0  TCP Sweden.local:40976->a23-33-215-23.deploy.akamaitechnologies.com:http (CLOSE_WAIT)
done
```

Still leaking.


Oh, heh, the reason it doesn't reproduce for me is because that page returns me a 200 OK and sends back a body. It probably depends on your IP address.

`http://www.gogle.com` sends me a 301 to `http://www.google.com/`, but when I use that URL in the test, I still can't reproduce the bug. Can anyone reproduce the bug with this URL?


It must, because from the UK I get a 302 and a redirect to `gb.mouser.com`.

If I try `http://www.gogle.com` I get a 301 to `http://www.google.com/` followed by a 302 to `http://www.google.co.uk`. The test script **does not indicate a leak**.


Maybe someone who can reproduce this could try running the script under `strace -e network,file -s 4096`?


strace output where the issue reproduces: https://gist.github.com/3368251


Heh, apparently strace doesn't consider `close(2)` "file-related" (or network-related). That's silly.

My fork has a branch `leak_patch` [https://github.com/slingamn/requests/tree/leak_patch] which adds some debugging prints for the connection cleanup code. Could you try it and post the output?


Here is is:

> adding new connection for www.mouser.com
> returning to pool: www.mouser.com adding new connection for il.mouser.com
> returning to pool: il.mouser.com 4
> closing requests.sessions.Session
> Pool is empty: www.mouser.com
> Closing FD il.mouser.com 4
> Pool is empty: il.mouser.com
> done, calling lsof
> COMMAND   PID USER   FD   TYPE  DEVICE SIZE/OFF NODE NAME
> python  20466 eran    3u  IPv4 2341665      0t0  TCP 192.168.0.107:35936->a92-122-135-> 23.deploy.akamaitechnologies.com:http (CLOSE_WAIT)
> done


Is this a leak from Requests or Urllib3?


I'm afraid I have no idea. Could you advise on how to inspect this?
Thanks
On Aug 25, 2012 5:52 PM, "Kenneth Reitz" notifications@github.com wrote:

> Is this a leak from Requests or Urllib3?
> 
> —
> Reply to this email directly or view it on GitHubhttps://github.com/kennethreitz/requests/issues/771#issuecomment-8023994.


Unfortunately this is quite challenging to debug, because the relevant code extends across Requests, urllib3, and the standard-library `httplib`. Also, it's hard to reproduce :-/

I think some hints about how to inspect the problem are in the debugging patch mentioned above. Basically, try and identify every time a socket is created, and figure out who is creating it and storing it, and output its `fileno` whenever possible, and then try and correlate that with output from `lsof` and/or `strace` describing the actions taken by the program on its file descriptors. An interactive debugger (pdb, ipdb, pudb) might help.

@keves this is hard, but we'd be really appreciative if you could investigate the issue :-)

One thing I thought was interesting from the debugging output was:

```
returning to pool: www.mouser.com adding new connection for il.mouser.com
```

Seemed like there should have been a newline in between the "returning" and "adding" messages. I think I saw a similar missing newline when I was playing with google.com's redirection, but I didn't have a corresponding leak.


I would be glad to investigate the issue on my own, however it will take me
some time to get into that as I'm pretty overwhelmed with work at the
moment and as you say, this isn't the simplest of bugs :/

What I can do, in the meantime, is offer ssh access to a Linux VM where
this constantly reproduces. If anyone feels like playing with this, let me
know and I will set it up. If not, I'm hoping to have some time to look
into it myself in the near future. Tracking the socket from its creation
sounds like a good idea, and maybe I could monkey-patch the socket module
to print a stack-trace when a new socket is created and then match it
against the lsof output and find out the offender.

On Fri, Sep 7, 2012 at 7:03 AM, Shivaram Lingamneni <
notifications@github.com> wrote:

> Unfortunately this is quite challenging to debug, because the relevant
> code extends across Requests, urllib3, and the standard-library httplib.
> Also, it's hard to reproduce :-/
> 
> I think some hints about how to inspect the problem are in the debugging
> patch mentioned above. Basically, try and identify every time a socket is
> created, and figure out who is creating it and storing it, and output its
> fileno whenever possible, and then try and correlate that with output
> from lsof and/or strace describing the actions taken by the program on
> its file descriptors. An interactive debugger (pdb, ipdb, pudb) might help.
> 
> @keves https://github.com/keves this is hard, but we'd be really
> appreciative if you could investigate the issue :-)
> 
> One thing I thought was interesting from the debugging output was:
> 
> returning to pool: www.mouser.com adding new connection for il.mouser.com
> 
> Seemed like there should have been a newline in between the "returning"
> and "adding" messages. I think I saw a similar missing newline when I was
> playing with google.com's redirection, but I didn't have a corresponding
> leak.
> 
> —
> Reply to this email directly or view it on GitHubhttps://github.com/kennethreitz/requests/issues/771#issuecomment-8355455.


Well, this turns out to be very ugly. I also patch the close() method on the socket object, and I see it gets called twice - for both file descriptors.

Here is the code I used and its output: https://gist.github.com/3665659

```

--> new sock 3

--> close sock 3
RELEASE: False
teh release!!!
--> new sock 4

RELEASE: False
--> close sock 4
done, calling lsof
COMMAND   PID USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
python  11087 eran    3u  IPv4  33696      0t0  TCP 192.168.0.105:44490->a88-221-75-23.deploy.akamaitechnologies.com:http (CLOSE_WAIT)
done
```


Oh, excellent --- patching `socket` was a great idea.

You can use `import traceback; traceback.print_stack()` to find the exact places in requests/urllib3/httplib where the sockets are being created and closed.


Ah, I see you already tried that.

Well, this is suspicious; the output claims that we closed file descriptor 3, but it ends up in the lsof output anyway. Maybe a different FD was opened after the close and given the number 3?

Another thing you can play with is `os.close()`, which lets you close arbitrary FDs by number --- if you put an `os.close(3)` before the lsof, do you still see CLOSE_WAIT?


Some updates:
1) Calling os.close() explicitly before calling lsof fixes the issue (as expected)
2) The following shows a snippet of strace running the test Python script in the gist https://gist.github.com/3665659:

```

socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 2), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ffe16e66000
write(1, "--> new sock 3\n", 15)        = 15
write(1, "\n", 1)                       = 1
fcntl(3, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(3, F_SETFL, O_RDWR)               = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("88.221.75.23")}, 16) = 0
sendto(3, "GET /Search/Refine.aspx?Keyword="..., 209, 0, NULL, 0) = 209
fcntl(3, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(3, F_SETFL, O_RDWR)               = 0
recvfrom(3, "HTTP/1.1 302 Moved Temporarily\r\n"..., 8192, 0, NULL, NULL) = 877
write(1, "--> before close sock 3\n", 24) = 24
write(1, "--> after close sock\n", 21)  = 21
```

Look closely at the gist script and at the 2 write(1,...) lines at the bottom. The close() syscall should have appeared there!
Looking further down the strace:

```
write(1, "--> before close sock 4\n", 24) = 24
close(4)                                = 0
write(1, "--> after close sock\n", 21)  = 21
```

The first socket doesn't get closed, the second one does. Whats wrong with socket's close() method?

3) The combination of the 2 discoveries above made me think that maybe _sock.close()_ isn't calling _os.close()_, but as further investigation revealed, the actual socket is implemented in C and is closed from there by means of reference counting. The socket is closed when the object is finalized.

I then used objgraph to print the backrefs to the actual _sock object (the C object inside the Pythonic wrapper in _socket.py_ from stdlib) and noticed the difference between the socket that gets properly closed and the one that is left open: The broken one has an _httplib.HTTPResponse_ instance which references it through its _fp_ member.

Digging deeper, I eventually found out that _r.history_ (_r_ is the request returned from _reqsess.get()_ in the test script) references the 302 redirection request. If I clear _r.history_, the garbage socket gets disposed...
I think now would be a good time for people familiar with requests code to jump in...

**TL;DR**: r.history keeps a reference to the redirection response, which in turn keeps a reference to the httplib.HTTPResponse, which in turn keeps a reference to the socket - and this is why we're seeing the 'junk' socket. Perhaps someone familiar enough with requests/urllib internals could hint at this?


This is extremely helpful, thanks so much!

It looks like `socket.close()` is not guaranteed to close the socket, but `socket.shutdown()` can help with that: [http://docs.python.org/library/socket.html#socket.socket.close] But I'm not clear on the mechanics of why this happens.

In general we are hoping not to rely on the semantics of the garbage collector for socket disposal, since we are also targeting pypy, which doesn't use reference counting and thus has less predictable/eager garbage collection behavior. So ideally the fix would be something other than trying to zero out the refcount of the socket object. However, as per this comment in `socket.py`:

```
# Wrapper around platform socket objects. This implements
# a platform-independent dup() functionality. The
# implementation currently relies on reference counting
# to close the underlying socket object.
```

there may be no other way. This patch should drop the reference to the socket from the history list; could you see if it fixes the problem for you? [https://gist.github.com/5ae6b972b067d7b81e96]

I'd like to think more about this, in particular to understand why the cpython socket module does things this way, and to figure out what the best practices are for writing socket code for both cpython and pypy.

P.S. Taking the cpython docs at their word, here's a patch that calls shutdown on the sockets prior to disposal, but it probably doesn't help: [https://gist.github.com/32f5030728b9d241d128]


@slingamn my first instinct about the docs telling you to use shutdown first is that it changes the behavior of the socket just like shutdown would do with [C sockets](http://beej.us/guide/bgnet/output/html/singlepage/bgnet.html#closedown). I would agree with you that the shutdown call will not likely help, but it is worth trying.


Hello.

The suggested patch (setting raw to None) fixes the issue. The shutdown patch doesn't, as expected.


I was looking into why I couldn't reproduce the bug locally, and it looks like we are supposed to be handling this already. Basically, the reference chain `r.history[0].raw._fp.fp` is supposed to be broken at the last `.`, by `_fp` (an `httplib.HTTPResponse`) having `.close()` called on it when the content is consumed. This is supposed to set `_fp.fp` to `None`.

See this traceback:

```
  File "./buggist.py", line 25, in <module>
    r = reqsess.get(r'http://www.google.in/')
  File "/home/shivaram/workspace/requests/requests/sessions.py", line 265, in get
    return self.request('get', url, **kwargs)
  File "/home/shivaram/workspace/requests/requests/sessions.py", line 252, in request
    r.send(prefetch=prefetch)
  File "/home/shivaram/workspace/requests/requests/models.py", line 640, in send
    self._build_response(r)
  File "/home/shivaram/workspace/requests/requests/models.py", line 233, in _build_response
    r.content  # Consume socket so it can be released
  File "/home/shivaram/workspace/requests/requests/models.py", line 793, in content
    self._content = bytes().join(self.iter_content(CONTENT_CHUNK_SIZE)) or bytes()
  File "/home/shivaram/workspace/requests/requests/models.py", line 739, in generate
    chunk = self.raw.read(chunk_size)
  File "/home/shivaram/workspace/requests/requests/packages/urllib3/response.py", line 165, in read
    return self._fp.read(amt)
  File "/usr/lib64/python2.7/httplib.py", line 565, in read
    self.close()
```

which I obtained using a monkeypatching technique similar to yours: [https://gist.github.com/955bfeaded8099b1a99f]. The crucial step is that `_build_response` calls `r.content`, which reads the entire response, triggering a call to `close()`. (In my gist I had to copy and paste the original code of `HTTPResponse.close` into my instrumented subclass --- it's an old-style class and I was having some headaches getting the superclass call to work.)

Do you have any idea why this isn't happening correctly on your system?


Hi,

I didn't have time to look into yet, so currently I have no idea.
I added a printing of self.fp in the print "close intercepted!!!!!" line.
Here is the output:

close intercepted!!!!! <socket._fileobject object at 0x1f35550>
  File "t2.py", line 23, in <module>
    r = reqsess.get(r'http://www.mouser.com/Search/Refine.aspx?Keyword=test
')
  File "/home/eran/tmp/xxx/requests/requests/sessions.py", line 256, in get
    return self.request('get', url, **kwargs)
  File "/home/eran/tmp/xxx/requests/requests/sessions.py", line 243, in
request
    r.send(prefetch=prefetch)
  File "/home/eran/tmp/xxx/requests/requests/models.py", line 640, in send
    self._build_response(r)
  File "/home/eran/tmp/xxx/requests/requests/models.py", line 310, in
_build_response
    request.send()
  File "/home/eran/tmp/xxx/requests/requests/models.py", line 654, in send
    self.response.content
  File "/home/eran/tmp/xxx/requests/requests/models.py", line 794, in
content
    self._content = bytes().join(self.iter_content(CONTENT_CHUNK_SIZE)) or
bytes()
  File "/home/eran/tmp/xxx/requests/requests/utils.py", line 412, in
stream_decompress
    for chunk in iterator:
  File "/home/eran/tmp/xxx/requests/requests/models.py", line 740, in
generate
    chunk = self.raw.read(chunk_size)
  File "/home/eran/tmp/xxx/requests/requests/packages/urllib3/response.py",
line 146, in read
    return self._fp.read(amt)
  File "/usr/lib/python2.7/httplib.py", line 541, in read
    return self._read_chunked(amt)
  File "/usr/lib/python2.7/httplib.py", line 622, in _read_chunked
    self.close()
  File "t2.py", line 7, in close
    traceback.print_stack()
close intercepted!!!!! None
  File "t2.py", line 27, in <module>
    reqsess.close()
  File "/home/eran/tmp/xxx/requests/requests/sessions.py", line 119, in
close
    self.poolmanager.clear()
  File
"/home/eran/tmp/xxx/requests/requests/packages/urllib3/poolmanager.py",
line 63, in clear
    self.pools.clear()
  File
"/home/eran/tmp/xxx/requests/requests/packages/urllib3/_collections.py",
line 90, in clear
    self.dispose_func(value)
  File
"/home/eran/tmp/xxx/requests/requests/packages/urllib3/poolmanager.py",
line 54, in <lambda>
    dispose_func=lambda p: p.close())
  File
"/home/eran/tmp/xxx/requests/requests/packages/urllib3/connectionpool.py",
line 306, in close
    conn.close()
  File "/usr/lib/python2.7/httplib.py", line 768, in close
    self.__response.close()
  File "t2.py", line 7, in close
    traceback.print_stack()
_fp is <__main__.Instrumented instance at 0x1f93fc8>
_fp.fp is <socket._fileobject object at 0x1f354d0>
done, calling lsof
COMMAND  PID USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
python  2070 eran    3u  IPv4  11206      0t0  TCP 192.168.0.105:58925
->a88-221-75-23.deploy.akamaitechnologies.com:http (CLOSE_WAIT)
done

Are the _fp prints before the "done, calling lsof" line as same as on your
machine?


Mine looks more like this: [https://gist.github.com/777b41131a8bb39aa8d0]


Hi,

With google.in I am getting similar results to what you are seeing.
Could you try it with the mouser url?
Would you be interested in a capture of the HTTP traffic?

Thanks

On Sun, Sep 16, 2012 at 10:48 AM, Shivaram Lingamneni <
notifications@github.com> wrote:

> Mine looks more like this: [https://gist.github.com/777b41131a8bb39aa8d0]
> 
> —
> Reply to this email directly or view it on GitHubhttps://github.com/kennethreitz/requests/issues/771#issuecomment-8592890.


I can't reproduce using the Mouser URL, since it returns a 200-OK for me (I think possibly because of my IP address).

If you have time, could you look into the question of why `r.content` isn't breaking the reference chain, by setting `_fp.fp` to None? I think that's the core question here, since it is intended to prevent exactly this situation.