Closed Bug 456996 Opened 16 years ago Closed 15 years ago

After 304 browser doesn't send "If-None-Match" or "If-Modified-Since" (resulting in a cycle of 200->304->200->304->etc).

Categories

(Core :: Networking, defect)

Product:
Core
Component:
Networking
Platform:
x86
Windows XP
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED INVALID

People

(Reporter: adam.luter, Unassigned)

Details

(Whiteboard: [firebug-p1])

Attachments

(1 file)

Test case extension
1.93 KB, application/x-xpinstall
Details 
User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.2) Gecko/2008091620 Firefox/3.0.2
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.2) Gecko/2008091620 Firefox/3.0.2

I came in today to report something similar.  I make this request:

Host: aluter.ath.cx:3100
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.2)
Gecko/2008091620 Firefox/3.0.2
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive

I serve the following response:

Connection: close
Date: Wed, 24 Sep 2008 20:00:35 GMT
Status: 200 OK
X-Runtime: 0.27049
Etag: "19590867d00773f3bf67809c03f38775"
Cache-Control: max-age=0, must-revalidate
Server: Mongrel 1.1.5
Content-Type: application/xml; charset=utf-8
Content-Length: 25044

(please note the Cache-Control directive has no effect on the reported
behaviour, but also note that the ETag is set).

Reloading the page (my preferred method is to select the url bar and hit enter)
generates the expected request and response:

Host: aluter.ath.cx:3100
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.2)
Gecko/2008091620 Firefox/3.0.2
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
If-None-Match: "19590867d00773f3bf67809c03f38775"

Response:

Date: Wed, 24 Sep 2008 20:05:17 GMT
Status: 304 Not Modified
X-Runtime: 0.28660
Etag: "19590867d00773f3bf67809c03f38775"
Cache-Control: max-age=0, must-revalidate
Server: Mongrel 1.1.5
Content-Type: application/xml; charset=utf-8
Content-Length: 25044

Please note that the 304, as expected, is returned due to the request having an
"If-None-Matched".

*However*, upon a 3rd reload:

Host: aluter.ath.cx:3100
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.2)
Gecko/2008091620 Firefox/3.0.2
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive

And the response:

Connection: close
Date: Wed, 24 Sep 2008 20:06:54 GMT
Status: 200 OK
X-Runtime: 0.38690
Etag: "19590867d00773f3bf67809c03f38775"
Cache-Control: max-age=0, must-revalidate
Server: Mongrel 1.1.5
Content-Type: application/xml; charset=utf-8
Content-Length: 25044

As you can see, the browser fails to send the "If-None-Match" on the 3rd
request.  The server, appropriately has no choice but to send a 200.  Oddly,
the client does send it for the 4th, 6th, etc. responses.  (So, it seems to
forget the Etag after receiving a 304?).

This has been tested on Firefox 2 to *not* exhibit this behaviour (just works
correctly).  But on Firefox 3 (tested with 3.0.2 and 3.1a2) the behaviour above
does exist consistently.

I've tried to add and remove various headers, but the basic behaviour remains. 
The best I can do is add an expiration (via "Expires" or "max-age") which
causes the request to not happen at all (as expected).  However, I would like
proper 304 behaviour as seen in FF2.

Additionally the copy of 3.1a2 was a fresh install on a fresh copy of XP (an
IE7 testing VPC).  And the copy of 3.0.2 wasn't so fresh, but I tried with and
without add-ons enabled (still XP).

I'm going to assume it's you not me, and continue on my development way!  Let
me know if there is anything else I can do or have failed to provide.

Reproducible: Always

Steps to Reproduce:
1. Serve content with ETag. (preferably without Expires to ease testing)
2. Enter URL in browser (hit enter)
3. Click URL bar (hit enter)
4. Repeat 3 and notice cycle of 200 / 304's.
Actual Results:  
200 on first request, 304 on second.  However 200 on 3rd request, 304 on 4th, etc.

Expected Results:  
200 on first request, 304 on all following.
Hello,

