Cache Deserialization (part two) -- warning message ... | psf/cachecontrol

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.

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

Description

Contributor guide

First steps

Research direction

Assessment