KeyError: HTTPConnection(origin=...) on ReadTimeout in connection_pool #817

Activity

1. ojii commented on Feb 19, 2020

   

   ojii

   on Feb 19, 2020

   Author

   More actions

   I've made a repo that can usually reproduced the issue: https://github.com/HENNGE/httpx-h2-testing

   When the client tries to send ~1000 requests the KeyError usually happens.
2. lovelydinosaur commented on Feb 19, 2020

   

   lovelydinosaur

   on Feb 19, 2020

   Member

   More actions

   Okay, thanks for the report.

   I've been taking a refresh onto the connection pool handling in httpcore... https://github.com/encode/httpcore/blob/master/httpcore/_async/connection_pool.py

   Might be that I need to prioritize working on that again, in order to get this, #283, and #514 resolved.
3. ojii commented on Feb 20, 2020

   

   ojii

   on Feb 20, 2020

   Author

   More actions

   The example I made indeed also shows #514. I'd expect it to use a single connection (or maybe 1 connection per 100 requests since that's the stream limit). Also with different parameters (eg issue 10k requests) it also exhausts the per-connection stream limit. In our real-world scenario, we don't currently hit the second issue, but the first two (KeyError and lots of connections) do happen and we're also seeing some sort of memory leak (but haven't been able to track this down to httpx or our app yet).

   Let me know if there's more information you need or if there are other ways I can help.

   👍React with 👍2Reacted by Kim Christie and Victor
4. dimaqq commented on Feb 28, 2020

   

   dimaqq

   on Feb 28, 2020

   More actions

   I've been poking at @ojii 's test and I think (not fully sure yet) that KeyError only happens in a very peculiar circumstance:

   1. many requests are send in parallel
   2. one of the requests fails (Timeout or ConnectionReset), which is legal
   3. await gather(all those requests) propagates the exception
   4. asyncio.run finishes
   5. asyncio attempts to clean up outstanding tasks (via cancellation if I get it right)
   6. during that, KeyError is hit

   If that's correct, then the problem is in cancellation and not on the happy path.
5. dimaqq commented on Feb 28, 2020

   

   dimaqq

   on Feb 28, 2020

   More actions

   Having instrumented connection pool / connection store:

   diff --git a/httpx/_dispatch/connection_pool.py b/httpx/_dispatch/connection_pool.py
   index 61d323c..20c8f31 100644
   --- a/httpx/_dispatch/connection_pool.py
   +++ b/httpx/_dispatch/connection_pool.py
   @@ -62,6 +62,7 @@ class ConnectionStore:
            return connection
   
        def add(self, connection: HTTPConnection) -> None:
   +        __import__("logging").warning("add called on %s", id(self))
            self.all[connection] = 0.0
            try:
                self.by_origin[connection.origin][connection] = 0.0
   @@ -69,12 +70,14 @@ class ConnectionStore:
                self.by_origin[connection.origin] = {connection: 0.0}
   
        def remove(self, connection: HTTPConnection) -> None:
   +        __import__("logging").warning("remove called on %s", id(self))
            del self.all[connection]
            del self.by_origin[connection.origin][connection]
            if not self.by_origin[connection.origin]:
                del self.by_origin[connection.origin]
   
        def clear(self) -> None:
   +        __import__("logging").warning("clear called on %s", id(self))
            self.all.clear()
            self.by_origin.clear()
   

   I get log:

   WARNING:root:add called on 140611732770096
   WARNING:root:add called on 140611732770096
   ...
   WARNING:root:remove called on 140611732770096
   WARNING:root:clear called on 140611732770144
   WARNING:root:remove called on 140611732770096
   ...
   

   This is the traceback when .clear() was is called:

   Traceback (most recent call last):
     File "asyncio/runners.py", line 43, in run
       return loop.run_until_complete(main)
     File "asyncio/base_events.py", line 642, in run_until_complete
       return future.result()
     File "tests/stress/test_cancellation.py", line 25, in run_client
       await asyncio.gather(*todo)
     File "httpx/_client.py", line 1401, in __aexit__
       await self.aclose()
     File "httpx/_client.py", line 1390, in aclose
       await self.dispatch.close()
     File "httpx/_dispatch/connection_pool.py", line 211, in close
       self.keepalive_connections.clear()
     File "httpx/_dispatch/connection_pool.py", line 81, in clear
   

   So, basically, the async with statement finishes before individual requests.
6. dimaqq commented on Feb 28, 2020

   

   dimaqq

   on Feb 28, 2020

   More actions

   Work-around: https://github.com/dimaqq/httpx/blob/91ed44abe4f88ce32cc9e82a4d230c5ad5a5c10b/tests/stress/test_cancellation.py#L26-L33
7. florimondmanca commented on Mar 13, 2020

   

   florimondmanca

   on Mar 13, 2020

   Last edited by florimondmanca

   Contributor

   More actions

   Hi here, the httpcore-based implementation has come along nicely now; has anyone tried to reproduce this against an HTTPX installation pinned on #804? Is it still an issue on that branch?
8. florimondmanca

   added

   bugSomething isn't workingSomething isn't working

   concurrencyIssues related to concurrency and usage of async librariesIssues related to concurrency and usage of async libraries

   poolingIssues and PRs relative to connection poolingIssues and PRs relative to connection pooling

   on Mar 13, 2020
9. lovelydinosaur commented on Apr 30, 2020

   

   lovelydinosaur

   on Apr 30, 2020

   Member

   More actions

   I'm going to close this on the assumption that its resolved in the 0.13.dev0 pre-release, given that we've totally refreshed the pool handling, and it's a much more careful implementation.
10. lovelydinosaur

    closed this as completedon Apr 30, 2020