(fix): hang after browser OIDC authentication#1693
Conversation
Signed-off-by: Sachin Sampras M <sampras343@gmail.com>
Signed-off-by: Sachin Sampras M <sampras343@gmail.com>
|
@sampras343 is there a corresponding issue for this? |
@woodruffw I couldn't find any corresponding issue for this behavior. But it persists on sigstore v4.2.0 |
|
I added some timestamp and delta logs at this stage just to debug: The delta between |
|
Applied the fix and with the same logs, below are the results: The delta between |
Okay. In the future please file an issue before opening a PR, it makes triaging these things easier. Could you share a reproducer example that hangs for you? I just tried this and couldn't reproduce a hang: touch empty
uvx sigstore sign emptyYielded: (That's with v4.2.0, on Python 3.14.3) |
|
I tried with the exact example as yours, additionally logging the timestamps of each stdout Results: + 23:56:48 Waiting for browser interaction...
+ 23:59:28 [23:59:28] INFO Transparency log entry created at index: xxx _cli.py:729
23:59:28 Using ephemeral certificate:
23:59:28 -----BEGIN CERTIFICATE-----
23:59:28 MIICyTCCAk6gAwIBAgIUFKQH32C0IVdQ0Wc5ZmG67NyYOf8wCgYIKoZIzj0EAwMw
23:59:28 NzEVMBMGA1UEChMMc2lnc3RvcmUuZGV2MR4wHAYDVQQDExVzaWdzdG9yZS1pbnRl
23:59:28 cm1lZGlhdGUwHhcNMjYwMjEzMjM1OTI3WhcNMjYwMjE0MDAwOTI3WjAAMFkwEwYH
23:59:28 KoZIzj0CAQYIKoZIzj0DAQcDQgAEoZ4vKp82XX48+/QhtmzZH7BVN7D4Ewrf4zE5
23:59:28 c4WKUrut2JCXfcSxs70v4HN2n9vIE0g2dGW/y60XSWWbe49hMqOCAW0wggFpMA4G
23:59:28 A1UdDwEB/wQEAwIHgDATBgNVHSUEDDAKBggrBgEFBQcDAzAdBgNVHQ4EFgQUG1X6
23:59:28 2rmVCwiGK9UOAH6KLswTa/owHwYDVR0jBBgwFoAU39Ppz1YkEZb5qNjpKFWixi4Y
23:59:28 ZD8wHQYDVR0RAQH/BBMwEYEPc2FjbUByZWRoYXQuY29tMCkGCisGAQQBg78wAQEE
23:59:28 G2h0dHBzOi8vYWNjb3VudHMuZ29vZ2xlLmNvbTArBgorBgEEAYO/MAEIBB0MG2h0
23:59:28 dHBzOi8vYWNjb3VudHMuZ29vZ2xlLmNvbTCBigYKKwYBBAHWeQIEAgR8BHoAeAB2
23:59:28 AN09MGrGxxEyYxkeHJlnNwKiSl643jyt/4eKcoAvKe6OAAABnFlx+DcAAAQDAEcw
23:59:28 RQIgVvYCm25iRJLWc4E4lGyUqjCjWeAjh/TAxNplXRBCceQCIQCX4UX/GsGJrZAa
23:59:28 KCoYsugCcR6hZ3+M/zimPA0GEtoQOjAKBggqhkjOPQQDAwNpADBmAjEAo6heZyAF
23:59:28 K5GhTTH/HfKz9IhyCikE2xQ6ezjIBn6ySlvYZAorblZws25UkD94PltxAjEAmF2x
23:59:28 nnKMHFUrjQLCpCioWmAwTMKHwi9cABfin0qN72xrhZq6HybT42IsF41TINdm
23:59:28 -----END CERTIFICATE-----
23:59:28
23:59:28 Sigstore bundle written to emptydata.sigstore.jsonAssuming that the browser interaction took 5-10 seconds, the delta still remains at 2m40s Another signing with the same emptydata: Output: + 00:06:08 Waiting for browser interaction...
+ 00:07:28 [00:07:28] INFO Transparency log entry created at index: xxx _cli.py:729
00:07:28 Using ephemeral certificate:
00:07:28 -----BEGIN CERTIFICATE-----
00:07:28 MIICyDCCAk6gAwIBAgIUAlujDR1eR2YwmXDGDI0kbPFKbN4wCgYIKoZIzj0EAwMw
00:07:28 NzEVMBMGA1UEChMMc2lnc3RvcmUuZGV2MR4wHAYDVQQDExVzaWdzdG9yZS1pbnRl
00:07:28 cm1lZGlhdGUwHhcNMjYwMjE0MDAwNzI3WhcNMjYwMjE0MDAxNzI3WjAAMFkwEwYH
00:07:28 KoZIzj0CAQYIKoZIzj0DAQcDQgAEn3PSWlphDSbJksb4CHV0k+CzPWTI0TknCOgJ
00:07:28 MO85H/6rwTXmuR2KoqXohMBOKhZJZG+YYKS/LmM6jKfoBZp6j6OCAW0wggFpMA4G
00:07:28 A1UdDwEB/wQEAwIHgDATBgNVHSUEDDAKBggrBgEFBQcDAzAdBgNVHQ4EFgQU0mMR
00:07:28 z9Kjg3sYHQzDD0wMi+E+/RMwHwYDVR0jBBgwFoAU39Ppz1YkEZb5qNjpKFWixi4Y
00:07:28 ZD8wHQYDVR0RAQH/BBMwEYEPc2FjbUByZWRoYXQuY29tMCkGCisGAQQBg78wAQEE
00:07:28 G2h0dHBzOi8vYWNjb3VudHMuZ29vZ2xlLmNvbTArBgorBgEEAYO/MAEIBB0MG2h0
00:07:28 dHBzOi8vYWNjb3VudHMuZ29vZ2xlLmNvbTCBigYKKwYBBAHWeQIEAgR8BHoAeAB2
00:07:28 AN09MGrGxxEyYxkeHJlnNwKiSl643jyt/4eKcoAvKe6OAAABnFl5TIUAAAQDAEcw
00:07:28 RQIhAN9ICGXC/V7mG8K4PeBjaEufdwUCV/51xL2j04dDXj+3AiAcXec6R5DjsFFv
00:07:28 Hwk9DcQ48QZvHgaFl6ADgoijypaJuTAKBggqhkjOPQQDAwNoADBlAjEAsvyfoslK
00:07:28 RDxy7Ff36O1e/IeoLbMLGrPg07xa1BNNzEYHu4i7MrJNCz88jrKRevgiAjBX1hC8
00:07:28 yXbdfycRsTVaeyW9GhNLJ6HjALFq8LYjK31Hxm7lawBn+KdXHA7P1POSlzQ=
00:07:28 -----END CERTIFICATE-----
00:07:28
00:07:28 Sigstore bundle written to emptydata.sigstore.jsonAssuming that the browser interaction took 5-10 seconds, the delta still remains at 1m20s python --version --> Output of |
|
Also, I'd imagine it's still better to create an issue and link it to the PR. Thoughts? |
|
Okay, thanks for trying the reproducer. Could you share more about your host OS, and try running with debug logs?
Yeah that's totally fine, it's more just the lack of an issue entirely. Without one and without a reproducer there's basically no way to evaluate the proposed change. |
OS Info: Attaching logs after running in debug mode: Command run: Logs: 04:16:42 [04:16:42] DEBUG parsed arguments Namespace(verbose=0, staging=False, instance=None, trust_config=None, subcommand='sign', identity_token=None, oidc_client_id='sigstore', oidc_client_secret=None, oidc_disable_ambient_providers=False, oidc_issuer=None, _cli.py:639
04:16:42 oauth_force_oob=False, no_default_files=False, signature=None, certificate=None, bundle=None, output_directory=None, overwrite=True, files=[PosixPath('emptydata')])
04:16:42 DEBUG TUF metadata: /home/sacm/.local/share/sigstore-python/tuf/https%3A%2F%2Ftuf-repo-cdn.sigstore.dev tuf.py:98
04:16:42 DEBUG TUF targets cache: /home/sacm/.cache/sigstore-python/tuf/https%3A%2F%2Ftuf-repo-cdn.sigstore.dev tuf.py:99
04:16:42 DEBUG Found and verified trusted root tuf.py:151
04:16:42 DEBUG Found and verified signing config tuf.py:174
04:16:42 DEBUG Fulcio client using URL: https://fulcio.sigstore.dev client.py:166
+ 04:16:43 Waiting for browser interaction...
04:16:43 [04:16:43] DEBUG GET: / with {'Host': 'localhost:42779', 'Connection': 'keep-alive', 'sec-ch-ua': '"Not(A:Brand";v="8", "Chromium";v="144", "Google Chrome";v="144"', 'sec-ch-ua-mobile': '?0', 'sec-ch-ua-platform': '"Linux"', 'Upgrade-Insecure-Requests': '1', oauth.py:137
04:16:43 'User-Agent': 'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/144.0.0.0 Safari/537.36', 'Accept':
04:16:43 'text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7', 'Sec-Fetch-Site': 'none', 'Sec-Fetch-Mode': 'navigate', 'Sec-Fetch-User': '?1', 'Sec-Fetch-Dest': 'document',
04:16:43 'Accept-Encoding': 'gzip, deflate, br, zstd', 'Accept-Language': 'en-US,en;q=0.9'}
04:16:49 [04:16:49] DEBUG GET: /auth/callback?code=a6u47e3xo74hyiyqbgvvyxetf&state=faae093c-3c1d-4f3c-a4ff-5287f3aa9e7e with {'Host': 'localhost:42779', 'Connection': 'keep-alive', 'Upgrade-Insecure-Requests': '1', 'User-Agent': 'Mozilla/5.0 (X11; Linux x86_64) oauth.py:137
04:16:49 AppleWebKit/537.36 (KHTML, like Gecko) Chrome/144.0.0.0 Safari/537.36', 'Accept': 'text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7', 'Sec-Fetch-Site':
04:16:49 'cross-site', 'Sec-Fetch-Mode': 'navigate', 'Sec-Fetch-User': '?1', 'Sec-Fetch-Dest': 'document', 'sec-ch-ua': '"Not(A:Brand";v="8", "Chromium";v="144", "Google Chrome";v="144"', 'sec-ch-ua-mobile': '?0', 'sec-ch-ua-platform': '"Linux"', 'Referer':
+ 04:16:49 'https://accounts.google.com/', 'Accept-Encoding': 'gzip, deflate, br, zstd', 'Accept-Language': 'en-US,en;q=0.9'}
+ 04:18:25 [04:18:25] DEBUG Generating ephemeral keys... sign.py:106
04:18:25 DEBUG Requesting ephemeral certificate... sign.py:108
04:18:25 DEBUG Retrieving signed certificate... sign.py:142
04:18:26 [04:18:26] DEBUG Found <Name(O=sigstore.dev,CN=sigstore-intermediate)> as issuer, verifying if it is a ca sct.py:171
04:18:26 DEBUG attempting to verify SCT with key ID dd3d306ac6c7113263191e1c99673702a24a5eb8de3cadff878a72802f29ee8e sct.py:226
04:18:26 DEBUG Successfully verified SCT... sign.py:173
04:18:26 DEBUG signing for emptydata _cli.py:705
04:18:26 DEBUG proposed: {"apiVersion": "0.0.1", "kind": "hashedrekord", "spec":
.
. SKIPPING BODY
.
04:18:26 -----END CERTIFICATE-----
04:18:26
04:18:26 Sigstore bundle written to emptydata.sigstore.jsonApprox delta: 1m 37s Command run (fix included): 04:29:57 [04:29:57] DEBUG parsed arguments Namespace(verbose=0, staging=False, instance=None, trust_config=None, subcommand='sign', identity_token=None, oidc_client_id='sigstore', oidc_client_secret=None, oidc_disable_ambient_providers=False, oidc_issuer=None, _cli.py:639
04:29:57 oauth_force_oob=False, no_default_files=False, signature=None, certificate=None, bundle=None, output_directory=None, overwrite=True, files=[PosixPath('emptydata')])
04:29:57 DEBUG TUF metadata: /home/sacm/.local/share/sigstore-python/tuf/https%3A%2F%2Ftuf-repo-cdn.sigstore.dev tuf.py:98
04:29:57 DEBUG TUF targets cache: /home/sacm/.cache/sigstore-python/tuf/https%3A%2F%2Ftuf-repo-cdn.sigstore.dev tuf.py:99
04:29:57 DEBUG Found and verified trusted root tuf.py:151
04:29:57 DEBUG Found and verified signing config tuf.py:174
04:29:57 DEBUG Fulcio client using URL: https://fulcio.sigstore.dev client.py:166
04:29:58 [04:29:58] DEBUG GET: / with {'Host': 'localhost:37967', 'Connection': 'keep-alive', 'sec-ch-ua': '"Not(A:Brand";v="8", "Chromium";v="144", "Google Chrome";v="144"', 'sec-ch-ua-mobile': '?0', 'sec-ch-ua-platform': '"Linux"', 'Upgrade-Insecure-Requests': '1', oauth.py:140
04:29:58 'User-Agent': 'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/144.0.0.0 Safari/537.36', 'Accept':
04:29:58 'text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7', 'Sec-Fetch-Site': 'none', 'Sec-Fetch-Mode': 'navigate', 'Sec-Fetch-User': '?1', 'Sec-Fetch-Dest': 'document',
04:29:58 'Accept-Encoding': 'gzip, deflate, br, zstd', 'Accept-Language': 'en-US,en;q=0.9'}
+ 04:29:58 Waiting for browser interaction...
04:30:02 [04:30:02] DEBUG GET: /auth/callback?code=u5nv5zerraajgcabuctdsr7ui&state=1a7b808c-6aaa-4a42-84b1-3a852c82be78 with {'Host': 'localhost:37967', 'Connection': 'keep-alive', 'Upgrade-Insecure-Requests': '1', 'User-Agent': 'Mozilla/5.0 (X11; Linux x86_64) oauth.py:140
04:30:02 AppleWebKit/537.36 (KHTML, like Gecko) Chrome/144.0.0.0 Safari/537.36', 'Accept': 'text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7', 'Sec-Fetch-Site':
04:30:02 'cross-site', 'Sec-Fetch-Mode': 'navigate', 'Sec-Fetch-User': '?1', 'Sec-Fetch-Dest': 'document', 'sec-ch-ua': '"Not(A:Brand";v="8", "Chromium";v="144", "Google Chrome";v="144"', 'sec-ch-ua-mobile': '?0', 'sec-ch-ua-platform': '"Linux"', 'Referer':
+ 04:30:02 'https://accounts.google.com/', 'Accept-Encoding': 'gzip, deflate, br, zstd', 'Accept-Language': 'en-US,en;q=0.9'}
+ 04:30:03 [04:30:03] DEBUG Generating ephemeral keys... sign.py:106
04:30:03 DEBUG Requesting ephemeral certificate... sign.py:108
04:30:03 DEBUG Retrieving signed certificate... sign.py:142
04:30:03 DEBUG Found <Name(O=sigstore.dev,CN=sigstore-intermediate)> as issuer, verifying if it is a ca sct.py:171
04:30:03 DEBUG attempting to verify SCT with key ID dd3d306ac6c7113263191e1c99673702a24a5eb8de3cadff878a72802f29ee8e sct.py:226
04:30:03 DEBUG Successfully verified SCT... sign.py:173
04:30:03 DEBUG signing for emptydata _cli.py:705
04:30:03 DEBUG proposed: {"apiVersion": "0.0.1",
.
. SKIPPING BODY
.
04:30:04 -----END CERTIFICATE-----
04:30:04
04:30:04 Sigstore bundle written to emptydata.sigstore.jsonApprox delta: 1-2s |
Signed-off-by: Sachin Sampras M <sampras343@gmail.com>
|
For reference, I've never seen this issue either. I wonder what the missing piece is for reproduction? Anyway, the PR seems correct to me. |
|
/gcbrun |
Yeah, I tried some more and couldn't reproduce it. @sampras343 is there any chance you're behind a corporate MITM or other traffic-modifying proxy? (But yeah, I agree the patch looks correct regardless, I'm okay with us merging it if we can't figure out the root cause here.) |
Yes I am, but it's the same behavior with or without VPN. |
Summary
Fix HTTP keep-alive deadlock in the OIDC redirect server that caused the CLI to hang for ~60 seconds after successful browser authentication.
Add missing
end_headers()calls,close_connection = Trueon all handler paths, and a 1-second socket timeout on the handler class.Closes #1697
Why:
After a user completes browser-based OIDC authentication (e.g. sigstore sign), the CLI would hang for approximately 60 seconds before continuing, even though the browser immediately showed "sigstore authentication successful!"
Release Note
Added the below:
Documentation
None