search

jawah / niquests

“Safest, Fastest, Easiest, and Most advanced” Python HTTP Client. Production Ready! Drop-in replacement for Requests. HTTP/1.1, HTTP/2, and HTTP/3 supported. With WebSocket!
https://niquests.readthedocs.io/en/latest/
Apache License 2.0
1.05k stars 23 forks source link

MultiplexingError: resolving lazy responses using a proxy #170

Closed UlionTse closed 1 week ago

UlionTse commented 3 weeks ago

Expected Result

Actual Result

Reproduction Steps

import niquests

def f2():
    responses = []
    with niquests.Session(multiplexed=True) as s2:
        responses.append(s2.get("https://pie.dev/delay/3"))
        responses.append(s2.get("https://pie.dev/delay/3"))
        print([r.status_code for r in responses])
    return

System Information

Traceback (most recent call last):
  File "/opt/anaconda3/lib/python3.10/site-packages/IPython/core/interactiveshell.py", line 3553, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-5-55649989190d>", line 1, in <module>
    f2()
  File "<ipython-input-4-a3c977f886c2>", line 6, in f2
    print([r.status_code for r in responses])
  File "<ipython-input-4-a3c977f886c2>", line 6, in <listcomp>
    print([r.status_code for r in responses])
  File "/opt/anaconda3/lib/python3.10/site-packages/niquests/models.py", line 1093, in __getattribute__
    super().__getattribute__("_gather")()
  File "/opt/anaconda3/lib/python3.10/site-packages/niquests/models.py", line 1073, in _gather
    super().__getattribute__("connection").gather(self)
  File "/opt/anaconda3/lib/python3.10/site-packages/niquests/adapters.py", line 1352, in gather
    raise MultiplexingError(
niquests.exceptions.MultiplexingError: Underlying library did not recognize our promise when asked to retrieve it. Did you close the session too early?
Ousret commented 3 weeks ago

I cannot reproduce the error you encountered.

What I see is [200, 200] as it should.

I highly suspect your environment to be somehow broken. I see IPython and anaconda3 referenced in your logs, which I don't have installed.

Make sure your "anaconda3" environment have the latest versions of both niquests and urllib3-future. If the issue persist, I shall try to simulate this exact environment.

Regards,

UlionTse commented 2 weeks ago
截屏2024-11-06 10 52 51
Ousret commented 2 weeks ago

image

image

Something seems very specific to you.

Let's try to understand what has happened.

Please run:

import logging
import niquests

logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
explain_handler = logging.StreamHandler()
explain_handler.setFormatter(
    logging.Formatter("%(asctime)s | %(levelname)s | %(message)s")
)
logger.addHandler(explain_handler)

(i) re-run as before

def f2():
    responses = []
    with niquests.Session(multiplexed=True) as s2:
        responses.append(s2.get("https://pie.dev/delay/3"))
        responses.append(s2.get("https://pie.dev/delay/3"))
        print([r.status_code for r in responses])
    return

f2()

(ii) run with disable_http2=True

def f2():
    responses = []
    with niquests.Session(multiplexed=True, disable_http2=True) as s2:
        responses.append(s2.get("https://pie.dev/delay/3"))
        responses.append(s2.get("https://pie.dev/delay/3"))
        print([r.status_code for r in responses])
    return

f2()

(iii) run with disable_http3=True

def f2():
    responses = []
    with niquests.Session(multiplexed=True, disable_http3=True) as s2:
        responses.append(s2.get("https://pie.dev/delay/3"))
        responses.append(s2.get("https://pie.dev/delay/3"))
        print([r.status_code for r in responses])
    return

f2()

(iv) then, try

def f2():
    responses = []
    with niquests.Session(multiplexed=True) as s2:
        responses.append(s2.get("https://httpbingo.org/delay/3"))
        responses.append(s2.get("https://httpbingo.org/delay/3"))
        print([r.status_code for r in responses])
    return

f2()

(v) finally

def f2():
    responses = []
    with niquests.Session(multiplexed=True, resolver="doh+cloudflare://") as s2:
        responses.append(s2.get("https://pie.dev/delay/3"))
        responses.append(s2.get("https://pie.dev/delay/3"))
        print([r.status_code for r in responses])
    return

f2()

Copy and paste every outputs & logs here, we should have the explanation of why and get directions for next steps.

regards,

UlionTse commented 2 weeks ago

@Ousret Sorry, I have used VPN when I tested it. When I closed VPN, (i)(ii)(iii)(iv) are okay, (v) is slowly to fail. But when I open VPN, only (ii) is okay. The question now becomes whether I can still normally use niquests while using a VPN. Thanks.

Ousret commented 1 week ago

I had suspected connectivity issues anyway.

The question now becomes whether I can still normally use niquests while using a VPN.

Of course you can. I daily drive Niquests with and without VPN and so far, I never encountered this situation.

What is probably happening is that the remote peer does not like your IP, and doing more than one requests (e.g. multiplexing) using a single connection ends up in this failure. You probably need to choose another VPN endpoint (e.g. country) or check your sys logs networking related issue or use wireshark to understand what went wrong.

I am going to close this issue as it is related to your personal networking configuration. You could detect this edge case like:

with niquests.Session(multiplexed=True) as s:
    try:
        s.gather(*[s.get("https://httpbingo.org/get"), s.get("https://httpbingo.org/get")])
    except niquests.exceptions.MultiplexedError:
        print("multiplexing not supported in current network, check that your IP is clean and not flagged using https://ipinfo.io/ for example")

Without logs, we cannot say anything better than "probably is due to". If you want deeper analysis, run:

import logging
import niquests

logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
explain_handler = logging.StreamHandler()
explain_handler.setFormatter(
    logging.Formatter("%(asctime)s | %(levelname)s | %(message)s")
)
logger.addHandler(explain_handler)

along with given examples.

Regards,

UlionTse commented 1 week ago

@Ousret My issue title: niquests.exceptions.MultiplexingError: Underlying library did not recognize our promise when asked to retrieve it. Did you close the session too early?

Your test (the same as ): niquests.exceptions.MultiplexingError: multiplexing not supported in current network, check that your IP is clean and not flagged using https://ipinfo.io/ for example

Are you kidding me ?

Ousret commented 1 week ago

Are you kidding me ?

Not at all. There is probably a misunderstanding somewhere.

I will try to rephrase with more details.

with niquests.Session(multiplexed=True) as s:
    try:
        s.gather(*[s.get("https://httpbingo.org/get"), s.get("https://httpbingo.org/get")])
    except niquests.exceptions.MultiplexedError:
        print("multiplexing not supported in current network, check that your IP is clean and not flagged using https://ipinfo.io/ for example")

That example is the minimal reproducer that fail on your PC using your VPN. Which I cannot reproduce no matter what I do or tweak on my end. And no one ever encountered this beside you. OK so far?

I asked you to run the following program:

import logging
import niquests

logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
explain_handler = logging.StreamHandler()
explain_handler.setFormatter(
    logging.Formatter("%(asctime)s | %(levelname)s | %(message)s")
)
logger.addHandler(explain_handler)

with niquests.Session(multiplexed=True) as s:
    try:
        s.gather(*[s.get("https://httpbingo.org/get"), s.get("https://httpbingo.org/get")])
    except niquests.exceptions.MultiplexedError:
        print("multiplexing not supported in current network, check that your IP is clean and not flagged using https://ipinfo.io/ for example")

And to paste the full output including the logs. To that moment, I did not see any of them.

The output I expect look like this:

2024-01-03 12:07:11,846 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-01-03 12:07:11,847 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-01-03 12:07:11,859 | DEBUG | Starting new HTTPS connection (1): pie.dev:443
2024-01-03 12:07:12,136 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-01-03 12:07:12,136 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-01-03 12:07:12,138 | DEBUG | Starting new HTTP connection (1): e1.o.lencr.org:80
2024-01-03 12:07:12,250 | DEBUG | http://e1.o.lencr.org:80 "POST / HTTP/1.1" 200 344
2024-01-03 12:07:12,253 | DEBUG | Adding (b':method', b'GET') to the header table, sensitive:False, huffman:True
2024-01-03 12:07:12,253 | DEBUG | Encoding 2 with 7 bits
2024-01-03 12:07:12,253 | DEBUG | Adding (b':scheme', b'https') to the header table, sensitive:False, huffman:True
2024-01-03 12:07:12,253 | DEBUG | Encoding 7 with 7 bits
2024-01-03 12:07:12,253 | DEBUG | Adding (b':path', b'/get') to the header table, sensitive:False, huffman:True
2024-01-03 12:07:12,253 | DEBUG | Encoding 4 with 6 bits
2024-01-03 12:07:12,253 | DEBUG | Encoding 3 with 7 bits
2024-01-03 12:07:12,253 | DEBUG | Adding (b':authority', b'pie.dev') to the header table, sensitive:False, huffman:True
2024-01-03 12:07:12,253 | DEBUG | Encoding 1 with 6 bits
2024-01-03 12:07:12,253 | DEBUG | Encoding 5 with 7 bits
2024-01-03 12:07:12,253 | DEBUG | Adding (b'user-agent', b'niquests/3.4.0') to the header table, sensitive:False, huffman:True
2024-01-03 12:07:12,253 | DEBUG | Encoding 58 with 6 bits
2024-01-03 12:07:12,253 | DEBUG | Encoding 10 with 7 bits
2024-01-03 12:07:12,253 | DEBUG | Adding (b'accept-encoding', b'gzip, deflate') to the header table, sensitive:False, huffman:True
2024-01-03 12:07:12,254 | DEBUG | Encoding 16 with 7 bits
2024-01-03 12:07:12,254 | DEBUG | Adding (b'accept', b'*/*') to the header table, sensitive:False, huffman:True
2024-01-03 12:07:12,254 | DEBUG | Encoding 19 with 6 bits
2024-01-03 12:07:12,254 | DEBUG | Encoding 3 with 7 bits

Finally, based on your issue and my experience of the project I inferred the following:

Now, that is just guessing. And we don't want that. If I am wrong, then there is something that we can do, but.

If you would provide the full logs, it will be useful to pursue the investigation.

Regards,

UlionTse commented 1 week ago

@Ousret

  1. niquests.Session(multiplexed=True)

Logs when I turned on the VPN:

2024-11-12 23:41:32,510 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-12 23:41:32,511 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-12 23:41:34,005 | DEBUG | Starting new HTTPS connection (1): httpbingo.org:443
2024-11-12 23:41:41,202 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-12 23:41:41,204 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-12 23:41:41,207 | DEBUG | Starting new HTTP connection (1): 127.0.0.1:4780
2024-11-12 23:41:41,414 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-12 23:41:41,415 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-12 23:41:41,416 | DEBUG | Starting new HTTP connection (1): 127.0.0.1:4780
multiplexing not supported in current network, check that your IP is clean and not flagged using https://ipinfo.io/ for example

Logs when I turned off the VPN:

2024-11-12 23:42:09,153 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-12 23:42:09,153 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-12 23:42:09,156 | DEBUG | Starting new HTTPS connection (1): httpbingo.org:443
2024-11-12 23:42:09,444 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-12 23:42:09,444 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-12 23:42:09,445 | DEBUG | Starting new HTTP connection (1): e5.o.lencr.org:80
2024-11-12 23:42:09,854 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-12 23:42:09,854 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-12 23:42:09,855 | DEBUG | Starting new HTTP connection (1): e5.o.lencr.org:80
  1. niquests.Session(happy_eyeballs=True)

Logs when I turned on the VPN:

2024-11-13 00:05:00,914 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-13 00:05:00,914 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-13 00:05:00,918 | DEBUG | Starting new HTTPS connection (1): httpbingo.org:443
2024-11-13 00:05:00,918 | DEBUG | Attempting Happy-Eyeball httpbingo.org:443
2024-11-13 00:05:00,919 | DEBUG | Happy-Eyeball Ineligible httpbingo.org:443
2024-11-13 00:05:02,994 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-13 00:05:02,994 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-13 00:05:02,995 | DEBUG | Starting new HTTP connection (1): 127.0.0.1:4780
2024-11-13 00:05:02,995 | DEBUG | Attempting Happy-Eyeball 127.0.0.1:4780
2024-11-13 00:05:02,995 | DEBUG | Happy-Eyeball Ineligible 127.0.0.1:4780
2024-11-13 00:05:03,680 | DEBUG | https://httpbingo.org:443 "GET /get HTTP/2.0" 200 None

Logs when I turned off the VPN:

2024-11-13 00:04:07,854 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-13 00:04:07,854 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-13 00:04:07,857 | DEBUG | Starting new HTTPS connection (1): httpbingo.org:443
2024-11-13 00:04:07,857 | DEBUG | Attempting Happy-Eyeball httpbingo.org:443
2024-11-13 00:04:07,859 | DEBUG | Happy-Eyeball Ineligible httpbingo.org:443
2024-11-13 00:04:08,667 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-13 00:04:08,667 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-11-13 00:04:08,667 | DEBUG | Starting new HTTP connection (1): e5.o.lencr.org:80
2024-11-13 00:04:08,667 | DEBUG | Attempting Happy-Eyeball e5.o.lencr.org:80
2024-11-13 00:04:08,676 | DEBUG | Happy-Eyeball Single-Stack e5.o.lencr.org:80
2024-11-13 00:04:09,309 | DEBUG | https://httpbingo.org:443 "GET /get HTTP/2.0" 200 None

Attention localhost 127.0.0.1:4780?

Ousret commented 1 week ago

This was it. 127.0.0.1:4780 was the critical piece of information we were missing. Your "VPN" software isn't one technically speaking, as it does not setup a virtual network adapter. It setup a local HTTP proxy (presumably forward tunnel), then automatically configure the environment to propagate the proxy configuration. Now, given this, I could reproduce your case.

Fortunately, it is now fixed! Upgrade to 3.10.3 and report back. Everything should be in order.

Regards,

UlionTse commented 1 week ago

@Ousret I have tested it with v3.10.3. Good Job!