I had the same problem, but on a clean Firefox (with just the extension "Live HTTP Headers") I can't reproduce it.
After some checks, it seems that the problem come from the extension "Firebug".

Do the problem come from Firebug for you too ?
I've filed this bug in the Firebug tracker: http://code.google.com/p/fbug/issues/detail?id=1274
As I reported there, it's just enough for me to disable the net panel to get everything back to normality.
Attached file Test case extension — 
I was looking at the Firebug reported issue and I think that the problem is caused when Firefox cache is accessed using nsICacheService. Specifically when asyncOpenCacheEntry/openCacheEntry methods are used.

I am attaching a test extension that can be used to reproduce the problem.
Here is what you have to do.

0) I was testing with Shiretoko 3.5b4pre (but the same problem is in 3.0.10)
1) Install the extension and enable console logging (dump is used in the code)
2) Start firefox and load http://www.janodvarko.cz/firebug/tests/1274/Issue1274.htm
3) Clear Cache
4) Refresh the page. See system console two responses should be displayed, both with 200 OK status
5) Refresh the page again. Now both requests should say 304 Not Modified
6) Refresh the page again. Both should be still 304 Not Modified, but it's 200 OK - BUG!

If you take a look at the source code (test.js) you can fix the problem by removing two lines marked with xxxHonza (line 49 and  55)

Honza
Whiteboard: [firebug-p1]
sorry I didn't bring this up sooner. Can we get some networking eyes on this?
Flags: wanted-firefox3.5?
Flags: blocking-firefox3.5?
Networking guys: please to be taking looksee ASAP, danke!
Using the steps in comment 3, I did the following:

1)  Installed that test extension in an m-c build (after editing the maxVersion).
2)  Cleared cache.
3)  Loaded http://www.janodvarko.cz/firebug/tests/1274/Issue1274.htm
4)  Focused url bar, hit enter
5)  Focused url bar, hit enter

Output:

  http://www.janodvarko.cz/firebug/tests/1274/Issue1274.htm: 200 OK
  ===================================
  ===================================
  ===================================
  ===================================
  http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php: 304 Not Modified
  ===================================

how do I reproduce the bug with that extension, exactly?

Note that I get similar behavior when clicking the reload button instead of hitting enter in the url bar.
Yes, I think firebug was the culprit here.  I have not noticed it recently.
Adam: yes, it's an incompatibility with Firebug, but it might be due to something we did.

Rob/JJB: anything to add beyond Honza's comment 3?
--> Core::Networking
Component: General → Networking
Flags: wanted-firefox3.5?
Flags: blocking-firefox3.5?
Product: Firefox → Core
QA Contact: general → networking
Flags: blocking1.9.2?
> how do I reproduce the bug with that extension, exactly?

Note that you need Firefox 3.5pre (the test case is using a new
http-on-examine-cached-response event)

I have been just re-checking the test-case extension and I am a bit confused
since I can't reproduce the problem with the online test page (at
www.janodvarko.cz). Anyway I still see the problem if I am using my local HTTP
server (Apache/2.2.11 (Win32) PHP/5.2.8) with the exactly same page.

Could this be a problem with the local server configuration?

- When refreshing the page (I am clicking the reload button), I am seeing
mostly an output saying:
http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php: 200 OK
http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php: 200 OK
http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php: 200 OK

The page should be cached and it is not.

- If you remove getCacheEntry method from the test case(line 49 and  55)
The log output is mostly like as follows:

http://www.janodvarko.cz/firebug/tests/1274/Issue1274.htm: 304 Not Modified
http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php: 304 Not Modified
http://www.janodvarko.cz/firebug/tests/1274/Issue1274.htm: 304 Not Modified
http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php: 304 Not Modified
http://www.janodvarko.cz/firebug/tests/1274/Issue1274.htm: 304 Not Modified
http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php: 304 Not Modified

This is correct, both requests are loaded properly from the cache.


The difference is that if the getCacheEntry method is removed the
nsICacheSession.asyncOpenCacheEntry isn't called.

Honza
> the test case is using a new http-on-examine-cached-response event)

