Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

binary post timeout #116

Closed
kgk opened this issue Apr 30, 2024 · 6 comments · Fixed by jawah/qh3#33
Closed

binary post timeout #116

kgk opened this issue Apr 30, 2024 · 6 comments · Fixed by jawah/qh3#33

Comments

@kgk
Copy link

kgk commented Apr 30, 2024

a post of a binary fails to connect

Expected Result

When run with requests :

<RequestsCookieJar[<Cookie mex_session=Kf9Af8RTYBge9AbBH-Ncg-7sEtcm3l4oOtWBMlgzPKbQ1biC_runmRXRKNgL0Z7UfCvCNfgYuSRv4UNmt3nBhHNlc3Npb246MDAtRkJYOTdLSkJFOE1YVEdzUWtjWmVMeg for XXXX/>]>
200

Actual Result

When using niquests

 200 <RequestsCookieJar[<Cookie mex_session=hZz_JtcqpnhtVJSP3IVCeJDot9xMG0BMDvczDiYB95INRCB_kCVBA9dgKyS-gMHRoIGABMOsL7l_BYvXCTddoHNlc3Npb246MDAtWGFIVXI5SEZvcldGdjl5dFdUUkVjYg for  XXXX>]>
^CTraceback (most recent call last):
  File "/home/kgk/work/bisque/viqi_1/ni_transfer_test.py", line 23, in <module>
    r = ss.post(furl(url).add(path=f"/import/transfer_direct/home/{tmpdir}/1.jpg").url,
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/kgk/.virtualenvs/http3/lib/python3.11/site-packages/niquests/sessions.py", line 800, in post
    return self.request(
           ^^^^^^^^^^^^^
  File "/home/kgk/.virtualenvs/http3/lib/python3.11/site-packages/niquests/sessions.py", line 539, in request
    resp = self.send(prep, **send_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/kgk/.virtualenvs/http3/lib/python3.11/site-packages/niquests/sessions.py", line 1174, in send
    r = adapter.send(request, **kwargs)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/kgk/.virtualenvs/http3/lib/python3.11/site-packages/niquests/adapters.py", line 896, in send
    resp_or_promise = conn.urlopen(  # type: ignore[call-overload]
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/kgk/.virtualenvs/http3/lib/python3.11/site-packages/urllib3/connectionpool.py", line 1383, in urlopen
    response = self._make_request(  # type: ignore[call-overload,misc]
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/kgk/.virtualenvs/http3/lib/python3.11/site-packages/urllib3/connectionpool.py", line 1009, in _make_request
    rp = conn.request(
         ^^^^^^^^^^^^^
  File "/home/kgk/.virtualenvs/http3/lib/python3.11/site-packages/urllib3/connection.py", line 477, in request
    self.send(chunk)
  File "/home/kgk/.virtualenvs/http3/lib/python3.11/site-packages/urllib3/backend/hface.py", line 1055, in send
    self._protocol.bytes_received(self.sock.recv(self.blocksize))
                                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
KeyboardInterrupt

Reproduction Steps

 
import  niquests as requests
import random
import string
from furl import furl

# Setup
url = "https://authenticated.server.."
user="XXX"
pswd="XXX"
localfile = "/home/kgk/Desktop/pics/shrub.JPG"

# tests
ss = requests.Session(multiplexed=True)
r = ss.post(furl(url).add(path="/auth_service/login_handler", args={ "login": user, "password": pswd}).url)

print (r.status_code, ss.cookies)


tmpdir  = "".join(random.choices(string.ascii_lowercase, k=4))

r = ss.post(furl(url).add(path=f"/import/transfer_direct/home/{tmpdir}/1.jpg").url,
        data = open (localfile, "rb").read(),
        headers = {"content-type": "application/octet-stream"})

print(r.status_code)

System Information

$ python -m niquests.help

Failed 1st time because h2 was missing after executing pip install h2 I get

{

  "charset_normalizer": {
    "version": "3.3.2"
  },
  "http1": {
    "h11": "0.14.0"
  },
  "http2": {
    "h2": "4.1.0"
  },
  "http3": {
    "enabled": true,
    "qh3": "1.0.4"
  },
  "idna": {
    "version": "3.7"
  },
  "implementation": {
    "name": "CPython",
    "version": "3.11.2"
  },
  "niquests": {
    "version": "3.6.1"
  },
  "ocsp": {
    "enabled": true
  },
  "platform": {
    "release": "6.1.0-18-amd64",
    "system": "Linux"
  },
  "system_ssl": {
    "version": "300000b0"
  },
  "urllib3.future": {
    "cohabitation_version": null,
    "version": "2.7.905"
  },
  "wassima": {
    "certifi_fallback": false,
    "enabled": true,
    "version": "1.1.1"
  }
}

The environmen allow me to use niquest against the server

In [1]: import  niquests as requests

In [2]: requests.get("XXXX")
Out[2]: <Response HTTP/2 [200]>

In [3]: requests.get("XXXX")
Out[3]: <Response HTTP/3 [200]>

@Ousret
Copy link
Member

Ousret commented May 1, 2024

OK. Let's try to understand what is happening.

What I understand so far from your report:

  • Your server is HTTP 3 capable
  • Your first request is issued with HTTP/2 (authentication)
  • Your second request should be made with HTTP/3 (file upload)
  • It hangs indefinitely on the upload (more specifically, waiting for data flow control)

Immediately, I tried to reproduce your scenario using a demo HTTP/3 server and it worked without error.
So, I could not reproduce. And obviously I can't access your server to inspect network frames.

To dig this further, we need to know:

  • Server type (nginx, caddy, traefik, ...) ?

On your side, try:

A) Try to add disable_http3=True inside of Session(...) and see if it works with http2 only.

B) Try to replace https://authenticated.server.. with https://pie.dev and use the /post path for both requests while removing disable_http3=True

C) Run your code, the original one, but add this code to be executed before all:

import logging

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)

And copy/paste the logs here.

Regards,

@Ousret Ousret added the question Further information is requested label May 2, 2024
@Ousret
Copy link
Member

Ousret commented May 6, 2024

Without further information, it will be impossible for me to investigate.
Even if (very) unlikely to resolve, try to upgrade our programs to latest.

pip install niquests urllib3-future qh3 jh2 -U

If the issue persist, let us know.

@kgk
Copy link
Author

kgk commented May 7, 2024

Sorry .. other work sidetracked me for a couple of days.

We terminate http/2 and http/3 in traefik 2.11

A. disable_http3 worked correctly
B. received 404 for all requests.
C. I upgraded all requirements as requested and added logging

2024-05-07 11:06:21,418 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-05-07 11:06:21,418 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-05-07 11:06:21,419 | DEBUG | Starting new HTTPS connection (1): testing.viqiai.dev:443
2024-05-07 11:06:21,654 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-05-07 11:06:21,655 | DEBUG | Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=None, status=None)
2024-05-07 11:06:21,655 | DEBUG | Starting new HTTP connection (1): r3.o.lencr.org:80
2024-05-07 11:06:21,690 | DEBUG | http://r3.o.lencr.org:80 "POST / HTTP/1.1" 200 503
2024-05-07 11:06:21,885 | DEBUG | Resetting dropped connection: testing.viqiai.dev
2024-05-07 11:06:21,896 | DEBUG | [d475a938c3e7181a] TLS State.CLIENT_HANDSHAKE_START -> State.CLIENT_EXPECT_SERVER_HELLO
2024-05-07 11:06:21,931 | DEBUG | [d475a938c3e7181a] QuicConnectionState.FIRSTFLIGHT -> QuicConnectionState.CONNECTED
2024-05-07 11:06:21,933 | DEBUG | [d475a938c3e7181a] TLS State.CLIENT_EXPECT_SERVER_HELLO -> State.CLIENT_EXPECT_ENCRYPTED_EXTENSIONS
2024-05-07 11:06:21,933 | DEBUG | [d475a938c3e7181a] TLS State.CLIENT_EXPECT_ENCRYPTED_EXTENSIONS -> State.CLIENT_EXPECT_CERTIFICATE_REQUEST_OR_CERTIFICATE
2024-05-07 11:06:21,934 | DEBUG | [d475a938c3e7181a] Discarding epoch Epoch.INITIAL
2024-05-07 11:06:21,936 | DEBUG | [d475a938c3e7181a] TLS State.CLIENT_EXPECT_CERTIFICATE_REQUEST_OR_CERTIFICATE -> State.CLIENT_EXPECT_CERTIFICATE_VERIFY
2024-05-07 11:06:21,949 | DEBUG | [d475a938c3e7181a] TLS State.CLIENT_EXPECT_CERTIFICATE_VERIFY -> State.CLIENT_EXPECT_FINISHED
2024-05-07 11:06:21,950 | DEBUG | [d475a938c3e7181a] TLS State.CLIENT_EXPECT_FINISHED -> State.CLIENT_POST_HANDSHAKE
2024-05-07 11:06:21,951 | DEBUG | [d475a938c3e7181a] ALPN negotiated protocol h3
2024-05-07 11:06:21,955 | DEBUG | [d475a938c3e7181a] Stream 3 created by peer
2024-05-07 11:06:21,983 | DEBUG | [d475a938c3e7181a] Discarding epoch Epoch.HANDSHAKE
2024-05-07 11:06:21,983 | DEBUG | [d475a938c3e7181a] Peer retiring CID a1a36b2559406560 (0)
2024-05-07 11:06:21,989 | DEBUG | [d475a938c3e7181a] Stream 0 discarded
2024-05-07 11:06:22,022 | DEBUG | [d475a938c3e7181a] Remote max_streams_bidi raised to 101
2024-05-07 11:06:22,024 | DEBUG | [d475a938c3e7181a] Stream 4 discarded
2024-05-07 11:06:22,053 | DEBUG | [d475a938c3e7181a] Remote max_streams_bidi raised to 102
200 <RequestsCookieJar[<Cookie mex_session=kQ6S2CWhpeIkRYPeI_tWK5DviCMXTcJ9T-vftfjpddXcoglOiqcMWhASjXpdGn6fxBtKgbnIqlmeQVcGCd3h2XNlc3Npb246MDAtNGEzY1BmZk1UV0tQYVpRWUZiclM0UA for testing.viqiai.dev/>]>
2024-05-07 11:06:22,067 | DEBUG | [d475a938c3e7181a] Stream 8 discarded
2024-05-07 11:06:22,123 | DEBUG | [d475a938c3e7181a] Remote max_streams_bidi raised to 103
2024-05-07 11:06:22,187 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,188 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,189 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,190 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,190 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,191 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,192 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,193 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,193 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,194 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,195 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,196 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,196 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,197 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,197 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,199 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,200 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,201 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,201 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,202 | DEBUG | [d475a938c3e7181a] decryption failed
2024-05-07 11:06:22,202 | DEBUG | [d475a938c3e7181a] decryption failed

@Ousret
Copy link
Member

Ousret commented May 8, 2024

No worries about it.

So! I managed to reproduce the error. This is good news.
The weird thing is.. we use Traefik for our integration pipeline and did not notice that error prior to your discovery.
Well, we used Traefik v2.10.4 and this error occurred since v2.10.5 or newer.

It seems that <=v2.10.4 (and others for that matter) have a weak spot. it did not rotate the key... often enough...? so our test suite was weak on that point.

We fixed the issue in the latest qh3 version. Run pip install qh3 -U v1.0.7 to fix this definitely.

Thank you for the detailed report.

Regards,

@Ousret Ousret removed the question Further information is requested label May 8, 2024
@kgk
Copy link
Author

kgk commented May 8, 2024 via email

@Ousret
Copy link
Member

Ousret commented May 8, 2024

Your feedback are most welcome.

regards,

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants