Cached stale binary files generate a 304 exception on successful revalidation

Bug #274815 reported by Leonard Richardson
4
Affects Status Importance Assigned to Milestone
launchpadlib
Triaged
High
Unassigned

Bug Description

The first time I open a binary file it works fine.

send: 'GET /beta/~leonardr/mugshot HTTP/1.1\r\nHost: api.staging.launchpad.net:443\r\nAccept-Encoding: identity\r\nte: deflate, gzip\r\nAuthorization: OAuth realm="https://api.launchpad.net", oauth_nonce="63471975", oauth_timestamp="1222438065", oauth_consumer_key="just testing", oauth_signature_method="PLAINTEXT", oauth_version="1.0", oauth_token="5dxcwV7XbD3tSNl24DHk", oauth_signature="&Mp3Lb7rrRZ6g9zTFcj9SGh3LWFMxKvbv13QLH6LsxXvhk7kNgq0gsMtPPVbMKHw2vC9TmmCwb9bG5q7B"\r\naccept: application/json\r\nuser-agent: Python-httplib2/$Rev: 259 $\r\n\r\n'
reply: ''
send: 'GET /beta/~leonardr/mugshot HTTP/1.1\r\nHost: api.staging.launchpad.net:443\r\nAccept-Encoding: identity\r\nte: deflate, gzip\r\nAuthorization: OAuth realm="https://api.launchpad.net", oauth_nonce="63471975", oauth_timestamp="1222438065", oauth_consumer_key="just testing", oauth_signature_method="PLAINTEXT", oauth_version="1.0", oauth_token="5dxcwV7XbD3tSNl24DHk", oauth_signature="&Mp3Lb7rrRZ6g9zTFcj9SGh3LWFMxKvbv13QLH6LsxXvhk7kNgq0gsMtPPVbMKHw2vC9TmmCwb9bG5q7B"\r\naccept: application/json\r\nuser-agent: Python-httplib2/$Rev: 259 $\r\n\r\n'
reply: 'HTTP/1.1 303 See Other\r\n'
header: Date: Fri, 26 Sep 2008 14:07:46 GMT
header: Server: zope.server.http (HTTP)
header: X-Powered-By: Zope (www.zope.org), Python (www.python.org)
header: X-Content-Type-Warning: guessed from content
header: Content-Length: 0
header: Content-Type: text/plain
header: Location: https://staging.launchpadlibrarian.net/12619694/skull.jpg
header: Via: 1.1 wildcard.staging.launchpad.net
send: 'GET /12619694/skull.jpg HTTP/1.1\r\nHost: staging.launchpadlibrarian.net:443\r\nAccept-Encoding: identity\r\nAuthorization: OAuth realm="https://api.launchpad.net", oauth_nonce="90375050", oauth_timestamp="1222438067", oauth_consumer_key="just testing", oauth_signature_method="PLAINTEXT", oauth_version="1.0", oauth_token="5dxcwV7XbD3tSNl24DHk", oauth_signature="&Mp3Lb7rrRZ6g9zTFcj9SGh3LWFMxKvbv13QLH6LsxXvhk7kNgq0gsMtPPVbMKHw2vC9TmmCwb9bG5q7B"\r\nte: deflate, gzip\r\naccept: application/json\r\nuser-agent: Python-httplib2/$Rev: 259 $\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: Date: Sat, 26 Jul 2008 14:58:28 GMT
header: Server: TwistedWeb/8.0.1
header: Last-Modified: Wed, 12 Mar 2008 21:47:05 GMT
header: Content-Length: 29541
header: Content-Type: image/jpeg
header: X-Cache: MISS from arsenic.canonical.com
header: X-Cache-Lookup: MISS from arsenic.canonical.com:3128
header: Age: 2101
header: X-Cache: HIT from arsenic.canonical.com
header: X-Cache-Lookup: HIT from arsenic.canonical.com:3128
header: Via: 1.0 arsenic.canonical.com:3128 (squid/2.6.STABLE18), 1.0 launchpadlibrarian.net, 1.0 arsenic.canonical.com:3128 (squid/2.6.STABLE18)
header: Via: 1.1 staging.launchpadlibrarian.net
header: Cache-Control: public,max-age=604800
>>> mugshot_handle.last_modified
'Wed, 12 Mar 2008 21:47:05 GMT'

The second time, not so much.

>>> mugshot_handle = mugshot.open()
send: 'GET /beta/~leonardr/mugshot HTTP/1.1\r\nHost: api.staging.launchpad.net:443\r\nAccept-Encoding: identity\r\nte: deflate, gzip\r\nAuthorization: OAuth realm="https://api.launchpad.net", oauth_nonce="06393936", oauth_timestamp="1222439543", oauth_consumer_key="just testing", oauth_signature_method="PLAINTEXT", oauth_version="1.0", oauth_token="5dxcwV7XbD3tSNl24DHk", oauth_signature="&Mp3Lb7rrRZ6g9zTFcj9SGh3LWFMxKvbv13QLH6LsxXvhk7kNgq0gsMtPPVbMKHw2vC9TmmCwb9bG5q7B"\r\naccept: application/json\r\nuser-agent: Python-httplib2/$Rev: 259 $\r\n\r\n'
reply: ''
send: 'GET /beta/~leonardr/mugshot HTTP/1.1\r\nHost: api.staging.launchpad.net:443\r\nAccept-Encoding: identity\r\nte: deflate, gzip\r\nAuthorization: OAuth realm="https://api.launchpad.net", oauth_nonce="06393936", oauth_timestamp="1222439543", oauth_consumer_key="just testing", oauth_signature_method="PLAINTEXT", oauth_version="1.0", oauth_token="5dxcwV7XbD3tSNl24DHk", oauth_signature="&Mp3Lb7rrRZ6g9zTFcj9SGh3LWFMxKvbv13QLH6LsxXvhk7kNgq0gsMtPPVbMKHw2vC9TmmCwb9bG5q7B"\r\naccept: application/json\r\nuser-agent: Python-httplib2/$Rev: 259 $\r\n\r\n'
reply: 'HTTP/1.1 303 See Other\r\n'
header: Date: Fri, 26 Sep 2008 14:32:24 GMT
header: Server: zope.server.http (HTTP)
header: X-Powered-By: Zope (www.zope.org), Python (www.python.org)
header: X-Content-Type-Warning: guessed from content
header: Content-Length: 0
header: Content-Type: text/plain
header: Location: https://staging.launchpadlibrarian.net/12619694/skull.jpg
header: Via: 1.1 wildcard.staging.launchpad.net
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "launchpadlib/resource.py", line 699, in open
    return HostedFileBuffer(self, mode, content_type, filename)
  File "launchpadlib/resource.py", line 724, in __init__
    self.url, True)
  File "launchpadlib/_browser.py", line 221, in get
    response, content = self._request(url)
  File "launchpadlib/_browser.py", line 211, in _request
    raise HTTPError(response, content)
launchpadlib.errors.HTTPError: HTTP Error 304: Ok

httplib2 is supposed to return the cached request (the cache file in this case is staging.launchpadlibrarian.net,12619694,skull.jpg-application,json,201da2a36ecabc4e51fd9af2a5bc2971, and if I remove it the problem goes away), but instead it's either ignoring it or treating the 304 error code as an exception. I suspect this has something to do with the fact that the 304 error code comes after following a redirect, and not in response to the initial request.

Changed in launchpadlib:
importance: Undecided → High
status: New → Triaged
Revision history for this message
Markus Korn (thekorn) wrote :

I think I was faced with the very same bug today, but the strange thing is: I can only reproduce this with an old cache which I've been using since two month. But when I create new cache and run a script to get hosted files twice, I don't get this error.
Please see the attached log as an example:
lines 1-54: reading me.mugshot, using the old cache => reproducing this error
lines 55-75: reading me.mugshot, using "/tmp/new_cache" as cache => works fine
lines 75-80: cache is still there
lines 81-89: reading me.mugshot, using "/tmp/new_cache" as cache => cannot reproduce error

As you can see in the last few lines of the log newly created caches of binary files have "age:"-value in the header, maybe this is a reason why this is fixed.

Revision history for this message
Markus Korn (thekorn) wrote :
Revision history for this message
Markus Korn (thekorn) wrote :
Revision history for this message
Leonard Richardson (leonardr) wrote :

You can only reproduce this with an old cache because the librarian sends a Cache-Control header when it serves a file:

cache-control: public,max-age=604800

