Cached stale binary files generate a 304 exception on successful revalidation

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.

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.

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.

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.

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.

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.