Repository navigation
HTTP 302 Found responses with Cache Headers not being cached #384
Description
Activity
Hi @mklein0, thanks for opening an issue.
I think the reason we don't cache this is because the various RFCs are ambiguous about temporary redirects vs. permanent ones: RFC 2616 doesn't proscribe caching for these ("cacheable" isn't qualified by SHOULD or similar), while RFC 7231 doesn't mention caching for 302 at all and RFC 7234 mentions only permanent redirects explicitly.
I'm not opposed to changing this per se, but I'd like to better understand why JFrog is using HTTP 302 instead of HTTP 301 for these redirects -- ideally this is something they'd fix on their own end, since other mirror indices don't appear to have this problem.
(More broadly, I agree with the appraisal in pypa/pip#13396 (comment) -- it would be good to better understand the intended behavior here, since a signed URL strongly suggests that caching shouldn't be done.)
Reacted by George MargaritisAs you pointed out the standards are vague on required behavior, so I interpretted it as a suggestion as well. I do not know how common the usage of a private CDN redirect is, so I thought to bring it up and see if there is a best practice.
I will take these two tickets to JFROG and have them advocate for a behavior or have them alter theirs. Thank you.
@woodruffw I believe JFrog is not using HTTP 301 for redirects likely the 'Location:' of the redirect has same url but different query component, i.e., the signature, e.g.,
X-Goog-Signatureis different each time?Not caching the initial request that results in the HTTP 302 redirect may not be that critical since the relevant content returned is tiny with just the
Location:being important.Would the concern be more of NOT caching the redirected
Location:url which is the larger piece of content being transferred. I did some tests, and is it correct to say that pip performs a cache hit/miss based on the entire url including the query components? This results in the caching NOT happening because each time theX-Goog-Signaturechanges?I believe JFrog is not using HTTP 301 for redirects likely the 'Location:' of the redirect has same url but different query component, i.e., the signature, e.g., X-Goog-Signature is different each time?
Sorry, could you clarify what you mean here? "A same URL but different query component" is not the same URL, since the query is part of the URL. I'm guessing you mean "same path component," but I want to make sure I understand correctly.
I did some tests, and is it correct to say that pip performs a cache hit/miss based on the entire url including the query components? This results in the caching NOT happening because each time the X-Goog-Signature changes?
I think the pip maintainers would better be able to answer what pip specifically does -- all I know is what the caching middleware does, which pip may or may not tweak, do a superset of, etc.
For CacheControl specifically, we (currently) key off of the query string exactly as it appears in the request via
_urlnormhere:cachecontrol/cachecontrol/controller.py
Lines 65 to 83 in 9af76f7
@classmethod def _urlnorm(cls, uri: str) -> str: """Normalize the URL to create a safe key for the cache""" (scheme, authority, path, query, fragment) = parse_uri(uri) if not scheme or not authority: raise Exception("Only absolute URIs are allowed. uri = %s" % uri) scheme = scheme.lower() authority = authority.lower() if not path: path = "/" # Could do syntax based normalization of the URI before # computing the digest. See Section 6.2.2 of Std 66. request_uri = query and "?".join([path, query]) or path defrag_uri = scheme + "://" + authority + request_uri return defrag_uri (Based on my read of the RFCs, this is correct enough, and ignoring the query URL would cause overly permissive cache hits.)
@woodruffw Sorry that I was not clear with what I meant by "A same URL but different query component". I have an AWS cloudfront/s3 pre-signed url on hand so I will use that as an example.
https://d3njxchdk64paq.cloudfront.net/development/2/7/pypi/packages/8.whl?Expires=1752474000&Signature=xMOpa8TJo3OgXQRdI3ASkvvwQ5OVNBhSX1kUQjkJ964CvYsDxLXr8Dg8w0PraCRchLOP1fw-bO1UWEC7xiHGRYHYvMo27u0mCfnZDhj~q-sxEO9uYzK-Q7QNdRUBGoiveYB87g9HgzKh3G0Im8TuRmdyhpOFXOgdWlZK1JgDZG9vPOvynJjGzazkuIb9S~Wj8YfcTy3ul7hDzIJpfi24VeIP9fG3O9rmQM8cZ1SRmAgPZeC5Y3-zXSn9Hpu2bT346CW7uhmoSdGyqSAcUewZ1vCpo-UpxiJvg~TQ9KkAuYJsVFxFuJY9~bsvkqgLQ82Kad31w-i~bOb6Ym7nnSAJnw__&Key-Pair-Id=K1126YPJP5H8PThe 'main' url is
https://d3njxchdk64paq.cloudfront.net/development/2/7/pypi/packages/8.whland this does not change for a pre-signed url. Then there is the query components/url parameters, i.e., everything after?, e.g.,Expires,Signature, etc., which usually changes each time the 'main' url is pre-signed.Thank you for clarifying with:
(a) This quote "... the query is part of the URL"
(b) The code snippet showing (a)I think this is the crux of the discussion (I hope I didn't misinterpret anyone. At the very least our users (Buildkite/Packagecloud) are seeing the same phenomenon), i.e., each pre-signed url (whether google storage, aws cloudfront/s3, etc.) if considered with query component/string, is always different even though the pre-signed url is pointing to the same object in the bucket, thus cache hit never happens. This is because the pre-signed url contains query component/string with
ExpiresandSignature(for aws) and similar counterparts for other cloud, that is always changing each time a pre-signed url is generated.uv, which is apipalternative on the other hand behavesas expected, i.e., performing cache hit/miss based on just the url without considering the query components/strings.If you can help point to any RFCs that indicates cache hit/miss should take the full url including query components/string, it will be super helpful to determine where we can fix this issue.
If you can help point to any RFCs that indicates cache hit/miss should take the full url including query components/string, it will be super helpful to determine where we can fix this issue.
See this part of RFC 7234: https://datatracker.ietf.org/doc/html/rfc7234#section-4
Specifically, a cache MUST NOT reuse a response if the "effective request URI" does not match. That is then defined here: https://datatracker.ietf.org/doc/html/rfc7230#section-5.5
And to my read, the requirement here is to include the query component in the "effective request URI" (since it's a semantically relevant part of the URI).
I don't know exactly how uv behaves in this regard, but if you're seeing cache hits on signed URLs that vary by query component then I suspect that something, somewhere, is violating cache-control semantics. That, or there's some special casing around these kinds of signed URLs, since they're uncacheable by design.
However, to take a step back: can you confirm that what you're seeing is related to the original issue here? Specifically, is your first URL performing a 301 redirect or a 302 redirect?
(Another possibility is that uv is doing application level catching instead of HTTP response caching. That would sidestep the problem entirely, but I don't know if that's actually what's happening.)
I looked into this, and I don't believe uv is doing application-level caching -- it has HTTP caching middleware that (like CacheControl) doesn't cache the HTTP 302 redirect. As far as I can tell uv's caching should also invalidate on URL query changes (there are some places in uv where the query component is removed, but FWICT these don't affect the cache key).
However, to take a step back: can you confirm that what you're seeing is related to the original issue here? Specifically, is your first URL performing a 301 redirect or a 302 redirect?
This is what
pipis doing when I didpip install verysimplemodule===0.0.1the second time (I deleted the package after first install but left the cache untouched)[A] pip request for simple index
[B] pip gets 302 redirect
[C] pip says 302 is NOT in (200, 203, 300, 301, 308)
[D] pip looks up the redirectLocation:header which points to AWS cloudfront pre-signed url (which hasExpiresquery parameter that is constantly changing each this the same AWS cloudfront url is pre-signed
[E] pip found not cache hit for the AWS cloudfront pre-signed url as it considers all query parameters when searching for cache hit
[F] pip downloads the python package from AWS cloudfront pre-signed url2025-07-14T06:07:35,373 Found index url http://packagecloud.localhost/khor/another-repo/pypi/simple/ <====== [A] 2025-07-14T06:07:35,373 Looking up "http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl" in the cache 2025-07-14T06:07:35,373 No cache entry available 2025-07-14T06:07:35,373 No cache entry available 2025-07-14T06:07:35,403 http://packagecloud.localhost:80 "GET /khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl HTTP/1.1" 302 0 <======== [B] 2025-07-14T06:07:35,403 Status code 302 not in (200, 203, 300, 301, 308) <======== [C] 2025-07-14T06:07:35,404 Looking up "https://d3njxchdk64paq.cloudfront.net/development/2/7/pypi/packages/8.whl?Expires=1752474000&Signature=qORpa8TJo3OgXQRdI3ASkvvwQ5OVNBhSX1kUQjkJ964CvYsDxLXr8Dg8w0PraCRchLOP1fw-bO1UWEC7xiHGRYHYvMo27u0mCfnZDhf~q-sxEO9uZdK-Q7QNdRUBGoiveYB87g9HgzKh3G0Im8TuRmdyhpOFXOgdWlZK1JgDZG9vPOvynJjGzazkuIb9S~Wj8YfcTy3ul7hDzIJpfi24VeIP9fG3O9rmQM8cZ1SRmAgPZeC5Y3-zXSn9Hpu2bT346CW7uhmoSdGyqSAcUewZ1vCpo-UpxiJvg~TQ9KkAuYJsVFxFuJY9~bsvkqgLQ82Kad31w-i~bOb6Ym7nnSAJnw__&Key-Pair-Id=K1126YPJP5H8P0" in the cache <======== [D] 2025-07-14T06:07:35,404 No cache entry available <======== [E] 2025-07-14T06:07:35,404 No cache entry available 2025-07-14T06:07:35,876 https://d3njxchdk64paq.cloudfront.net:443 "GET /development/2/7/pypi/packages/8.whl?Expires=1752474000&Signature=pMRpa8TJo3OgXQRdI3ASkvvwQ5OVNBhSX1kUQjkJ964CvYsDxLXr8Dg8w0PraCRchLOP1fw-bO1UWEC7xiHGRYHYvMo27u0mCfnZDhf~q-sxEO9uYzK-Q7QNdRUBGoiveYB87g9HgzKh3G0Im8TuRmdyhpOFXOgdWlZK1JgDZG9vPOvynJjGzazkuIb9S~Wj8YfcTy3ul7hDzIJpfi24VeIP9fG3O9rmQM8cZ1SRmAgPZeC5Y3-zXSn9Hpu2bT346CW7uhmoSdGyqSAcUewZ1vCpo-UpxiJvg~TQ9KkAuYJsVFxFuJY9~bsvkqgLQ82Kad31w-i~bOb6Ym7nnSAJnw__&Key-Pair-Id=K1126YPJP5H8P0 HTTP/1.1" 200 1242 2025-07-14T06:07:35,877 Downloading http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl (1.2 kB) <======== [F]Likewise when using
uvto downloadverysimplemodule===0.0.1the second time (I deleted the package after first install but left the cache untouched):[A] uv request for simple index
[B] uv seems to have found the cached url for simple index, and requested revalidation
[C] uv got modified response for simple index
[D] uv retrieved the newer simple index
[E] uv conclude that there is a cache hit for the python package so no need for redownloadDEBUG Found stale response for: http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ <===== [A] DEBUG Sending revalidation request for: http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ <===== [B] DEBUG Found modified response for: http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ <===== [C] DEBUG Searching for a compatible version of verysimplemodule (>=0.0.1, <0.0.1+) DEBUG Selecting: verysimplemodule==0.0.1 [compatible] (verysimplemodule-0.0.1-py3-none-any.whl) DEBUG Found fresh response for: http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl.metadata <===== [D] DEBUG Tried 2 versions: test 1, verysimplemodule 1 DEBUG all marker environments resolution took 0.408s Resolved 2 packages in 409ms DEBUG Using request timeout of 30s DEBUG Registry requirement already cached: verysimplemodule==0.0.1 <===== [E] Installed 1 package in 2ms + verysimplemodule==0.0.1uv, which is apipalternative on the other hand behavesas expected, i.e., performing cache hit/miss based on just the url without considering the query components/strings.I wasn't aware uv cached HTTP responses at all. I know it caches built packages and other application specific artifacts.
Can you point to what you mean in the uv codebase, prior art of other applications implementing your intended behavior is useful to make informed choices.
@nethsix Thanks for the detailed logs, that's very helpful. Could you re-run the uv one at
TRACE? That might reveal more of the redirects.@notatallshaw Yep, uv uses a subset of the cache-control semantics -- you can see those here (in part): https://github.com/astral-sh/uv/blob/00efde06b61756f0f305fcf67b12db71a29063d3/crates/uv-client/src/httpcache/mod.rs
Thanks for the info.
This is probably obvious to everyone in the discussion but cache control is far more of a general middleware than pip's specific use case, and using http cache as the primary mechanism for catching is probably not perfect for pip, but cache control shouldn't be changed for that purpose.
I'm going to privately ping the uv team in case they have any input on the question of query components.
This is probably obvious to everyone in the discussion but cache control is far more of a general middleware than pip's specific use case, and using http cache as the primary mechanism for catching is probably not perfect for pip, but cache control shouldn't be changed for that purpose.
Yep, agreed -- I also think (barring more evidence) that what CacheControl and pip are doing here is probably more correct, since the observed states (302 redirects and changing queries) are straightforwardly not cacheable at the HTTP layer. But to your point, this is a discrepancy between what pip semantically wants to cache (application-level contents) and what HTTP caching actually enables (responses).
I'm going to privately ping the uv team in case they have any input on the question of query components.
I've already raised it internally 😉
Reacted by Damian Shaw@woodruffw Thanks for recommending running
uvwithTRACE, i.e.,-vvv. Would love you hear your interpretation of it.(test) root@orbstack:/test# uv -vvv --no-config --allow-insecure-host packagecloud.localhost add --cache-dir ./.cache --index=http://packagecloud.localhost/khor/another-repo/pypi/simple very simplemodule==0.0.1 DEBUG uv 0.8.3 DEBUG Found project root: `/test` DEBUG No workspace root found, using project root TRACE Checking lock for `/test` at `/tmp/uv-d01170fa7b5d04fb.lock` DEBUG Acquired lock for `/test` DEBUG Ignoring Python version file at `.python-version` due to `--no-config` DEBUG Using Python request `>=3.11` from `requires-python` metadata DEBUG Checking for Python environment at: `.venv` TRACE Found cached interpreter info for Python 3.11.13, skipping query of: .venv/bin/python3 DEBUG The project environment's Python version satisfies the request: `Python >=3.11` TRACE The project environment's Python version meets the Python requirement: `>=3.11` TRACE The virtual environment's Python interpreter meets the Python preference: `prefer managed` DEBUG Released lock at `/tmp/uv-d01170fa7b5d04fb.lock` TRACE Checking lock for `.venv` at `.venv/.lock` DEBUG Acquired lock for `.venv` DEBUG Using request timeout of 30s DEBUG Found static `pyproject.toml` for: test @ file:///test DEBUG No workspace root found, using project root DEBUG Ignoring existing lockfile due to mismatched requirements for: `test==0.1.0` Requested: {Requirement { name: PackageName("verysimplemodule"), extras: [], groups: [], marker: true, source: Registry { specifier: VersionSpecifiers([VersionSpecifier { operator: Equal, v ersion: "0.0.1" }]), index: None, conflict: None }, origin: None }} Existing: {} TRACE Performing lookahead for test @ file:///test DEBUG Solving with installed Python version: 3.11.13 DEBUG Solving with target Python version: >=3.11 TRACE Assigned packages: TRACE Chose package for decision: root. remaining choices: DEBUG Adding direct dependency: test* INFO add_decision: Id::<PubGrubPackage>(0) @ 0a0.dev0 without checking dependencies TRACE Assigned packages: root==0a0.dev0 TRACE Chose package for decision: test. remaining choices: DEBUG Searching for a compatible version of test @ file:///test (*) DEBUG Adding direct dependency: verysimplemodule>=0.0.1, <0.0.1+ INFO add_decision: Id::<PubGrubPackage>(1) @ 0.1.0 without checking dependencies TRACE Assigned packages: root==0a0.dev0, test==0.1.0 TRACE Chose package for decision: verysimplemodule. remaining choices: TRACE Fetching metadata for verysimplemodule from http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ TRACE Cached request http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ is storable because this is a shared cache and its response has a 'private' cache-control di rective TRACE Freshness lifetime found via cache-control max age setting: 0ns TRACE Cached request http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ has a cached response that does not permit staleness because the response has a 'must-revalidate' cache-control directive set TRACE Request http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ does not have a fresh cache because its age is 103 seconds, it is greater than the freshness lifetime of 0 seconds and stale cached responses are not allowed DEBUG Found stale response for: http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ DEBUG Sending revalidation request for: http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ TRACE Handling request for http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ with authentication policy auto TRACE Request for http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ is unauthenticated, checking cache 18:35:38 [6/1849] TRACE No credentials in cache for URL http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ TRACE Attempting unauthenticated request for http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ TRACE checkout waiting for idle connection: ("http", packagecloud.localhost) DEBUG starting new connection: http://packagecloud.localhost/ TRACE Http::connect; scheme=Some("http"), host=Some("packagecloud.localhost"), port=None DEBUG connecting to 127.0.0.1:80 DEBUG connected to 127.0.0.1:80 TRACE http1 handshake complete, spawning background dispatcher task TRACE waiting for connection to be ready TRACE connection is ready TRACE checkout dropped for ("http", packagecloud.localhost) TRACE put; add idle connection for ("http", packagecloud.localhost) DEBUG pooling idle connection for ("http", packagecloud.localhost) TRACE Resource is modified because status is 200 and not 304 DEBUG Found modified response for: http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ TRACE Cached request http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ is storable because this is a shared cache and its response has a 'private' cache-control directive TRACE Received package metadata for: verysimplemodule TRACE Selecting candidate for verysimplemodule with range >=0.0.1, <0.0.1+ with 1 remote versions DEBUG Searching for a compatible version of verysimplemodule (>=0.0.1, <0.0.1+) TRACE Selecting candidate for verysimplemodule with range >=0.0.1, <0.0.1+ with 1 remote versions TRACE Found candidate for package verysimplemodule with range >=0.0.1, <0.0.1+ after 1 steps: 0.0.1 version TRACE Returning candidate for package verysimplemodule with range >=0.0.1, <0.0.1+ after 1 steps TRACE Found candidate for package verysimplemodule with range >=0.0.1, <0.0.1+ after 1 steps: 0.0.1 version TRACE Returning candidate for package verysimplemodule with range >=0.0.1, <0.0.1+ after 1 steps DEBUG Selecting: verysimplemodule==0.0.1 [compatible] (verysimplemodule-0.0.1-py3-none-any.whl) TRACE idle interval checking for expired TRACE Cached request http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl.metadata is storable because its response has a heuristically cacheable status code 200 TRACE Freshness lifetime heuristically assumed because of presence of last-modified header: 600s DEBUG Found fresh response for: http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl.metadata TRACE Received built distribution metadata for: verysimplemodule==0.0.1 INFO add_decision: Id::<PubGrubPackage>(2) @ 0.0.1 without checking dependencies TRACE Assigned packages: root==0a0.dev0, test==0.1.0, verysimplemodule==0.0.1 DEBUG Tried 2 versions: test 1, verysimplemodule 1 DEBUG all marker environments resolution took 0.198s TRACE Resolution: ResolverEnvironment { kind: Universal { initial_forks: [], markers: true, include: {}, exclude: {} } } TRACE Resolution edge: ROOT -> test TRACE Resolution edge: 0a0.dev0 -> 0.1.0 TRACE Resolution edge: test -> verysimplemodule TRACE Resolution edge: 0.1.0 -> 0.0.1 Resolved 2 packages in 204ms TRACE pool closed, canceling idle interval DEBUG Using request timeout of 30s DEBUG Registry requirement already cached: verysimplemodule==0.0.1 TRACE Extracting file name=PackageName("verysimplemodule") TRACE Extracted 4 files name=PackageName("verysimplemodule") TRACE No entrypoints name=PackageName("verysimplemodule") TRACE No data name=PackageName("verysimplemodule") TRACE Writing installer metadata name=PackageName("verysimplemodule") TRACE Writing record name=PackageName("verysimplemodule") Installed 1 package in 1ms + verysimplemodule==0.0.1 DEBUG Released lock at `/test/.venv/.lock`Thanks @nethsix. Unfortunately that doesn't reveal a lot 😅 -- looks like the cache hits only show up for the pre-redirect URLs and there's no logging of the artifact itself, just the
.metadatavariant.I'm not sure what to make of that. Do the logs vary much when you clear uv's cache entirely?
(I also don't see any signs of authentication or 302 redirects at all in those logs -- could you say more about how you're authenticating to that index?)
@woodruffw I've uninstalled 'verysimplemodule' and deleted the cache dir, and performed
uvinstall again.The order of urls
uvcalls:- http://packagecloud.localhost/khor/another-repo/pypi/simple
- http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule
- http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl.metadata
- This gets 302 redirected to AWS cloudfront
- http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl
- This gets 302 redirected to AWS cloudfront
Logs:
(test) root@orbstack:/test# uv remove verysimplemodule error: The dependency `verysimplemodule` could not be found in `project.dependencies` (test) root@orbstack:/test# rm -rf .cache/ (test) root@orbstack:/test# uv -vvv --no-config --allow-insecure-host packagecloud.localhost add --cache-dir ./.cache --index=http://packagecloud.localhost/khor/another-repo/pypi/simple verysimplemodule==0.0.1 DEBUG uv 0.8.3 DEBUG Found project root: `/test` DEBUG No workspace root found, using project root TRACE Checking lock for `/test` at `/tmp/uv-d01170fa7b5d04fb.lock` DEBUG Acquired lock for `/test` DEBUG Ignoring Python version file at `.python-version` due to `--no-config` DEBUG Using Python request `>=3.11` from `requires-python` metadata DEBUG Checking for Python environment at: `.venv` TRACE Querying interpreter executable at /test/.venv/bin/python3 DEBUG The project environment's Python version satisfies the request: `Python >=3.11` TRACE The project environment's Python version meets the Python requirement: `>=3.11` TRACE The virtual environment's Python interpreter meets the Python preference: `prefer managed` DEBUG Released lock at `/tmp/uv-d01170fa7b5d04fb.lock` TRACE Checking lock for `.venv` at `.venv/.lock` DEBUG Acquired lock for `.venv` DEBUG Using request timeout of 30s DEBUG Found static `pyproject.toml` for: test @ file:///test DEBUG No workspace root found, using project root DEBUG Ignoring existing lockfile due to mismatched requirements for: `test==0.1.0` Requested: {Requirement { name: PackageName("verysimplemodule"), extras: [], groups: [], marker: true, source: Registry { specifier: VersionSpecifiers([VersionSpecifier { operator: Equal, version: "0.0.1" }]), index: None, conflict: None }, origin: None }} Existing: {} TRACE Performing lookahead for test @ file:///test DEBUG Solving with installed Python version: 3.11.13 DEBUG Solving with target Python version: >=3.11 TRACE Assigned packages: TRACE Chose package for decision: root. remaining choices: DEBUG Adding direct dependency: test* INFO add_decision: Id::<PubGrubPackage>(0) @ 0a0.dev0 without checking dependencies TRACE Assigned packages: root==0a0.dev0 TRACE Chose package for decision: test. remaining choices: DEBUG Searching for a compatible version of test @ file:///test (*) DEBUG Adding direct dependency: verysimplemodule>=0.0.1, <0.0.1+ INFO add_decision: Id::<PubGrubPackage>(1) @ 0.1.0 without checking dependencies TRACE Assigned packages: root==0a0.dev0, test==0.1.0 TRACE Chose package for decision: verysimplemodule. remaining choices: TRACE Fetching metadata for verysimplemodule from http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ TRACE No cache entry exists for /test/.cache/simple-v16/index/4d42de747be8addc/verysimplemodule.rkyv DEBUG No cache entry for: http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ TRACE Sending fresh GET request for http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ TRACE Handling request for http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ with authentication policy auto TRACE Request for http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ is unauthenticated, checking cache TRACE No credentials in cache for URL http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ TRACE Attempting unauthenticated request for http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ TRACE checkout waiting for idle connection: ("http", packagecloud.localhost) DEBUG starting new connection: http://packagecloud.localhost/ TRACE Http::connect; scheme=Some("http"), host=Some("packagecloud.localhost"), port=None DEBUG connecting to 127.0.0.1:80 DEBUG connected to 127.0.0.1:80 TRACE http1 handshake complete, spawning background dispatcher task TRACE waiting for connection to be ready TRACE connection is ready TRACE checkout dropped for ("http", packagecloud.localhost) TRACE put; add idle connection for ("http", packagecloud.localhost) DEBUG pooling idle connection for ("http", packagecloud.localhost) TRACE Cached request http://packagecloud.localhost/khor/another-repo/pypi/simple/verysimplemodule/ is storable because this is a shared cache and its response has a ' private' cache-control directive TRACE idle interval checking for expired TRACE Received package metadata for: verysimplemodule TRACE Selecting candidate for verysimplemodule with range >=0.0.1, <0.0.1+ with 1 remote versions TRACE Found candidate for package verysimplemodule with range >=0.0.1, <0.0.1+ after 1 steps: 0.0.1 version TRACE Returning candidate for package verysimplemodule with range >=0.0.1, <0.0.1+ after 1 steps DEBUG Searching for a compatible version of verysimplemodule (>=0.0.1, <0.0.1+) TRACE Selecting candidate for verysimplemodule with range >=0.0.1, <0.0.1+ with 1 remote versions TRACE Found candidate for package verysimplemodule with range >=0.0.1, <0.0.1+ after 1 steps: 0.0.1 version TRACE Returning candidate for package verysimplemodule with range >=0.0.1, <0.0.1+ after 1 steps DEBUG Selecting: verysimplemodule==0.0.1 [compatible] (verysimplemodule-0.0.1-py3-none-any.whl) TRACE No cache entry exists for /test/.cache/wheels-v5/index/4d42de747be8addc/verysimplemodule/0.0.1-py3-none-any.msgpack DEBUG No cache entry for: http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl.metadata TRACE Sending fresh GET request for http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl.metadata TRACE Handling request for http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl.metadata with authentication policy auto TRACE Request for http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl.metadata is unauthenticated, checking cache TRACE No credentials in cache for URL http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl.metadata TRACE Attempting unauthenticated request for http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl.metadata TRACE take? ("http", packagecloud.localhost): expiration = Some(90s) DEBUG reuse idle connection for ("http", packagecloud.localhost) TRACE put; add idle connection for ("http", packagecloud.localhost) DEBUG pooling idle connection for ("http", packagecloud.localhost) DEBUG Received a cross-origin redirect. Removing sensitive headers. DEBUG Received HTTP 302 Found. Redirecting to https://d3njxchdk64paq.cloudfront.net/2/7/blobs/01980711-3457-7e13-9f23-550b8067a729/verysimplemodule20:08:34 [411/1927] .whl.metadata?Expires=1753961014&Signature=lry81VD7nGHsbKjwR7K2etJ8JwIHRgANQPz~judqZ8lmPTcdNe4ebLtq9GVxyS-OgvgUcdUo0~Ai99xs2nGHS~KqDyaAgzLaMRVWle8f9wJKWuSOizF0A-zmYrk FPz5609NcRP7QCVHjDbN7oAFaoof~R5h-ptOKV1wLDREEVgrtdTbuH6-f-h9fM7O-AjxMt-KcNYEs5VB7CdNkNkiBwMCaYh9-CLeZ9lioDPO4SS7rMykmRBTSPJDkL3DR6XHF1wWoytBHBy50pKEHMZ9W2~HkU9sLpRHMn 1DyUtOj28H1ELEgku5HXM-0yJqCYUdtw3FlRdm-x-t-Z7lAsAbgKA__&Key-Pair-Id=K1126YPJP5H8P0 TRACE Handling request for https://d3njxchdk64paq.cloudfront.net/2/7/blobs/01980711-3457-7e13-9f23-550b8067a729/verysimplemodule-0.0.1-py3-none-any.whl.metadata?Expir es=1753961014&Signature=lry81VD7nGHsbKjwR7K2etJ8JwIHRgANQPz~judqZ8lmPTcdNe4ebLtq9GVxyS-OgvgUcdUo0~Ai99xs2nGHS~KqDyaAgzLaMRVWle8f9wJKWuSOizF0A-zmYrkFPz5609NcRP7QCVHjDb N7oAFaoof~R5h-ptOKV1wLDREEVgrtdTbuH6-f-h9fM7O-AjxMt-KcNYEs5VB7CdNkNkiBwMCaYh9-CLeZ9lioDPO4SS7rMykmRBTSPJDkL3DR6XHF1wWoytBHBy50pKEHMZ9W2~HkU9sLpRHMn1DyUtOj28H1ELEgku5H XM-0yJqCYUdtw3FlRdm-x-t-Z7lAsAbgKA__&Key-Pair-Id=K1126YPJP5H8P0 with authentication policy auto TRACE Request for https://d3njxchdk64paq.cloudfront.net/2/7/blobs/01980711-3457-7e13-9f23-550b8067a729/verysimplemodule-0.0.1-py3-none-any.whl.metadata?Expires=175396 1014&Signature=lry81VD7nGHsbKjwR7K2etJ8JwIHRgANQPz~judqZ8lmPTcdNe4ebLtq9GVxyS-OgvgUcdUo0~Ai99xs2nGHS~KqDyaAgzLaMRVWle8f9wJKWuSOizF0A-zmYrkFPz5609NcRP7QCVHjDbN7oAFaoof ~R5h-ptOKV1wLDREEVgrtdTbuH6-f-h9fM7O-AjxMt-KcNYEs5VB7CdNkNkiBwMCaYh9-CLeZ9lioDPO4SS7rMykmRBTSPJDkL3DR6XHF1wWoytBHBy50pKEHMZ9W2~HkU9sLpRHMn1DyUtOj28H1ELEgku5HXM-0yJqCY Udtw3FlRdm-x-t-Z7lAsAbgKA__&Key-Pair-Id=K1126YPJP5H8P0 is unauthenticated, checking cache TRACE No credentials in cache for URL https://d3njxchdk64paq.cloudfront.net/2/7/blobs/01980711-3457-7e13-9f23-550b8067a729/verysimplemodule-0.0.1-py3-none-any.whl.met adata?Expires=1753961014&Signature=lry81VD7nGHsbKjwR7K2etJ8JwIHRgANQPz~judqZ8lmPTcdNe4ebLtq9GVxyS-OgvgUcdUo0~Ai99xs2nGHS~KqDyaAgzLaMRVWle8f9wJKWuSOizF0A-zmYrkFPz5609N cRP7QCVHjDbN7oAFaoof~R5h-ptOKV1wLDREEVgrtdTbuH6-f-h9fM7O-AjxMt-KcNYEs5VB7CdNkNkiBwMCaYh9-CLeZ9lioDPO4SS7rMykmRBTSPJDkL3DR6XHF1wWoytBHBy50pKEHMZ9W2~HkU9sLpRHMn1DyUtOj2 8H1ELEgku5HXM-0yJqCYUdtw3FlRdm-x-t-Z7lAsAbgKA__&Key-Pair-Id=K1126YPJP5H8P0 TRACE Attempting unauthenticated request for https://d3njxchdk64paq.cloudfront.net/2/7/blobs/01980711-3457-7e13-9f23-550b8067a729/verysimplemodule-0.0.1-py3-none-any. whl.metadata?Expires=1753961014&Signature=lry81VD7nGHsbKjwR7K2etJ8JwIHRgANQPz~judqZ8lmPTcdNe4ebLtq9GVxyS-OgvgUcdUo0~Ai99xs2nGHS~KqDyaAgzLaMRVWle8f9wJKWuSOizF0A-zmYrkF Pz5609NcRP7QCVHjDbN7oAFaoof~R5h-ptOKV1wLDREEVgrtdTbuH6-f-h9fM7O-AjxMt-KcNYEs5VB7CdNkNkiBwMCaYh9-CLeZ9lioDPO4SS7rMykmRBTSPJDkL3DR6XHF1wWoytBHBy50pKEHMZ9W2~HkU9sLpRHMn1 DyUtOj28H1ELEgku5HXM-0yJqCYUdtw3FlRdm-x-t-Z7lAsAbgKA__&Key-Pair-Id=K1126YPJP5H8P0 TRACE checkout waiting for idle connection: ("https", d3njxchdk64paq.cloudfront.net) DEBUG starting new connection: https://d3njxchdk64paq.cloudfront.net/ TRACE Http::connect; scheme=Some("https"), host=Some("d3njxchdk64paq.cloudfront.net"), port=None DEBUG connecting to 3.166.208.142:443 DEBUG connected to 3.166.208.142:443 TRACE ALPN negotiated h2, updating pool DEBUG binding client connection DEBUG client connection bound DEBUG send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 } TRACE encoding SETTINGS; len=24 TRACE encoding setting; val=EnablePush(0) TRACE encoding setting; val=InitialWindowSize(2097152) TRACE encoding setting; val=MaxFrameSize(16384) TRACE encoding setting; val=MaxHeaderListSize(16384) TRACE encoded settings rem=33 TRACE inc_window; sz=65535; old=0; new=65535 TRACE inc_window; sz=65535; old=0; new=65535 TRACE Prioritize::new; flow=FlowControl { window_size: Window(65535), available: Window(65535) } TRACE set_target_connection_window; target=5242880; available=65535, reserved=0 TRACE http2 handshake complete, spawning background dispatcher task TRACE put; add idle connection for ("https", d3njxchdk64paq.cloudfront.net) DEBUG pooling idle connection for ("https", d3njxchdk64paq.cloudfront.net) TRACE checkout dropped for ("https", d3njxchdk64paq.cloudfront.net) TRACE connection.state=Open TRACE poll DEBUG send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 } TRACE encoding WINDOW_UPDATE; id=StreamId(0) TRACE encoded window_update rem=46 TRACE inc_window; sz=5177345; old=65535; new=5242880 20:08:34 [363/1927] TRACE poll_complete TRACE schedule_pending_open TRACE queued_data_frame=false TRACE flushing buffer TRACE inc_window; sz=65535; old=0; new=65535 TRACE inc_window; sz=65535; old=0; new=65535 TRACE send_headers; frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }; init_window=65535 TRACE Queue::push_back TRACE -> first entry TRACE drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: HalfClosedLocal(AwaitingHeaders) }, is_counted: false, ref_count: 2, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(65535), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_tas k: None, pending_send: Deque { indices: Some(Indices { head: 0, tail: 0 }) }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: fa lse, next_open: None, is_pending_open: true, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window (65535), available: Window(65535) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pendi ng_recv: Deque { indices: None }, is_recv: true, recv_task: None, push_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData<h2::proto::streams::s tream::NextAccept> }, content_length: Omitted } TRACE transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=0; num_send=0 TRACE connection.state=Open TRACE poll TRACE poll_complete TRACE schedule_pending_open TRACE schedule_pending_open; stream=StreamId(1) TRACE Queue::push_front TRACE -> first entry TRACE requested=0 additional=0 buffered=0 window=65535 conn=65535 TRACE is_pending_reset=false TRACE pop_frame; frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) } TRACE transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; n um_recv=0; num_send=1 TRACE writing frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) } DEBUG send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) } TRACE schedule_pending_open TRACE queued_data_frame=false TRACE flushing buffer TRACE connection.state=Open TRACE poll TRACE read.bytes=27 TRACE decoding frame from 27B TRACE frame.kind=Settings DEBUG received frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 65536, max_frame_size: 16777215 } TRACE recv SETTINGS frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 65536, max_frame_size: 16777215 } DEBUG send frame=Settings { flags: (0x1: ACK) } TRACE encoding SETTINGS; len=0 TRACE encoded settings rem=9 TRACE ACK sent; applying settings TRACE poll TRACE read.bytes=13 20:08:35 [315/1927] TRACE decoding frame from 13B TRACE frame.kind=WindowUpdate DEBUG received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 2147418112 } TRACE recv WINDOW_UPDATE frame=WindowUpdate { stream_id: StreamId(0), size_increment: 2147418112 } TRACE inc_window; sz=2147418112; old=65535; new=2147483647 TRACE poll TRACE read.bytes=9 TRACE decoding frame from 9B TRACE frame.kind=Settings DEBUG received frame=Settings { flags: (0x1: ACK) } TRACE recv SETTINGS frame=Settings { flags: (0x1: ACK) } DEBUG received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 } TRACE update_initial_window_size; new=2097152; old=65535 TRACE incrementing all windows; inc=2031617 TRACE inc_window; sz=2031617; old=65535; new=2097152 TRACE poll TRACE poll_complete TRACE schedule_pending_open TRACE queued_data_frame=false TRACE flushing buffer TRACE connection.state=Open TRACE poll TRACE read.bytes=444 TRACE decoding frame from 444B TRACE frame.kind=Headers TRACE loading headers; flags=(0x4: END_HEADERS) TRACE decode TRACE rem=435 kind=Indexed TRACE rem=434 kind=LiteralWithIndexing TRACE rem=416 kind=LiteralWithIndexing TRACE rem=411 kind=LiteralWithoutIndexing TRACE rem=383 kind=LiteralWithoutIndexing TRACE rem=348 kind=LiteralWithoutIndexing TRACE rem=268 kind=LiteralWithoutIndexing TRACE rem=236 kind=LiteralWithoutIndexing TRACE rem=208 kind=LiteralWithoutIndexing TRACE rem=192 kind=LiteralWithoutIndexing TRACE rem=178 kind=LiteralWithoutIndexing TRACE rem=155 kind=LiteralWithoutIndexing TRACE rem=102 kind=LiteralWithoutIndexing TRACE rem=83 kind=LiteralWithoutIndexing TRACE rem=59 kind=LiteralWithoutIndexing DEBUG received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) } TRACE recv HEADERS frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) } TRACE recv_headers; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) } TRACE opening stream; init_window=2097152 TRACE transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(Streaming) }; is_closed=false; pending_send_empty=true; buffered_s20:08:35 [268/1927] v=0; num_send=1 TRACE poll TRACE read.bytes=535 TRACE decoding frame from 535B TRACE frame.kind=Data DEBUG received frame=Data { stream_id: StreamId(1) } TRACE recv DATA frame=Data { stream_id: StreamId(1) } TRACE recv_data; size=526; connection=5242880; stream=2097152 TRACE send_data; sz=526; window=5242880; available=5242880 TRACE send_data; sz=526; window=2097152; available=2097152 TRACE transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(Streaming) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_rec v=0; num_send=1 TRACE poll TRACE read.bytes=9 TRACE decoding frame from 9B TRACE frame.kind=Data DEBUG received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) } TRACE recv DATA frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) } TRACE recv_data; size=0; connection=5242354; stream=2096626 TRACE send_data; sz=0; window=5242354; available=5242354 TRACE recv_close: HalfClosedLocal => Closed TRACE send_data; sz=0; window=2096626; available=2096626 TRACE transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_s end=1 TRACE dec_num_streams; stream=StreamId(1) TRACE poll TRACE poll_complete TRACE schedule_pending_open TRACE flushing buffer TRACE drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(EndStream) }, is_counted: false, ref_count: 2, next_pending_send: None, is_pendin g_send: false, send_flow: FlowControl { window_size: Window(65535), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: None, pendin g_send: Deque { indices: None }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: false, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(2096626), available: Window(2096626) }, in_ flight_recv_data: 526, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: Some(Indices { head: 1, tail: 2 }) }, is_recv: true, recv_task: None, push_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData<h2::proto::streams::stream::N extAccept> }, content_length: Remaining(0) } TRACE transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_s end=0 TRACE Cached request http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl.metadata is storable because its response h as a heuristically cacheable status code 200 TRACE release_capacity; size=526 TRACE release_connection_capacity; size=526, connection in_flight_data=526 TRACE release_capacity; size=0 TRACE release_connection_capacity; size=0, connection in_flight_data=0 TRACE drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(EndStream) }, is_counted: false, ref_count: 1, next_pending_se20:08:35 [223/1927] g_send: false, send_flow: FlowControl { window_size: Window(65535), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: None, pendin g_send: Deque { indices: None }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: false, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(2096626), available: Window(2097152) }, in_ flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, is_rec v: false, recv_task: None, push_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData<h2::proto::streams::stream::NextAccept> }, content_length: R emaining(0) } TRACE transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_s end=0 TRACE connection.state=Open TRACE poll TRACE poll_complete TRACE schedule_pending_open TRACE flushing buffer TRACE Received built distribution metadata for: verysimplemodule==0.0.1 INFO add_decision: Id::<PubGrubPackage>(2) @ 0.0.1 without checking dependencies TRACE Assigned packages: root==0a0.dev0, test==0.1.0, verysimplemodule==0.0.1 DEBUG Tried 2 versions: test 1, verysimplemodule 1 DEBUG all marker environments resolution took 1.294s TRACE Resolution: ResolverEnvironment { kind: Universal { initial_forks: [], markers: true, include: {}, exclude: {} } } TRACE Resolution edge: ROOT -> test TRACE Resolution edge: 0a0.dev0 -> 0.1.0 TRACE Resolution edge: test -> verysimplemodule TRACE Resolution edge: 0.1.0 -> 0.0.1 Resolved 2 packages in 1.30s TRACE pool closed, canceling idle interval TRACE connection.state=Open DEBUG send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) } TRACE encoding GO_AWAY; code=NO_ERROR TRACE encoded go_away rem=17 DEBUG Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library) TRACE -> already going away TRACE connection.state=Closing(NO_ERROR, Library) TRACE connection closing after flush TRACE queued_data_frame=false TRACE flushing buffer TRACE connection.state=Closed(NO_ERROR, Library) TRACE Streams::recv_eof DEBUG Using request timeout of 30s DEBUG Identified uncached distribution: verysimplemodule==0.0.1 TRACE No cache entry exists for /test/.cache/wheels-v5/index/4d42de747be8addc/verysimplemodule/0.0.1-py3-none-any.http DEBUG No cache entry for: http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl TRACE Sending fresh GET request for http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl TRACE Handling request for http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl with authentication policy auto TRACE Request for http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl is unauthenticated, checking cache TRACE No credentials in cache for URL http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl TRACE Attempting unauthenticated request for http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl TRACE checkout waiting for idle connection: ("http", packagecloud.localhost) 20:08:35 [176/1927] DEBUG starting new connection: http://packagecloud.localhost/ TRACE Http::connect; scheme=Some("http"), host=Some("packagecloud.localhost"), port=None DEBUG connecting to 127.0.0.1:80 DEBUG connected to 127.0.0.1:80 TRACE http1 handshake complete, spawning background dispatcher task TRACE waiting for connection to be ready TRACE connection is ready TRACE checkout dropped for ("http", packagecloud.localhost) TRACE put; add idle connection for ("http", packagecloud.localhost) DEBUG pooling idle connection for ("http", packagecloud.localhost) DEBUG Received a cross-origin redirect. Removing sensitive headers. DEBUG Received HTTP 302 Found. Redirecting to https://d3njxchdk64paq.cloudfront.net/development/2/7/pypi/packages/8.whl?Expires=1753961015&Signature=SeOa1lBIWlytDGZOQ uLkBj2IVYaSu1phvVWZPEc-kOQxEbuILwv~tequB4897yUrxiP8CkPlmyqsIaU6w5lmJ23FHHe3nxgR2Yv28Kg4VCYVdb0I09MPYu6n9e1VOe0lrSoCrt0OpbUUStGOY69ji7zJnUbhD-LCJvh~IPYe9egrzvZ8vUt2MMc UuuBiKF6xkUD9vYVzhs2y3wBc~IBMXcxEZw0pIlBxraNhBgsPCJSjegC0suOs5aGokIObBQpmHNuBmS-9pEDEX1NCvsBWJFGZ1HpcIAaZUggOUQXNmoFvov0BG4SZxHLFxC3g9830cNgkQO5QUmeAEh2TEjWXuQ__&Key- Pair-Id=K1126YPJP5H8P0 TRACE Handling request for https://d3njxchdk64paq.cloudfront.net/development/2/7/pypi/packages/8.whl?Expires=1753961015&Signature=SeOa1lBIWlytDGZOQuLkBj2IVYaSu1phvVWZ PEc-kOQxEbuILwv~tequB4897yUrxiP8CkPlmyqsIaU6w5lmJ23FHHe3nxgR2Yv28Kg4VCYVdb0I09MPYu6n9e1VOe0lrSoCrt0OpbUUStGOY69ji7zJnUbhD-LCJvh~IPYe9egrzvZ8vUt2MMcUuuBiKF6xkUD9vYVzhs 2y3wBc~IBMXcxEZw0pIlBxraNhBgsPCJSjegC0suOs5aGokIObBQpmHNuBmS-9pEDEX1NCvsBWJFGZ1HpcIAaZUggOUQXNmoFvov0BG4SZxHLFxC3g9830cNgkQO5QUmeAEh2TEjWXuQ__&Key-Pair-Id=K1126YPJP5H 8P0 with authentication policy auto TRACE Request for https://d3njxchdk64paq.cloudfront.net/development/2/7/pypi/packages/8.whl?Expires=1753961015&Signature=SeOa1lBIWlytDGZOQuLkBj2IVYaSu1phvVWZPEc-kOQxE buILwv~tequB4897yUrxiP8CkPlmyqsIaU6w5lmJ23FHHe3nxgR2Yv28Kg4VCYVdb0I09MPYu6n9e1VOe0lrSoCrt0OpbUUStGOY69ji7zJnUbhD-LCJvh~IPYe9egrzvZ8vUt2MMcUuuBiKF6xkUD9vYVzhs2y3wBc~IB MXcxEZw0pIlBxraNhBgsPCJSjegC0suOs5aGokIObBQpmHNuBmS-9pEDEX1NCvsBWJFGZ1HpcIAaZUggOUQXNmoFvov0BG4SZxHLFxC3g9830cNgkQO5QUmeAEh2TEjWXuQ__&Key-Pair-Id=K1126YPJP5H8P0 is un authenticated, checking cache TRACE No credentials in cache for URL https://d3njxchdk64paq.cloudfront.net/development/2/7/pypi/packages/8.whl?Expires=1753961015&Signature=SeOa1lBIWlytDGZOQuLkBj2IV YaSu1phvVWZPEc-kOQxEbuILwv~tequB4897yUrxiP8CkPlmyqsIaU6w5lmJ23FHHe3nxgR2Yv28Kg4VCYVdb0I09MPYu6n9e1VOe0lrSoCrt0OpbUUStGOY69ji7zJnUbhD-LCJvh~IPYe9egrzvZ8vUt2MMcUuuBiKF6 xkUD9vYVzhs2y3wBc~IBMXcxEZw0pIlBxraNhBgsPCJSjegC0suOs5aGokIObBQpmHNuBmS-9pEDEX1NCvsBWJFGZ1HpcIAaZUggOUQXNmoFvov0BG4SZxHLFxC3g9830cNgkQO5QUmeAEh2TEjWXuQ__&Key-Pair-Id= K1126YPJP5H8P0 TRACE Attempting unauthenticated request for https://d3njxchdk64paq.cloudfront.net/development/2/7/pypi/packages/8.whl?Expires=1753961015&Signature=SeOa1lBIWlytDGZOQu LkBj2IVYaSu1phvVWZPEc-kOQxEbuILwv~tequB4897yUrxiP8CkPlmyqsIaU6w5lmJ23FHHe3nxgR2Yv28Kg4VCYVdb0I09MPYu6n9e1VOe0lrSoCrt0OpbUUStGOY69ji7zJnUbhD-LCJvh~IPYe9egrzvZ8vUt2MMcU uuBiKF6xkUD9vYVzhs2y3wBc~IBMXcxEZw0pIlBxraNhBgsPCJSjegC0suOs5aGokIObBQpmHNuBmS-9pEDEX1NCvsBWJFGZ1HpcIAaZUggOUQXNmoFvov0BG4SZxHLFxC3g9830cNgkQO5QUmeAEh2TEjWXuQ__&Key-P air-Id=K1126YPJP5H8P0 TRACE checkout waiting for idle connection: ("https", d3njxchdk64paq.cloudfront.net) DEBUG starting new connection: https://d3njxchdk64paq.cloudfront.net/ TRACE Http::connect; scheme=Some("https"), host=Some("d3njxchdk64paq.cloudfront.net"), port=None TRACE idle interval checking for expired DEBUG connecting to 3.166.208.142:443 DEBUG connected to 3.166.208.142:443 TRACE ALPN negotiated h2, updating pool DEBUG binding client connection DEBUG client connection bound DEBUG send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 } TRACE encoding SETTINGS; len=24 TRACE encoding setting; val=EnablePush(0) TRACE encoding setting; val=InitialWindowSize(2097152) TRACE encoding setting; val=MaxFrameSize(16384) TRACE encoding setting; val=MaxHeaderListSize(16384) TRACE encoded settings rem=33 TRACE inc_window; sz=65535; old=0; new=65535 TRACE inc_window; sz=65535; old=0; new=65535 TRACE Prioritize::new; flow=FlowControl { window_size: Window(65535), available: Window(65535) } TRACE set_target_connection_window; target=5242880; available=65535, reserved=0 TRACE http2 handshake complete, spawning background dispatcher task TRACE put; add idle connection for ("https", d3njxchdk64paq.cloudfront.net) DEBUG pooling idle connection for ("https", d3njxchdk64paq.cloudfront.net) TRACE checkout dropped for ("https", d3njxchdk64paq.cloudfront.net) TRACE connection.state=Open TRACE poll DEBUG send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 } TRACE encoding WINDOW_UPDATE; id=StreamId(0) TRACE encoded window_update rem=46 TRACE inc_window; sz=5177345; old=65535; new=5242880 TRACE poll_complete TRACE schedule_pending_open TRACE queued_data_frame=false TRACE flushing buffer TRACE inc_window; sz=65535; old=0; new=65535 TRACE inc_window; sz=65535; old=0; new=65535 TRACE send_headers; frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }; init_window=65535 TRACE Queue::push_back TRACE -> first entry TRACE drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: HalfClosedLocal(AwaitingHeaders) }, is_counted: false, ref_count: 2, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(65535), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_tas k: None, pending_send: Deque { indices: Some(Indices { head: 0, tail: 0 }) }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: fa lse, next_open: None, is_pending_open: true, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window (65535), available: Window(65535) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pendi ng_recv: Deque { indices: None }, is_recv: true, recv_task: None, push_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData<h2::proto::streams::s tream::NextAccept> }, content_length: Omitted } TRACE transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=0; num_send=0 TRACE connection.state=Open TRACE poll TRACE poll_complete TRACE schedule_pending_open TRACE schedule_pending_open; stream=StreamId(1) TRACE Queue::push_front TRACE -> first entry TRACE requested=0 additional=0 buffered=0 window=65535 conn=65535 TRACE is_pending_reset=false TRACE pop_frame; frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) } TRACE transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; n um_recv=0; num_send=1 TRACE writing frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) } DEBUG send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) } TRACE schedule_pending_open 20:08:35 [82/1927] TRACE queued_data_frame=false TRACE flushing buffer TRACE connection.state=Open TRACE poll TRACE read.bytes=27 TRACE decoding frame from 27B TRACE frame.kind=Settings DEBUG received frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 65536, max_frame_size: 16777215 } TRACE recv SETTINGS frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 65536, max_frame_size: 16777215 } DEBUG send frame=Settings { flags: (0x1: ACK) } TRACE encoding SETTINGS; len=0 TRACE encoded settings rem=9 TRACE ACK sent; applying settings TRACE poll TRACE read.bytes=13 TRACE decoding frame from 13B TRACE frame.kind=WindowUpdate DEBUG received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 2147418112 } TRACE recv WINDOW_UPDATE frame=WindowUpdate { stream_id: StreamId(0), size_increment: 2147418112 } TRACE inc_window; sz=2147418112; old=65535; new=2147483647 TRACE poll TRACE read.bytes=9 TRACE decoding frame from 9B TRACE frame.kind=Settings DEBUG received frame=Settings { flags: (0x1: ACK) } TRACE recv SETTINGS frame=Settings { flags: (0x1: ACK) } DEBUG received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 } TRACE update_initial_window_size; new=2097152; old=65535 TRACE incrementing all windows; inc=2031617 TRACE inc_window; sz=2031617; old=65535; new=2097152 TRACE poll TRACE poll_complete TRACE schedule_pending_open TRACE queued_data_frame=false TRACE flushing buffer TRACE connection.state=Open TRACE poll TRACE read.bytes=524 TRACE decoding frame from 524B TRACE frame.kind=Headers TRACE loading headers; flags=(0x4: END_HEADERS) TRACE decode TRACE rem=515 kind=Indexed TRACE rem=514 kind=LiteralWithIndexing TRACE rem=501 kind=LiteralWithIndexing TRACE rem=495 kind=LiteralWithoutIndexing TRACE rem=467 kind=LiteralWithoutIndexing TRACE rem=320 kind=LiteralWithoutIndexing 20:08:35 [32/1927] TRACE rem=292 kind=LiteralWithoutIndexing TRACE rem=268 kind=LiteralWithoutIndexing TRACE rem=206 kind=LiteralWithoutIndexing TRACE rem=190 kind=LiteralWithoutIndexing TRACE rem=176 kind=LiteralWithoutIndexing TRACE rem=153 kind=LiteralWithoutIndexing TRACE rem=100 kind=LiteralWithoutIndexing TRACE rem=81 kind=LiteralWithoutIndexing TRACE rem=57 kind=LiteralWithoutIndexing DEBUG received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) } TRACE recv HEADERS frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) } TRACE recv_headers; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) } TRACE opening stream; init_window=2097152 TRACE transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(Streaming) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_rec v=0; num_send=1 TRACE poll TRACE read.bytes=1251 TRACE decoding frame from 1251B TRACE frame.kind=Data DEBUG received frame=Data { stream_id: StreamId(1) } TRACE recv DATA frame=Data { stream_id: StreamId(1) } TRACE recv_data; size=1242; connection=5242880; stream=2097152 TRACE send_data; sz=1242; window=5242880; available=5242880 TRACE send_data; sz=1242; window=2097152; available=2097152 TRACE transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(Streaming) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_rec v=0; num_send=1 TRACE poll TRACE read.bytes=9 TRACE decoding frame from 9B TRACE frame.kind=Data DEBUG received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) } TRACE recv DATA frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) } TRACE recv_data; size=0; connection=5241638; stream=2095910 TRACE send_data; sz=0; window=5241638; available=5241638 TRACE recv_close: HalfClosedLocal => Closed TRACE send_data; sz=0; window=2095910; available=2095910 TRACE transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_s end=1 TRACE dec_num_streams; stream=StreamId(1) TRACE poll TRACE poll_complete TRACE schedule_pending_open TRACE flushing buffer TRACE drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(EndStream) }, is_counted: false, ref_count: 2, next_pending_send: None, is_pendin g_send: false, send_flow: FlowControl { window_size: Window(65535), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: None, pendin g_send: Deque { indices: None }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: false, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(2095910), available: Window(2095910) }, in_ flight_recv_data: 1242, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: Some(Indice s { head: 1, tail: 2 }) }, is_recv: true, recv_task: None, push_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData<h2::proto::streams::stream:: NextAccept> }, content_length: Remaining(0) } TRACE transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_s end=0 TRACE Cached request http://packagecloud.localhost/khor/another-repo/pypi/packages/verysimplemodule-0.0.1-py3-none-any.whl is storable because its response has an 'ma x-age' cache-control directive TRACE release_capacity; size=1242 TRACE release_connection_capacity; size=1242, connection in_flight_data=1242 TRACE release_capacity; size=0 TRACE release_connection_capacity; size=0, connection in_flight_data=0 TRACE drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(EndStream) }, is_counted: false, ref_count: 1, next_pending_send: None, is_pendin g_send: false, send_flow: FlowControl { window_size: Window(65535), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: None, pendin g_send: Deque { indices: None }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: false, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(2095910), available: Window(2097152) }, in_ flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, is_rec v: false, recv_task: None, push_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData<h2::proto::streams::stream::NextAccept> }, content_length: R emaining(0) } TRACE transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_s end=0 Prepared 1 package in 665ms TRACE Extracting file name=PackageName("verysimplemodule") TRACE Extracted 4 files name=PackageName("verysimplemodule") TRACE No entrypoints name=PackageName("verysimplemodule") TRACE No data name=PackageName("verysimplemodule") TRACE Writing installer metadata name=PackageName("verysimplemodule") TRACE Writing record name=PackageName("verysimplemodule") Installed 1 package in 3ms + verysimplemodule==0.0.1 DEBUG Released lock at `/test/.venv/.lock` TRACE Streams::recv_eof- added a commit that references this issue
on Jan 6, 2026 it would be good to better understand the intended behavior here, since a signed URL strongly suggests that caching shouldn't be done
Pulling back from the tangent on URL components, I am a user and not operator of one of the Python Registries in question, but I believe that I can describe the design intent.
- The Registry provides an index like one would expect.
- The index has links not unlike the PyPI: ex
https://packages.example.com/acme-corp/mirrors/pypi/packages/f1/13/63c0a02c44024ee16f664e0b36eefeb22d54e93531630bd99e237986f534/cowsay-6.1-py3-none-any.whl - (This url must be stable for among other things lockfiles to work)
- The above URL redirects (302) to a signed url to S3 or some other object storage system. The HTTP cache headers align with the time for which the signed url is valid.
The particular use case for this problem is the JFrog Artifactory uses 302 Found responses for signed URLs to cloud storage in HTTP requests to their PYPI proxy cache. Python PIP which leverages the CacheControl library in turn fails to cache those responses and downloads the packages everytime. This is a pain for CI processes which download large packages like PyTorch.
Additionally RFC2616 section 10.3.3 claims the 302 Found HTTP response can be cached if the Cache-Control or Expires response headers are present.