That tells httplib2 it's okay to keep the file cached for a week. There's a request httplib2 could make that would trigger the problem, but httplib2 won't make that request until a week after you first get the file. During that week it will retrieve the file's representation from the cache.

I can trigger this error reliably by hacking the max-age header in the cache. Working on a fix now.

Revision history for this message
Leonard Richardson (leonardr) wrote :

The fix is really simple.

=== modified file 'src/lazr/restfulclient/_browser.py'
--- src/lazr/restfulclient/_browser.py 2009-03-26 20:50:28 +0000
+++ src/lazr/restfulclient/_browser.py 2009-04-27 15:38:01 +0000
@@ -200,7 +200,9 @@
         response, content = self._connection.request(
             str(url), method=method, body=data, headers=headers)
         # Turn non-2xx responses into exceptions.
- if response.status // 100 != 2:
+ # 304 ("Not Modified") is okay because it means data was
+ # retrieved from the cache.
+ if response.status // 100 != 2 and response.status != 304:
             raise HTTPError(response, content)
         return response, content

Writing a test for this is not simple at all, because it relies on librarian-specific behavior. I may have to make the fake librarian more like the real librarian.

Revision history for this message
Leonard Richardson (leonardr) wrote :

That fix actually didn't work because some 304 response codes *should* be raised as exceptions. But I've got it working now and am moving on to the test.

Revision history for this message
Leonard Richardson (leonardr) wrote :

After some false starts I've discovered the real reason why this test is so difficult. Here's my analysis. This is not written very well but I need to write it down because I keep forgetting parts of it.

First, let's agree to ignore the Cache-Control wrinkle. That's a complicating factor that only affects how long it is until the problem shows up.

Consider a resource that serves an ETag when you GET it. The first time the client GETs it, lazr.restfulclient stores the ETag and httplib2 caches the representation. The second time it GETs that resource, it sends the ETag as If-None-Match. That is, it makes a conditional request. The conditional request either fails (in which case the response code is 200) or it succeeds (in which case raising an HTTPError is the correct behavior).

Now consider a file from the Launchpad librarian. When you GET this resource it serves Last-Modified but not ETag. lazr.restfulclient ignores Last-Modified, but httplib2 sends Last-Modified. The response is 304, and httplib2 retrieves the document from the cache.

But lazr.restfulclient doesn't think it's making a conditional request! Remember, there was no ETag. lazr.restfulclient gets the 304 and raises an exception, as it does in the 'normal' base. But since the code didn't think it was making a conditional request, there's no code to catch this exception and handle it correctly.

Every one of the lazr.restful resources serves an ETag, so I can't duplicate this problem with our existing lazr.restful example service. The right thing to do is to create a strange librarian-like resource in the example service that serves Last-Modified but not ETag. I might be able to make the fake librarian do this.

Then I can test the fix given above.

While diagnosing this I considered whether we should have lazr.restfulclient send If-Modified-Since in addition to If-None-Match. I don't think that makes sense right now: it would make sense if we had an http_modified_since field in entires, in addition to the http_etag we have in entries now. Until then, I think it makes perfect sense to have httplib2 handle If-Modified-Since. We're not wasting any bandwidth now.

Revision history for this message
Leonard Richardson (leonardr) wrote :

This is annoying. I think I've duplicated the requests with the example web service. I made the lazr.restful file manager stop serving ETags and made it capable of checking If-Modified-Since to detect a conditional GET.

Now my lazr.restful client makes a
---
GET /1.0/cookbooks/Everyday%20Greens/cover

HTTP/1.0 303 See Other
Location: http://cookbooks.dev/1.0/filemanager/0
---
GET /1.0/filemanager/0
if-modified-since: 2009-04-28T08:15:45.495289

HTTP/1.0 304 Not Modified
---

But according to lazr.restful the response code is 200, and the buggy code is not triggered.

In fact, this is the behavior I'd expect. httplib2 retrieves the cached response and gives it to lazr.restful. Not only does it give lazr.restful the cached data, it gives the cached response code. As far as lazr.restful is concerned, the request went through and the response code was 200 and here's the data. It doesn't have to handle the 304.

But for some reason, the behavior on the real Launchpad site is different. I'm trying to figure out the difference now.

summary: - Cached binary files aren't retrieved from cache
+ Cached stale binary files generate a 304 exception on successful
+ revalidation
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.