NewConnectionRequired exception raised when running behind a proxy

[pfmoore]

Environment

Windows 10, 64 bit
Python 3.9.2
httpx 0.18.1
httpcore 0.13.3

ZScaler proxy running on localhost (set via http{s}_proxy environment variables).

Problem

I'm writing some threaded code using httpx, and I've just started getting NewConnectionRequired errors in my test runs. I don't think I've changed anything that would affect the http call, but I am currently running on a work network which uses a HTTP proxy. I notice in the traceback that httpcore\_sync\http_proxy.py shows up, so maybe that implies it's the proxy that's the trigger for the problem?

My main concern here is that the exception doesn't give me any idea what I need to do to fix the issue, if it is a problem with my code or environment, and there's no documentation that I could find of what the exception means.

I'm reporting this here even though I'm not entirely sure if it's a bug - but even if it is a problem in my program or environment, a better error (or some documentation) would be welcome 🙂

I include a traceback from the error in case it's of any use in working out what the problem is.

2021-05-12 13:33:17.666 | ERROR    | pypidata.pypi:get_project:14 - An error has been caught in function 'get_project', process 'MainProcess' (16000), thread 'ThreadPoolExecutor-0_4' (16328):
Traceback (most recent call last):

  File "C:\Users\UK03306\AppData\Local\Programs\Python\Python39\lib\threading.py", line 912, in _bootstrap
    self._bootstrap_inner()
    │    └ <function Thread._bootstrap_inner at 0x0000027BDFAC1CA0>
    └ <Thread(ThreadPoolExecutor-0_4, started 16328)>

  File "C:\Users\UK03306\AppData\Local\Programs\Python\Python39\lib\threading.py", line 954, in _bootstrap_inner
    self.run()
    │    └ <function Thread.run at 0x0000027BDFAC19D0>
    └ <Thread(ThreadPoolExecutor-0_4, started 16328)>

  File "C:\Users\UK03306\AppData\Local\Programs\Python\Python39\lib\threading.py", line 892, in run
    self._target(*self._args, **self._kwargs)
    │    │        │    │        │    └ {}
    │    │        │    │        └ <Thread(ThreadPoolExecutor-0_4, started 16328)>
    │    │        │    └ (<weakref at 0x0000027BE2040090; to 'ThreadPoolExecutor' at 0x0000027BE201D1C0>, <_queue.SimpleQueue object at 0x0000027BE201...
    │    │        └ <Thread(ThreadPoolExecutor-0_4, started 16328)>
    │    └ <function _worker at 0x0000027BDFADE5E0>
    └ <Thread(ThreadPoolExecutor-0_4, started 16328)>

  File "C:\Users\UK03306\AppData\Local\Programs\Python\Python39\lib\concurrent\futures\thread.py", line 77, in _worker
    work_item.run()
    │         └ <function _WorkItem.run at 0x0000027BDFADE700>
    └ <concurrent.futures.thread._WorkItem object at 0x0000027BE206A5B0>

  File "C:\Users\UK03306\AppData\Local\Programs\Python\Python39\lib\concurrent\futures\thread.py", line 52, in run
    result = self.fn(*self.args, **self.kwargs)
             │    │   │    │       │    └ {}
             │    │   │    │       └ <concurrent.futures.thread._WorkItem object at 0x0000027BE206A5B0>
             │    │   │    └ ('101703322-missing-val',)
             │    │   └ <concurrent.futures.thread._WorkItem object at 0x0000027BE206A5B0>
             │    └ <bound method ProducerConsumer.producer_task of <__main__.ProducerConsumer object at 0x0000027BE1ED8850>>
             └ <concurrent.futures.thread._WorkItem object at 0x0000027BE206A5B0>

  File "C:\Work\Scratch\pypidata\src\pypidata\worker.py", line 34, in producer_task
    for data in self.producer(input):
                │    │        └ '101703322-missing-val'
                │    └ <function get_project_data.<locals>.p at 0x0000027BE2006CA0>
                └ <__main__.ProducerConsumer object at 0x0000027BE1ED8850>

  File "C:\Work\Scratch\pypidata\src\pypidata\worker.py", line 82, in p
    yield get_project(name, "simple", client)
          │           │               └ <httpx.Client object at 0x0000027BDFA58160>
          │           └ '101703322-missing-val'
          └ <function get_project at 0x0000027BDFAEB9D0>

> File "C:\Work\Scratch\pypidata\src\pypidata\pypi.py", line 14, in get_project
    response = get_url(url, client)
               │       │    └ <httpx.Client object at 0x0000027BDFA58160>
               │       └ 'https://pypi.org/simple/101703322-missing-val/'
               └ <function get_url at 0x0000027BE1EDAE50>

  File "C:\Work\Scratch\pypidata\src\pypidata\network.py", line 55, in get_url
    response = fetcher(method, url)
               │       │       └ 'https://pypi.org/simple/101703322-missing-val/'
               │       └ 'get'
               └ <bound method Client.request of <httpx.Client object at 0x0000027BDFA58160>>

  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpx\_client.py", line 747, in request
    return self.send(
           │    └ <function Client.send at 0x0000027BE1DB2AF0>
           └ <httpx.Client object at 0x0000027BDFA58160>

  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpx\_client.py", line 831, in send
    response = self._send_handling_auth(
               │    └ <function Client._send_handling_auth at 0x0000027BE1DB2B80>
               └ <httpx.Client object at 0x0000027BDFA58160>

  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpx\_client.py", line 866, in _send_handling_auth
    response = self._send_handling_redirects(
               │    └ <function Client._send_handling_redirects at 0x0000027BE1DB2C10>
               └ <httpx.Client object at 0x0000027BDFA58160>

  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpx\_client.py", line 900, in _send_handling_redirects
    response = self._send_single_request(request, timeout)
               │    │                    │        └ Timeout(timeout=5.0)
               │    │                    └ <Request('GET', 'https://pypi.org/simple/101703322-missing-val/')>
               │    └ <function Client._send_single_request at 0x0000027BE1DB2CA0>
               └ <httpx.Client object at 0x0000027BDFA58160>

  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpx\_client.py", line 934, in _send_single_request
    (status_code, headers, stream, extensions) = transport.handle_request(
                                                 │         └ <function HTTPTransport.handle_request at 0x0000027BE1DA9790>
                                                 └ <httpx.HTTPTransport object at 0x0000027BE201D6D0>

  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpx\_transports\default.py", line 179, in handle_request
    status_code, headers, byte_stream, extensions = self._pool.handle_request(
                 │                                  │    │     └ <function SyncHTTPProxy.handle_request at 0x0000027BE1DA9280>
                 │                                  │    └ <httpcore.SyncHTTPProxy object at 0x0000027BE201D790>
                 │                                  └ <httpx.HTTPTransport object at 0x0000027BE201D6D0>
                 └ [(b'Host', b'pypi.org'), (b'Accept', b'*/*'), (b'Accept-Encoding', b'gzip, deflate'), (b'Connection', b'keep-alive'), (b'User...  

  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpcore\_sync\http_proxy.py", line 127, in handle_request
    return self._tunnel_request(
           │    └ <function SyncHTTPProxy._tunnel_request at 0x0000027BE1DA93A0>
           └ <httpcore.SyncHTTPProxy object at 0x0000027BE201D790>

  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpcore\_sync\http_proxy.py", line 273, in _tunnel_request
    ) = connection.handle_request(
        │          └ <function SyncHTTPConnection.handle_request at 0x0000027BE1DA50D0>
        └ <SyncHTTPConnection http_version=HTTP/1.1 state=2>

  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpcore\_sync\connection.py", line 106, in handle_request
    raise NewConnectionRequired()
          └ <class 'httpcore._sync.base.NewConnectionRequired'>

httpcore._sync.base.NewConnectionRequired

[pfmoore]

Update: I've managed to create a small example to reproduce the issue:

import httpx
from concurrent.futures import ThreadPoolExecutor

with httpx.Client() as client:
    with ThreadPoolExecutor() as ex:
        for response in ex.map(lambda i: client.get("https://httpbin.org"), range(1000)):
            print(response)

This gives the following output:

<Response [200 OK]>
<Response [200 OK]>
<Response [200 OK]>
<Response [200 OK]>
<Response [200 OK]>
<Response [200 OK]>
<Response [200 OK]>
<Response [200 OK]>
<Response [200 OK]>
<Response [200 OK]>
<Response [200 OK]>
Traceback (most recent call last):
  File "C:\Work\Scratch\pypidata\httptest.py", line 6, in <module>
    for response in ex.map(lambda i: client.get("https://httpbin.org"), range(1000)):
  File "C:\Users\UK03306\AppData\Local\Programs\Python\Python39\lib\concurrent\futures\_base.py", line 600, in result_iterator
    yield fs.pop().result()
  File "C:\Users\UK03306\AppData\Local\Programs\Python\Python39\lib\concurrent\futures\_base.py", line 433, in result
    return self.__get_result()
  File "C:\Users\UK03306\AppData\Local\Programs\Python\Python39\lib\concurrent\futures\_base.py", line 389, in __get_result
    raise self._exception
  File "C:\Users\UK03306\AppData\Local\Programs\Python\Python39\lib\concurrent\futures\thread.py", line 52, in run
    result = self.fn(*self.args, **self.kwargs)
  File "C:\Work\Scratch\pypidata\httptest.py", line 6, in <lambda>
    for response in ex.map(lambda i: client.get("https://httpbin.org"), range(1000)):
  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpx\_client.py", line 975, in get
    return self.request(
  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpx\_client.py", line 747, in request
    return self.send(
  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpx\_client.py", line 831, in send
    response = self._send_handling_auth(
  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpx\_client.py", line 866, in _send_handling_auth
    response = self._send_handling_redirects(
  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpx\_client.py", line 900, in _send_handling_redirects
    response = self._send_single_request(request, timeout)
  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpx\_client.py", line 934, in _send_single_request
    (status_code, headers, stream, extensions) = transport.handle_request(
  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpx\_transports\default.py", line 179, in handle_request
    status_code, headers, byte_stream, extensions = self._pool.handle_request(
  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpcore\_sync\http_proxy.py", line 127, in handle_request
    return self._tunnel_request(
  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpcore\_sync\http_proxy.py", line 273, in _tunnel_request
    ) = connection.handle_request(
  File "C:\Work\Scratch\pypidata\.venv\lib\site-packages\httpcore\_sync\connection.py", line 106, in handle_request
    raise NewConnectionRequired()
httpcore._sync.base.NewConnectionRequired

Also, reducing the number of connections in the pool (httpx.Client(limits=httpx.Limits(max_connections=10))) seems to make the problem take longer to appear, so maybe the problem is that the proxy is slow connecting if I issue too many requests, and the pool is full of connections in "Connecting" state? (I'm guessing here based on a quick skim of the source...)

[tomchristie]

Okay, firstly - this is a really nicely described issue - thanks for your efforts in reducing it to a nice simple case.

And yes, I can reproduce this. I'm using mitmproxy, as documented here, which I needed to refer to in order to help me figure out how to get everything up and running.

And yes, it is a bug - that's an internal exception, that you shouldn't be seeing escape out of httpcore.
So, will have a dig into it.

Btw...

• Those tracebacks you're showing are fantastic - I really like the variable annotation its providing. What are you using to get those detailed tracebacks or environment are you using?
• There's a few good reminders in the traceback of classes that we ought to be adding more useful __repr__ cases for. httpx.Client() in particular, but also a few others.

[pfmoore]

Glad I was able to describe the bug well for you.

The tracebacks are nice, aren't they. The come from the logging package I'm trying out - loguru - as an unexpected benefit.

[johtso]

The pretty tracebacks specifically seem to be provided by this package.. https://github.com/Qix-/better-exceptions

[Granitosaurus]

Any updates on this? I'm encountering these quite often on asyncio.gather calls for proxied requests.
Any way to prevent this?

[tomchristie]

@Granitosaurus I'm working towards resolving this, but there's some bits of refactoring I'm need to do first in order to be able to tackle it.

[tomchristie]

This sort of thing is the preliminary work... #353

[maven-slava]

Any version ETA?

[emil45]

Any updates on this? I'm encountering these quite often on asyncio.gather calls for proxied requests.
Any way to prevent this?

+1, using httpx with AsyncClient, every few requests I get this error, ignoring for now.

[tomchristie]

See encode/httpx#1741

[tomchristie]

Closed by 0.14