Cache Deserialization (part two) -- warning message incorrect? #209

kratsg · 2019-08-27T15:17:56Z

This is related to #148 - but I would prefer not to necro. I'm seeing this repeatedly when I make the same request over and over again. I'll detail everything I'm using right now.

(stare) $ python --version
Python 3.7.3
(stare) $ pip --version
pip 19.2.3 from /Users/kratsg/.virtualenvs/stare/lib/python3.7/site-packages/pip (python 3.7)

Package             Version   Location               
------------------- --------- -----------------------
appdirs             1.4.3     
aspy.yaml           1.3.0     
atomicwrites        1.3.0     
attrs               19.1.0    
bandit              1.6.2     
betamax             0.8.1     
betamax-serializers 0.2.1     
black               19.3b0    
bleach              3.1.0     
bumpversion         0.5.3     
CacheControl        0.12.5    
certifi             2019.6.16 
cfgv                2.0.1     
chardet             3.0.4     
Click               7.0       
coverage            4.5.4     
docutils            0.15.2    
ecdsa               0.13.2    
future              0.17.1    
gitdb2              2.0.5     
GitPython           3.0.2     
identify            1.4.6     
idna                2.8       
importlib-metadata  0.19      
lockfile            0.12.2    
more-itertools      7.2.0     
msgpack             0.6.1     
nodeenv             1.3.3     
packaging           19.1      
pbr                 5.4.2     
pip                 19.2.3    
pkginfo             1.5.0.1   
pluggy              0.12.0    
pre-commit          1.18.2    
py                  1.8.0     
pyasn1              0.4.6     
pyflakes            2.1.1     
Pygments            2.4.2     
pyparsing           2.4.2     
pytest              5.1.1     
pytest-cov          2.7.1     
pytest-mock         1.10.4    
python-dotenv       0.10.3    
python-jose         3.0.1     
PyYAML              5.1.2     
readme-renderer     24.0      
requests            2.22.0    
requests-toolbelt   0.9.1     
rsa                 4.0       
setuptools          41.2.0    
six                 1.12.0    
smmap2              2.0.5     
stare               0.0.2     /Users/kratsg/stare/src
stevedore           1.30.1    
toml                0.10.0    
tqdm                4.35.0    
twine               1.13.0    
urllib3             1.25.3    
virtualenv          16.7.4    
wcwidth             0.1.7     
webencodings        0.5.1     
wheel               0.33.6    
zipp                0.6.0