As I said, I'm using a build that has that event.

I really can't tell you what's wrong with your local server; all I can tell you is that I can't reproduce the bug given your steps to reproduce, which makes it hard to tell you anything useful about the firebug behavior.

That said, is that testcase an accurate representation of what firebug does (complete with not closing the cache entry after opening it)?
> I really can't tell you what's wrong with your local server; all I can tell you
> is that I can't reproduce the bug given your steps to reproduce, which makes it
> hard to tell you anything useful about the firebug behavior.

Yes, sorry, my online test-page is obviously somehow wrong. Anyway, there is another page here: http://www.clubdeportivo.es/etag.htm
that I can successfully use to reproduce the behavior (using the same attached extension).

Here is what I do:

1) Install the extension and load http://www.clubdeportivo.es/etag.htm

2) Refresh the page a few times (I am clicking the toolbar button). You can see that only css.axd and js.axd files are still returned with 200 OK. All the other files are properly stored within the browser cache and the response for them is 304 Not Modified.

The console shows:
http://www.clubdeportivo.es/apariencia/css.axd?files=reservas.css: 200 OK
http://www.clubdeportivo.es/js.axd?files=WebResource.axd?d=9BUhK5RmCUrK43r0WC7PEyUwhG1OqtPf1kRe9VRM-a6pmbHZOC1UAyB73GkuX
nC40&t=633627123510000000: 200 OK

3) Remove the 49 and 55 lines from the test-extension (getCacheEntry).

4) Restart Firefox, load the page and refresh a few times again. In my case, all files (include css.axd and js.axd) are stored properly in the cache and the response is always 304 (perhaps apart from the first request if you clean the cache).

The console says:
http://www.clubdeportivo.es/apariencia/css.axd?files=reservas.css: 304 Not Modified
http://www.clubdeportivo.es/js.axd?files=WebResource.axd?d=9BUhK5RmCUrK43r0WC7PEyUwhG1OqtPf1kRe9VRM-a6pmbHZOC1UAyB73Gku
nC40&t=633627123510000000: 304 Not Modified



> That said, is that testcase an accurate representation of what firebug does
> (complete with not closing the cache entry after opening it)?
This is good hint. Firebug is not calling markValid (note that all entries are always opened with ACCESS_READ), but using this method doesn't solve the problem.


Honza
> Firebug is not calling markValid

No, I meant closing the cache entry.  Like calling close() on the descriptor when done with it...

I can reproduce the problem using the steps in comment 12, and the close() call doesn't help.  Looking into it now.
Status: UNCONFIRMED → NEW
Ever confirmed: true
Er, actually I didn't test quite right.  Calling close() on the descriptor when done with it does in fact fix the issue.  Firebug should be doing that, instead of relying on it to be closed when gc happens to maybe come through and the object is deallocated.
Status: NEW → RESOLVED
Closed: 15 years ago
Resolution: --- → INVALID
Sounds great, but still not success on my side. 

I do the following in the test extension:
onCacheEntryAvailable: function(descriptor, accessGranted, status)
{
    dump("===================================\n");
    descriptor.close();
}

...and I am still seeing 200 OK for css.axd and js.axd

Is this the correct way how to close the descriptor?
Honza
That's exactly what I did, and it makes me see 304s for the css and js files in that testcase...  let me test again just to make sure.
OK, and now I'm getting 200s.  Digging some more...
Status: RESOLVED → REOPENED
Resolution: INVALID → ---
(In reply to comment #14)
> Er, actually I didn't test quite right.  Calling close() on the descriptor when
> done with it does in fact fix the issue.  Firebug should be doing that, instead
> of relying on it to be closed when gc happens to maybe come through and the
> object is deallocated.

The problem really seems to be that the entry keeps opened. There is something wrong in firebug when nsHttpChannel opens the entry again before it is closed. Here is the log:

nsHttpChannel opens the cache entry:
-134486176[f7c19060]: Opening entry for session e9f70880, key http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php, mode 3, blocking 0
-134486176[f7c19060]: Created request e9f708a0
-134486176[f7c19060]: Activate entry for request e9f708a0
-134486176[f7c19060]: Active entry for request e9f708a0 is 0
-134486176[f7c19060]: mMemoryDevice: 0x0
-134486176[f7c19060]: Device search for request e9f708a0 returned e9f356f0
-134486176[f7c19060]: Added entry e9f356f0 to mActiveEntries
-134486176[f7c19060]: got cache entry [access=3]

nsHttpChannel closes the entry:
-134486176[f7c19060]: nsHttpChannel::CloseCacheEntry [this=edb97e30]
-134486176[f7c19060]: Deactivating entry e9f356f0
-134486176[f7c19060]: Removed deactivated entry e9f356f0 from mActiveEntries

Firebug opens the entry:
-134486176[f7c19060]: Opening entry for session e9f29620, key http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php, mode 1, blocking 1
-134486176[f7c19060]: Created request e9f70940
-134486176[f7c19060]: Activate entry for request e9f70940
-134486176[f7c19060]: Active entry for request e9f70940 is 0

Honza's extension opens the entry:
-134486176[f7c19060]: Opening entry for session f446b540, key http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php, mode 1, blocking 1
-134486176[f7c19060]: Created request edb7cac0
-134486176[f7c19060]: Activate entry for request edb7cac0
-134486176[f7c19060]: Active entry for request edb7cac0 is e9f35d80

nsHttpChannel opens the entry again (click on reload fast enough before the entry is closed):
-134486176[f7c19060]: Opening entry for session edb84700, key http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php, mode 3, blocking 0
-134486176[f7c19060]: Created request edb84720
-134486176[f7c19060]: Activate entry for request edb84720
-134486176[f7c19060]: Active entry for request edb84720 is e9f35d80
-134486176[f7c19060]: got cache entry [access=1]

nsHttpChannel got the same readonly entry as firebug. Is this OK?

Then firebug keeps opening the entry every second:

-134486176[f7c19060]: Opening entry for session e9f29620, key http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php, mode 1, blocking 0
-134486176[f7c19060]: Created request f306b4c0
-134486176[f7c19060]: Activate entry for request f306b4c0
-134486176[f7c19060]: Active entry for request f306b4c0 is e9f35d80
-134486176[f7c19060]: nsHttpHandler::NewURI
-134486176[f7c19060]: nsHttpHandler::NewURI
-134486176[f7c19060]: Opening entry for session f446b540, key http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php, mode 1, blocking 1
-134486176[f7c19060]: Created request f30ee160
-134486176[f7c19060]: Activate entry for request f30ee160
-134486176[f7c19060]: Active entry for request f30ee160 is e9f35d80
-134486176[f7c19060]: Opening entry for session e9f29620, key http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php, mode 1, blocking 0
-134486176[f7c19060]: Created request f30ee0e0
-134486176[f7c19060]: Activate entry for request f30ee0e0
-134486176[f7c19060]: Active entry for request f30ee0e0 is e9f35d80
-134486176[f7c19060]: Opening entry for session e9f29620, key http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php, mode 1, blocking 0
-134486176[f7c19060]: Created request f30ee2a0
-134486176[f7c19060]: Activate entry for request f30ee2a0
-134486176[f7c19060]: Active entry for request f30ee2a0 is e9f35d80
-134486176[f7c19060]: Opening entry for session e9f29620, key http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php, mode 1, blocking 0
-134486176[f7c19060]: Created request f30ee7a0
-134486176[f7c19060]: Activate entry for request f30ee7a0
-134486176[f7c19060]: Active entry for request f30ee7a0 is e9f35d80
-134486176[f7c19060]: Opening entry for session e9f29620, key http://www.janodvarko.cz/firebug/tests/1274/Issue1274.php, mode 1, blocking 0
-134486176[f7c19060]: Created request f30eea20
-134486176[f7c19060]: Activate entry for request f30eea20

So long as the entry is opened nsHttpChannel returns data only from cache and doesn't validate data on the server because the entry is readonly. The entry is doomed after 30 seconds (this is expiration time of that page) and then nsHttpChannel sends unconditional GET.
OK.  So we have this stack:

#0  nsCacheService::ActivateEntry
#1  0x00da2273 in nsCacheService::ProcessRequest
#2  0x00da3068 in nsCacheService::OpenCacheEntry
#3  0x00da5b3a in nsCacheSession::AsyncOpenCacheEntry

and then we hit this code:

1289     if (entry &&
1290         ((request->AccessRequested() == nsICache::ACCESS_WRITE) ||
1291          ((request->StoragePolicy() != nsICache::STORE_OFFLINE) &&
1292           (entry->mExpirationTime <= SecondsFromPRTime(PR_Now()) &&
1293            request->WillDoomEntriesIfExpired()))))
1294 
1295     {
1296         // this is FORCE-WRITE request or the entry has expired
1297         rv = DoomEntry_Internal(entry);

in our case the |entry| is the one that HTTP is writing to.  AccessRequested() is ACCESS_READ, StoragePolicy() is STORE_ANYWHERE, mExpirationTime is 0 (!), and WillDoomEntriesIfExpired() is true.

WillDoomEntriesIfExpired() is true because that's the default for cache sessions.  See nsICacheSession.idl.

mExpirationTime is 0 (and in fact, the HTTP log tells you so!) because the response has no max-age header, no expires header, no last-modified header, and is not a 300 or 301.  So we log:

324     LOG(("nsHttpResponseHead::ComputeFreshnessLifetime [this = %x] "
325          "Insufficient information to compute a non-zero freshness "
326          "lifetime!\n", this));

and revalidate the entry every time (treat it as always expired).
> nsHttpChannel got the same readonly entry as firebug. Is this OK?

Yes, sorta; we don't support concurrent access to the cache, so as long as there's an outstanding reader you can't get write access.
OK.  So the bug appears if firebug requests a cache entry after it has expired, basically.  At least assuming that Honza's testcase still correctly captures the code Firebug uses.  Since it uses a cache session that dooms expired entries, the moment it requests it the entry is doomed, and then the next http request doesn't get that entry; it gets a brand-new empty entry so has no ETag header to send.

Adding |cacheSession.doomEntriesIfExpired = false;| to the initCacheSession() in that test extension helps here (tested very very carefully this time).

Note that I bet the issue with the other testcase was a matter of which server sends which expiration-related headers... this last page was nice in that it consistently handed out CSS and JS that expires immediately.

Honza, please do reopen if changing firebug to not auto-doom expired entries it gets doesn't fix this for you (and if so, I'd like updated steps to reproduce!).
Status: REOPENED → RESOLVED
Closed: 15 years ago → 15 years ago
Resolution: --- → INVALID
(In reply to comment #21)
> Honza, please do reopen if changing firebug to not auto-doom expired entries it
> gets doesn't fix this for you (and if so, I'd like updated steps to
> reproduce!).

FYI, auto-doom in firebug is set intentionally.

function initCacheSession()
{
    if (!cacheSession)
    {
        var cacheService = CacheService.getService(nsICacheService);
        cacheSession = cacheService.createSession("HTTP", STORE_ANYWHERE, true);

        // xxxHonza setting this to false makes problems with the cache. See Issue 1029.
        //cacheSession.doomEntriesIfExpired = false;
    }
}
OK, then.  It might be that the problem was that it was creating these readonly descriptors and not closing them in a timely manner, which messed up http getting writable entries as discussed in comment 18 and comment 20...  and then that was hacked around by making firebug toss stuff that should still be in cache out of the cache.
Yes, this was the problem. Both test cases now work for me. 
Thank you guys for the help!
Honza
Status: RESOLVED → REOPENED
Resolution: INVALID → ---
Still invalid as a networking bug.  Pilot error, I tell you.  ;)
Status: REOPENED → RESOLVED
Closed: 15 years ago → 15 years ago
Resolution: --- → INVALID
Flags: blocking1.9.2? → blocking1.9.2-
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: