Httpx: Suppress error "returning true from eof_received() has no effect when using ssl"

[lethargy-navigator]

I'm using httpx 0.12 w/ python 3.6 behind an SSL-intercepting proxy. verify=False

I'm constantly getting error "returning true from eof_received() has no effect when using ssl" while my async function is running.

Is there any way to suppress this error?

[tomchristie]

Could you include a traceback.
It'd be great to have enough information to be able to replicate this - what proxy are you using and what would we need to do to reproduce the issue?

[lethargy-navigator]

Unfortunately this error is not being caught as an exception. It just prints to the console as I'm running my async function. Sorry for being ignorant, but where should I look to print more information on the error?

I think I've nailed this error down to a specific set of hosts I'm making requests against. I'll try to find any common attributes among those hosts.

The proxy being used is bluecoat proxySG, which afaik uses squid.

I have confirmed that the error also does print when using a squid proxy that does not perform SSL-intercept, otherwise known as "SSL bump".

[lethargy-navigator]

Ok, I was able to duplicate this off-network with the following setup:

squid configured with a basic config:
http_port 127.0.0.1:3128
http_access allow all

code:

import asyncio
import httpx
import random

timeout = 10
useragent = 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10.14; rv:72.0) Gecko/20100101 Firefox/72.0'
headers = {'User-Agent': useragent}
targets = 'path to list of hostnames'
livetargets = []
proxies = {'all':'http://127.0.0.1:3128'}

with open(targets) as hostslist:
    hostslist = hostslist.readlines()
    hostslist = [host.strip() for host in hostslist]
    hostslist = list(dict.fromkeys(hostslist))
    random.shuffle(hostslist)

sema = asyncio.BoundedSemaphore(50)
async def get_url(host):
    async with sema, httpx.AsyncClient(http2=True, verify=False, proxies=proxies) as client:
        try:
            print(host)
            https = await client.get('https://'+host+'/', timeout=timeout, headers=headers, allow_redirects=False)
            if https:
                url = 'https://'+host+'/'
                return host,url,https.status_code,https.reason_phrase,https.http_version
        except:
            try:
                http = await client.get('http://'+host+'/', timeout=timeout, headers=headers, allow_redirects=False)
                if http:
                    url = 'http://'+host+'/'
                    return host,url,http.status_code,http.reason_phrase,http.http_version
            except:
                return False

def main():
    loop = asyncio.get_event_loop()
    tasks = [get_url(host) for host in hostslist]
    results = loop.run_until_complete(asyncio.gather(*tasks))
    loop.close()

    for result in results:
        if result:
            livetargets.append(result)

    print(livetargets)
    print(len(livetargets))

if __name__ == '__main__':
    main()

[florimondmanca]

@lethargy-navigator Thanks for providing a code snippet, but it's still hard to reproduce. Ideally we should be able to copy/paste a bunch of code, run a Python script, and see the error. :-)

Can you, in order of priority:

• Share the exact warning you're seeing, and any useful context about it (module, line numbers, etc).
• Do some more investigation to pin-point which request exactly triggers the warning (if it's at the request level), and on which host. I'm assuming this will end up being some sort of interaction bettwen verify=False, requesting over HTTPS/HTTP, and perhaps a faulty server.

(FWIW, background on eof_received in the asyncio docs:

Protocol.eof_received():
[...]
Some transports, including SSL, don’t support half-closed connections, in which case returning true from this method will result in the connection being closed.

)

[tomchristie]

Indeed. One other thing too - it'd be useful to isolate this as asyncio-only (or not).
Does the issue replicate if you're using trio instead?

[lethargy-navigator]

@florimondmanca
error: "returning true from eof_received() has no effect when using ssl"

Unfortunately this is not caught as an exception so I don't have any details on the module or line number. It just prints to the console while my script is running.

This only affects asyncio when a proxy is used. I could not get the error to print when using trio.

Please see the following code which should allow you to easily reproduce this. This includes 100 randomly selected hosts from att.com.

import asyncio
import httpx

proxies = {'all':'http://127.0.0.1:3128'}

hostslist = ['ffmi04.dp.att.com', 'vnae02.acss.att.com', 'h-135-197-231-61.research.att.com', 'tmla-demo.att.com', 'h-135-207-51-140.research.att.com', 'extrameasures.att.com', 'almdm02.dp.att.com', 'h-135-207-1-50.research.att.com', 'h-135-207-50-100.research.att.com', 'h-135-207-7-10.research.att.com', 'seasons.casab.hvs.att.com', 'h-135-207-168-11.research.att.com', 'iqiproddis02.iqi.labs.att.com', 'h-135-207-58-41.research.att.com', 'q1eam1w10.stage.att.com', 'vnch0203.acss.att.com', 'b2bsase.att.com', 'recvdna.att.com', 'h-135-207-10-151.research.att.com', 'afmfe3.att.com', 'dss-p1mbw26.att.com', 'labsphere.labs.att.com', 'm.att.com', 'oauthapp2.stage.att.com', 'hvd-intl08.att.com', 'h-135-197-228-131.research.att.com', 'mdmint01.dp.att.com', 'h-135-207-172-1.research.att.com', 'am01.acss.att.com', 'dev-cybersecurityservices.att.com', 'h-135-207-178-210.research.att.com', 'h-135-197-231-60.research.att.com', 'tlws-ssl-ngeag.att.com', 'afmfe2.att.com', 'h-135-207-19-151.research.att.com', 'attreg.indigo.test.att.com', 'saml.e-access.att.com', 'autodiscover.att.com', 'h-135-207-133-80.research.att.com', 'anpw15fep1webext.attpoc1.att.com', 'lsreg.indigo.test.att.com', 'caemp2.vpn.att.com', 'assetmanagement.att.com', 'vnfr09.acss.att.com', 'h-135-207-38-10.research.att.com', 'mpoc.iot.att.com', 'vndh150.acss.att.com', 'h-135-207-52-110.research.att.com', 'h-135-197-240-41.research.att.com', 'h-135-197-246-50.research.att.com', 'seasons.calag.hvs.att.com', 'qvscol05.ciq.labs.att.com', 'h-135-207-35-70.research.att.com', 'h-135-207-49-241.research.att.com', 'h-135-207-31-10.research.att.com', 'opss-p2cgw9.att.com', 'h-135-207-22-21.research.att.com', 'demovnastd.att.com', 'apivdna.att.com', 'av.claritysfb.labs.att.com', 'believeneworleans.att.com', 'myattwx25.att.com', 'ph-connection.dlife.att.com', 'h-135-207-52-70.research.att.com', 'customerapi-workforcemanager.att.com', 'txssl9.vpn.att.com', 'bc-sf.att.com', 'h-135-207-60-120.research.att.com', 'ab02.acss.att.com', 'h-135-207-253-190.research.att.com', 'h-135-207-31-101.research.att.com', 'apsapitest01.att.com', 'h-135-207-53-100.research.att.com', 'h-135-207-168-120.research.att.com', 'apps.firstnet.att.com', 'h-135-207-57-201.research.att.com', 'h-135-207-51-90.research.att.com', 'h-135-207-62-190.research.att.com', 'h-135-207-53-60.research.att.com', 'xdmca.wireless.att.com', 'cnosc.att.com', 'h-135-207-57-211.research.att.com', 'h-135-207-105-210.research.att.com', 'atw-expe-cl2-1.att.com', 'h-135-207-180-61.research.att.com', 'ae03.acss.att.com', 'staging.synaptic.att.com', 'opssp9w1.att.com', 'iiwc.dlife.att.com', 'xoauthaccess-sf.att.com', 'h-135-207-241-121.research.att.com', 'mytime-mobile.test.att.com', 'connect1.uc.att.com', 'csi-systest.test.dlife.att.com', 'h-135-207-98-150.research.att.com', 'h-135-207-178-220.research.att.com', 'edge1.exch.att.com', 'origin-wbfc-lyn2.att.com', 'seicmsdev.test.att.com', 'h-135-207-249-201.research.att.com']

sema = asyncio.BoundedSemaphore(20)

async def get_url(host):
    async with sema, httpx.AsyncClient(proxies=proxies) as client:
        try:
            print(host)
            https = await client.get('https://'+host+'/')
            if https:
                url = 'https://'+host+'/'
                return host,url,https.status_code,https.reason_phrase,https.http_version
        except Exception as e:
            print(e)

loop = asyncio.get_event_loop()
tasks = [get_url(host) for host in hostslist]
results = loop.run_until_complete(asyncio.gather(*tasks))
loop.close()

[florimondmanca]

easily reproduce this

Unfortunately I don't have a local proxy running so I was not able to reproduce… Can you share some steps to setup such an SSL-intercepting proxy?

[lethargy-navigator]

I'll use debian-based linux distro steps, but it should be similar for any linux distro.

apt install squid
mv /etc/squid/squid.conf /etc/squid/squid.conf.orig
printf 'http_port 127.0.0.1:3128\nhttp_access allow all' > /etc/squid/squid.conf
systemctl start squid

That should give you a functional squid proxy listening on 127.0.0.1:3128.

Edit: This setup does not do SSL interception, but that is not required to reproduce the issue.

[lisonge]

i also meet the same problem

# proxies soft : v2rayN
proxies = {
"http": "http://127.0.0.1:10809",
"https": "http://127.0.0.1:10809",
}
headers = {
'Referer': 'https://www.pixiv.net/',
}
image_url = "https://i.pximg.net/img-original/img/2020/04/02/19/20/07/80517949_p0.jpg"
response = await client.get(image_url, headers=headers)
file_content = response.content
# do something
# and https://www.pixiv.net/ has many alike urls
# it is successful, but sometimes log "returning true from eof_received() has no effect when using ssl"

how can i disable this log?

[teds-teds]

I had the same problem.
I found that it was asyncio/sslproto.py that was throwing the error and just commented the warning out.

Linux
/usr/lib/$python_folder/asyncio/sslproto.py

Windows
$python_folder/Lib/asyncio/sslproto.py

def eof_received(self):
    """Called when the other end of the low-level stream
    is half-closed.

    If this returns a false value (including None), the transport
    will close itself.  If it returns a true value, closing the
    transport is up to the protocol.
    """
    try:
        if self._loop.get_debug():
            logger.debug("%r received EOF", self)

        self._wakeup_waiter(ConnectionResetError)

        if not self._in_handshake:
            keep_open = self._app_protocol.eof_received()
            if keep_open:
                logger.warning('returning true from eof_received() '
                               'has no effect when using ssl')

[lisonge]

@teds-teds
thanks, and it also is available

import logging, asyncio
asyncio.log.logger.setLevel(logging.ERROR)
# or just
asyncio.log.logger.setLevel(40)

[maxtheman]

I also had this issue and it was crashing my jupyter notebook due to the long outputs (making a lot of requests)

I can confirm that adding

asyncio.log.logger.setLevel(logging.ERROR)

Resolved it.

@florimondmanca would you like me to submit a pull request? I can either add this to the docs somewhere or aim to incorporate it into the library.

[florimondmanca]

@maxtheman Thanks for suggesting, but I don't think hiding asyncio warnings is a good solution long term. Feel free to use it as a _workaround_ for now, but there may still be something we need to account for to make this error not appear at all.

@lethargy-navigator Thanks for the pointers about Squid, it's very useful. I'm going to give this a shot using docker-squid, see if I can replicate… Stay tuned!

[florimondmanca]

Okay, here's my setup with httpx==0.12.1*:

# squid.conf
http_port 3128
http_access allow all

# proxy.sh
exec docker run --rm \
  --name squid \
  --publish 3128:3128 \
  --mount type=bind,source="$(pwd)/squid.conf",target=/etc/squid/squid.conf \
  sameersbn/squid

import asyncio
import httpx

proxies = "http://localhost:8080"
target = "https://www.google.com"
num_tasks = 20
num_ok = 0


async def fetch() -> None:
    global num_ok
    async with httpx.AsyncClient(proxies=proxies) as client:
        await client.get(target)
        num_ok += 1


async def main() -> None:
    tasks = [fetch() for _ in range(num_tasks)]
    await asyncio.gather(*tasks)


loop = asyncio.get_event_loop()
loop.run_until_complete(main())

assert num_ok == num_tasks  # Shows that errors aren't actual exceptions.

With this, I'm able to reproduce the returning true from eof_received() has no effect when using ssl error logs from asyncio. It appears a random number of times (between 0 and num_tasks) depending on the run.

(Obviously the error doesn't show up when requesting an HTTP server, eg a uvicorn server on localhost.)

I'm still not sure what's causing this issue (probably some kind of race condition due to .gather()), but at least now we've got a reproducible setup.

---

*On master this setup is completely broken, seems like there's a bug in httpcore… Any idea @tomchristie?

Traceback (most recent call last):
  File "client.py", line 13, in fetch
    r = await client.get(target)
  File "/Users/florimond/Developer/python-projects/httpx/httpx/_client.py", line 1279, in get
    return await self.request(
  File "/Users/florimond/Developer/python-projects/httpx/httpx/_client.py", line 1121, in request
    response = await self.send(
  File "/Users/florimond/Developer/python-projects/httpx/httpx/_client.py", line 1142, in send
    response = await self.send_handling_redirects(
  File "/Users/florimond/Developer/python-projects/httpx/httpx/_client.py", line 1169, in send_handling_redirects
    response = await self.send_handling_auth(
  File "/Users/florimond/Developer/python-projects/httpx/httpx/_client.py", line 1206, in send_handling_auth
    response = await self.send_single_request(request, timeout)
  File "/Users/florimond/Developer/python-projects/httpx/httpx/_client.py", line 1238, in send_single_request
    ) = await dispatcher.request(
  File "/Users/florimond/Developer/python-projects/httpx/venv/lib/python3.8/site-packages/httpcore/_async/http_proxy.py", line 81, in request
    return await self._tunnel_request(
  File "/Users/florimond/Developer/python-projects/httpx/venv/lib/python3.8/site-packages/httpcore/_async/http_proxy.py", line 155, in _tunnel_request
    proxy_response = await connection.request(
  File "/Users/florimond/Developer/python-projects/httpx/venv/lib/python3.8/site-packages/httpcore/_async/connection.py", line 52, in request
    assert url[:3] == self.origin
AssertionError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "client.py", line 24, in <module>
    loop.run_until_complete(main())
  File "/Users/florimond/.pyenv/versions/3.8.2/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "client.py", line 20, in main
    await asyncio.gather(*tasks)
  File "client.py", line 15, in fetch
    num_ok += 1
  File "/Users/florimond/Developer/python-projects/httpx/httpx/_client.py", line 1454, in __aexit__
    await self.aclose()
  File "/Users/florimond/Developer/python-projects/httpx/httpx/_client.py", line 1443, in aclose
    await proxy.aclose()
  File "/Users/florimond/Developer/python-projects/httpx/venv/lib/python3.8/site-packages/httpcore/_async/connection_pool.py", line 275, in aclose
    await self._remove_from_pool(connection)
  File "/Users/florimond/Developer/python-projects/httpx/venv/lib/python3.8/site-packages/httpcore/_async/connection_pool.py", line 258, in _remove_from_pool
    self._connection_semaphore.release()
  File "/Users/florimond/Developer/python-projects/httpx/venv/lib/python3.8/site-packages/httpcore/_backends/asyncio.py", line 210, in release
    self.semaphore.release()
  File "/Users/florimond/.pyenv/versions/3.8.2/lib/python3.8/asyncio/locks.py", line 533, in release
    raise ValueError('BoundedSemaphore released too many times')
ValueError: BoundedSemaphore released too many times

[yeraydiazdiaz]

On master this setup is completely broken, seems like there's a bug in httpcore

I can confirm there's a bug in httpcore's handling of tunnel proxies, I've opened https://github.com/encode/httpcore/issues/54 to address it.

[tomchristie]

Closed via https://github.com/encode/httpcore/issues/54

[amitripshtos]

@tomchristie Just for fully understanding - I still see the "returning true from eof_received() has no effect when using SSL" logs even on latest httpcore. Should I just change the logging level or should we re-open it? Thanks!

[florimondmanca]

@amitripshtos Yeah, it seems we closed this prematurely. #54 and the subsequent PR #57 were adressing the "unrelated bug" I was referring to earlier, not the original issue here. Lemme reopen.

[florimondmanca]

I've marked this as external because I believe this should be treated as a CPython "bug".

See:

https://github.com/python/cpython/blob/0ef96c2b2a291c9d2d9c0ba42bbc1900a21e65f3/Lib/asyncio/streams.py#L269-L278

The code there uses a ._over_ssl flag to return False in the SSL case, which should prevent the warning from firing, but it does. So maybe that flag is incorrectly set?

I don't think there's actually anything we can do at the HTTPX / HTTPCore level. There's a workaround above, and if this is causing too much trouble I'd recommend filing a ticket to CPython and helping solve the issue over there.

So… I'll actually close this back as "external". :-)

[florimondmanca]

Woops, okay, let me go through this slowly because I think it's actually on us…

There are 4 things at play here:

• asyncio's StreamReaderProtocol: it's got a ._over_ssl flag. It's False initially, then set to "does the transport have an sslcontext?" when .connection_made() is called. https://github.com/python/cpython/blob/0ef96c2b2a291c9d2d9c0ba42bbc1900a21e65f3/Lib/asyncio/streams.py#L236
• asyncio's SSLProtocol: it _optionally_ calls .connection_made() on the protocol it wraps after the handshake completes.
• asyncio's loop.start_tls: it creates a SSLProtocol wrapping the current transport protocol, _but does not instruct it to call .connection_made() on the current protocol_ as per call_connection_made=False (since I guess asyncio assumes that protocol is "already running"). https://github.com/python/cpython/blob/0ef96c2b2a291c9d2d9c0ba42bbc1900a21e65f3/Lib/asyncio/base_events.py#L1215-L1219
• Our own .start_tls() wrapper, which instantiates a StreamReaderProtocol, does not call .connection_made() on it, then passes that to asyncio's start_tls().

So in the end, the StreamReaderProtocol's .connection_made() doesn't get called, so _over_ssl isn't set, and so the warning is logged…

So, how do we fix this?

To fix this, I think we _might_ need to modify our .start_tls() wrapper so it uses the _currently running protocol_, as follows?

- stream_reader = asyncio.StreamReader()
- protocol = asyncio.StreamReaderProtocol(stream_reader)
  transport = self.stream_writer.transport
+ protocol = transport.get_protocol()

Or maybe something else…