Whenever I make the same request over and over (no warning the first time when there's no cache) but on subsequent requests, I get a warning...

cache entry deserialization failed, entry ignored (controller.py:147)

which indicates this line here: https://github.com/ionrock/cachecontrol/blob/0234b80/cachecontrol/controller.py#L147

So I'm going manually through the steps to find where the crash/error is. I see that we're using v4 so msgpack is being used:

>>> from cachecontrol.serialize import Serializer
>>> s = Serializer()
>>> data = open('.webcache/6/0/a/6/d/60a6d7942f39f888d6dc7b3a89964aea0a63c8f708eef2bdefd601be', 'rb').read()
>>> s.loads('', data)

No error there, so digging in more (given that there's no error on the empty request, I suspect it is not related to the cache but to the request itself...). So reverse-engineering what serialize.py is doing:

>>> ver, data = data.split(b",", 1)
>>> ver
b'cc=4'
>>> ver = ver.split(b"=", 1)[-1].decode("ascii")
>>> ver
'4'
>>> cached = msgpack.loads(data, raw=False)
>>> cached
{'response': {'body': b'<body suppressed for now>', 'headers': {'Date': 'Tue, 27 Aug 2019 14:51:20 GMT', 'Server': 'Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips mod_fcgid/2.3.9 PHP/5.4.16', 'Vary': 'Authorization,Accept-Encoding,User-Agent', 'X-Powered-By': 'PHP/5.4.16', 'Set-Cookie': 'PHPSESSID=<COOKIE>; path=/', 'Expires': 'Thu, 19 Nov 1981 08:52:00 GMT', 'Cache-Control': 'private', 'Pragma': 'no-cache', 'Access-Control-Allow-Origin': '*', 'Access-Control-Allow-Headers': 'API-KEY, Authorization', 'Access-Control-Allow-Methods': 'GET, POST, PUT, DELETE', 'Content-Encoding': 'gzip', 'Content-Length': '45806', 'Keep-Alive': 'timeout=5, max=100', 'Connection': 'Keep-Alive', 'Content-Type': 'application/json'}, 'status': 200, 'version': 11, 'reason': 'OK', 'strict': 0, 'decode_content': False}, 'vary': {'Authorization': 'Bearer <BEARER TOKEN>', 'Accept-Encoding': 'gzip, deflate', 'User-Agent': 'python-requests/2.22.0'}}

So now I prep a request to compare against to see how cachecontrol works in the prepare_response section

To do this part, I just insert pdb into the relevant section and just evaluate specific lines, but I found out that the problem is that the headers didn't match (and in fact, I'm making different requests since the Bearer Token changed between requests when I submit repeatedly since I'm not caching the access tokens).

https://github.com/ionrock/cachecontrol/blob/0234b80/cachecontrol/serialize.py#L115-L119

So what ends up happening, to me, is that the warning message being spit out is not very clear at all. In fact, it just (in this case) means that the headers didn't match -- so the cache should be rebuilt. That is cache deserialization did not fail.

The text was updated successfully, but these errors were encountered:

thatch · 2024-02-15T03:51:06Z

I've seen this too; the simplest way to repro is to send a request to an endpoint that serves a Vary: Accept response header, and then send a different Accept request header the second time. It looks to me that the None signals both a corrupt or unacceptable cached resource, and the simplest thing to do is just remove the warning message.

import logging
logging.basicConfig(level=logging.WARNING)

from cachecontrol import CacheControlAdapter
from cachecontrol.caches import SeparateBodyFileCache
from requests.adapters import HTTPAdapter
from requests.sessions import Session

cache_dir = "foo"
sess = Session()
cache_adapter = CacheControlAdapter(
    cache=SeparateBodyFileCache(cache_dir)
)
sess.mount("https://", cache_adapter)

sess.get("https://pypi.org/simple/cachecontrol", headers={"Accept": "text/html"})
sess.get("https://pypi.org/simple/cachecontrol", headers={"Accept": "application/vnd.pypi.simple.v1+json"})

dvershinin · 2024-02-15T12:05:45Z

@thatch Is your solution just requesting same resource twice with different Accept? I don't understand, can you elaborate?

thatch · 2024-02-15T16:15:40Z

@dvershinin sorry I wasn't clear -- that's just a simple repro, against a well-behaved server, showing the server using Vary: Accept is enough to trigger this message.

kratsg · 2024-02-15T22:19:24Z

My understanding based on @thatch's reproduction, is that there are perhaps certain keys or fields in the header that do not necessarily change the response from the server (for example the Accept could change the response, and so Vary: Accept is used to tell the cache that you need to also cache based on the value of the header's Accept). My guess is that cachecontrol is not ignoring most of the header fields (and not relying on Vary which admittedly is probably not as well-known?).

Particularly @thatch is expecting two separate caches to be made, rather than trying to (re)use the text/html cache for the json one.

thatch mentioned this issue Feb 15, 2024

Quiet down cachecontrol warnings hdeps/hdeps#7

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Cache Deserialization (part two) -- warning message incorrect? #209

Cache Deserialization (part two) -- warning message incorrect? #209

kratsg commented Aug 27, 2019 •

edited

Loading

thatch commented Feb 15, 2024 •

edited

Loading

dvershinin commented Feb 15, 2024

thatch commented Feb 15, 2024

kratsg commented Feb 15, 2024

Cache Deserialization (part two) -- warning message incorrect? #209

Cache Deserialization (part two) -- warning message incorrect? #209

Comments

kratsg commented Aug 27, 2019 • edited Loading

thatch commented Feb 15, 2024 • edited Loading

dvershinin commented Feb 15, 2024

thatch commented Feb 15, 2024

kratsg commented Feb 15, 2024

kratsg commented Aug 27, 2019 •

edited

Loading

thatch commented Feb 15, 2024 •

edited

Loading