Pool Depletion / Leaking Connections

[thatguystone]

In our production environment, we've noticed the following errors in our logs, pool size set to 500:

FetchError: FetchError: msg = "No retries left, giving up", original exception = "EmptyPoolError("HTTPConnectionPool(host='SUPER_SECRET', port=80): Pool reached maximum size and no more connections are allowed.",)", url = "http://SUPER_SECRET_URL/", retries = 2
ERROR - base.py:fetch:166 - FetchError: HTTPConnectionPool(host='SUPER_SECRET', port=80): Pool reached maximum size and no more connections are allowed., retries left = 2

After a bit of investigation, it looks like the number of connections in the pool is slow decreasing over time as we encounter other errors, forced timeouts, etc. On urllib3/connectionpool.py:424, if httplib/socket raises an error, the connection will be dropped from the pool because it was acquired on 382 and never put back on line 431 since conn == None.

This issue can be replicated with the following gist (uses gevent.Timeout, so quasi-related to #69): https://gist.github.com/2932793

It looks like the if conn on line 431 was originally added to ensure that a SocketError raised from _get_conn() didn't add None to the pool since a connection would never be gotten, but in the current incarnation, it has the effect of causing the pool size to shrink over time if a connection is acquired and any error is raised from httplib/socket.

[shazow]

Ah, thank you for the excellent bug report and analysis. I believe you're correct.

Is this something you may be interested in fixing and sending a pull request? Otherwise I'll take a look at it in the next week or two.

[thatguystone]

I was looking at trying to fix it, but I didn't just want to go in and change stuff while breaking everything. If you're okay reviewing any changes I make to make sure they're not going to mess everything up, I'd be more than happy to give it a shot.

[shazow]

Absolutely.

Since we suspect the bug is simply the way the queue gets populated, we should be able to start with a simple unit test illustrating the bug. Have a look at some of these for example: https://github.com/shazow/urllib3/blob/master/test/test_connectionpool.py

urllib3 should be very thoroughly tested so hopefully we won't need to worry about breakage too much. :)

[thatguystone]

@shazow: Could you run your tests of 358c789? I'm seeing the following failures. Just want to make sure I'm not missing something.

(ve)andi@Apollo:~/Dev/IHR/urllib3$ pip freeze
argparse==1.2.1
coverage==3.5.2
distribute==0.6.24
nose==1.1.2
tornado==2.3
wsgiref==0.1.2
(ve)andi@Apollo:~/Dev/IHR/urllib3$ nosetests
.........................F.F..................................
======================================================================
FAIL: test_cross_host_redirect (test.with_dummyserver.test_poolmanager.TestPoolManager)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/andi/Dev/IHR/urllib3/test/with_dummyserver/test_poolmanager.py", line 36, in test_cross_host_redirect
    self.fail("Request succeeded instead of raising an exception like it should.")
AssertionError: Request succeeded instead of raising an exception like it should.
-------------------- >> begin captured logging << --------------------
urllib3.connectionpool: INFO: Starting new HTTP connection (1): localhost
root: INFO: 200 GET http://localhost:18081/redirect?target=http%3A%2F%2F127.0.0.1%3A18081%2Fecho%3Fa%3Db (127.0.0.1) 1.38ms
urllib3.connectionpool: DEBUG: "GET http://localhost:18081/redirect?target=http%3A%2F%2F127.0.0.1%3A18081%2Fecho%3Fa%3Db ('HTTP/1.1',)" 200 13
--------------------- >> end captured logging << ---------------------

======================================================================
FAIL: test_redirect (test.with_dummyserver.test_poolmanager.TestPoolManager)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/andi/Dev/IHR/urllib3/test/with_dummyserver/test_poolmanager.py", line 20, in test_redirect
    self.assertEqual(r.status, 303)
AssertionError: 200 != 303
-------------------- >> begin captured logging << --------------------
urllib3.connectionpool: INFO: Starting new HTTP connection (1): localhost
root: INFO: 200 GET http://localhost:18081/redirect?target=http%3A%2F%2Flocalhost%3A18081%2F (127.0.0.1) 0.76ms
urllib3.connectionpool: DEBUG: "GET http://localhost:18081/redirect?target=http%3A%2F%2Flocalhost%3A18081%2F ('HTTP/1.1',)" 200 13
--------------------- >> end captured logging << ---------------------

Name                     Stmts   Miss  Cover   Missing
------------------------------------------------------
urllib3                     16      0   100%   
urllib3._collections        69      0   100%   
urllib3.connectionpool     152      7    95%   38, 251, 371-375, 408
urllib3.contrib              0      0   100%   
urllib3.exceptions          24      4    83%   43-47
urllib3.filepost            37      0   100%   
urllib3.poolmanager         48      3    94%   106-108
urllib3.request             23      0   100%   
urllib3.response            80      1    99%   152
urllib3.util                60      0   100%   
------------------------------------------------------
TOTAL                      509     15    97%   
----------------------------------------------------------------------
Ran 62 tests in 0.732s

FAILED (failures=2)

[shazow]

Hmm, passes on Tornado 2.1.1, fails on Tornado 2.3. Wonder what changed.

[thatguystone]

Alrighty, 1bbda4e is linked and contains the fixes. If you could review, I would greatly appreciate it.

[shazow]

Took a quick glance, looks good! I'll take a more thorough look this weekend and merge it in. Thanks for doing this, @thatguystone. You're welcome to add yourself to the CONTRIBUTORS.txt if you wish. :)

[adamJLev]

+1 please merge fix in. Thanks!

[shazow]

Looks like this has been merged? Hard to tell because it wasn't a real Github pull request. :)

Please reopen if I'm mistaken.

[thatguystone]

Just created #86 for this bug. Not sure why I couldn't just make this a pull request :-\