330820 - Cached images break after a while via If-Modified-Since / Not Modified

Status: RESOLVED DUPLICATE of bug 321361

(Firefox :: General, defect)

Description

[Tino Didriksen]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.1) Gecko/20060111 Firefox/1.5.0.1
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.1) Gecko/20060111 Firefox/1.5.0.1

[Background]
I have Firefox open pretty much 24/7/365 and restart it about twice a day to clean up memory leakage. I have self-refreshing pages open, in particular html chats such as http://pjj.cc/trial/ (frames are set to 2 minute refresh, though). I reboot maybe once a month. The image service I run for the chats is very aggressive with caching.

A typical first-time request/response would be:

GET /74424d97afa4fb2221d050fddd1b7a67.gif HTTP/1.1
Host: i.pjj.cc
Referer: http://pjj.cc/trial/reader.php

HTTP/1.1 200 OK
Date: Fri, 17 Mar 2006 14:29:55 GMT
Server: Apache
ETag: "74424d97afa4fb2221d050fddd1b7a67"
Content-Length: 8425
Last-Modified: Sat, 01 Jan 2000 11:59:59 GMT
Accept-Ranges: bytes
Connection: close
Vary: User-Agent
Content-Type: image/gif

Of note are the Etag and Last-Modified. The Etag is the md5sum of the image, and Last-Modified is always set to Sat, 01 Jan 2000 11:59:59 GMT regardless of when the image really was modified, since the image is stored in a way that if the data changes so would the filename (md5sum again).

On the other hand, if an If-Modified-Since header is present, the request/response would be:

GET /74424d97afa4fb2221d050fddd1b7a67.gif HTTP/1.1
Host: i.pjj.cc
Referer: http://pjj.cc/trial/reader.php
If-Modified-Since: anything

HTTP/1.1 304 Not Modified
Date: Fri, 17 Mar 2006 14:40:37 GMT
Server: Apache
Connection: close
ETag: "74424d97afa4fb2221d050fddd1b7a67"
Vary: User-Agent

So far so good...

[The Bug]
After 2-4 weeks of displaying the image in the page just fine, the image will display broken placeholder and claim to be corrupted if loaded in a seperate page, and has to be CTRL-F5'ed to load a fresh copy again.

I haven't checked the details of it, but I can only assume that the cached copy has been deleted or flushed out but the browser is still issuing an If-Modified-Since and thus not getting any displayable data.

I haven't had any of the IE users report anything similar, though a few other Firefox users have reported the same. I rule out disk corruption as I've run memtest86 and checked the drive for bad sectors.

(the example URL http://i.pjj.cc/74424d97afa4fb2221d050fddd1b7a67.gif is referer-checked, so can only be loaded if the referer is either blank or matches one of my presets; I've added *bug* to the allowed list for this report)

Reproducible: Sometimes

Steps to Reproduce:

Comment 1

[Brian Scott]

Firefox 1.5.0.1

I have experienced this type of problem several times.
My homepage has an image
http://azdomino.monrovia.com/monroviaweb.nsf/PassionVine.jpg!OpenImageResource
Once in a while, (perhaps once a month) the image will not be shown. I have
_not_ manually deleted cache files. My antivirus _has not_ reported any viruses
or trojans in many months. (and certainly not in this image.)

When I right-click and view image, Firefox reports "File not found" and has a
try again button. Clicking try again or refresh does not get the image.

I ran a packet capture, and get this HTTP conversation when I click try again:

GET /monroviaweb.nsf/PassionVine.jpg!OpenImageResource HTTP/1.1
Host: azdomino.monrovia.com
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.1)
Gecko/20060111 Firefox/1.5.0.1
Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
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
Cookie: zone=8
If-Modified-Since: Wed, 15 Mar 2006 19:48:36 GMT
If-None-Match:
W/"MTAtODA4Ny04ODI1NzEzMjAwNkNEMTdCLTg4MjU3MTE4MDA2RDhCN0MtNkE4NjIxRUY2Q0ZBM0I3MTg4MjU3MTExMDAxQ0FFOTc="
Cache-Control: max-age=0


## and the response:

HTTP/1.1 304 Not Modified
Server: Lotus-Domino
Date: Thu, 23 Mar 2006 17:07:46 GMT
ETag:
W/"MTAtODA4Ny04ODI1NzEzMjAwNkNEMTdCLTg4MjU3MTE4MDA2RDhCN0MtNkE4NjIxRUY2Q0ZBM0I3MTg4MjU3MTExMDAxQ0FFOTc="

The workaround is to shift-F5 to go around the cache, but this should not be
needed. The image will also load if I change the url slightly, such as changing
to a different FQDN that points at the same server, or adding a no-effect
parameter to the query string.

I have seen variations of this bug reported in Bugzilla several times, but they
try to explain it away as a manually deleted cache, or non-Moz programs messing
the cache. I believe this is not the case here. The problem, of course, is
trying to duplicate something that happens maybe once a month. Is it possible
that Firefox starts cleaning a full cache _after_ it decides to use the image
from cache?

Comment 2

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #0)
Following is about:cache entry for your image file.
(Disk cache device)
>           Key: http://i.pjj.cc/74424d97afa4fb2221d050fddd1b7a67.gif
>     Data size: 8425 bytes
> Last modified: 2006-03-24 15:21:26 (NOT Last-Modified: header. My access time)
>       Expires: 2006-11-07 00:23:35 (<= Heuristic Expiration)
(Memory cache device)
>           Key: http://i.pjj.cc/74424d97afa4fb2221d050fddd1b7a67.gif
>     Data size: 63648 bytes
> Last modified: 2006-03-24 15:21:25 (NOT Last-Modified: header. My access time)
>       Expires: 2006-11-07 00:23:32 (<= Heuristic Expiration)

Your server/php doesn't return explicite expiration(no Cache-Control:max-age, no  Expires:), then "Heuristic Expiration" is used.
And since "Last-Modified: Sat, 01 Jan 2000 11:59:59 GMT", the "Heuristic Expiration" became 2006-11-07, 8 months after today.

(In reply to comment #1)
Following is about:cache entry for your image file.
(Disk cache device)
> Key: http://azdomino.monrovia.com/monroviaweb.nsf/PassionVine.jpg!OpenImageResource
>     Data size: 35527 bytes
> Last modified: 2006-03-24 14:49:32 (NOT Last-Modified: header. My access time)
>       Expires: 2006-03-25 11:01:37 (<= Heuristic Expiration)
(Memory cache device)
> Key: http://azdomino.monrovia.com/monroviaweb.nsf/PassionVine.jpg!OpenImageResource
>     Data size: 782400 bytes
> Last modified: 2006-03-24 14:49:13 (NOT Last-Modified: header. My access time)
>       Expires: 2006-03-25 11:01:15 (<= Heuristic Expiration)

Your server doen't return explicite expiration too, and "Heuristic Expiration" is used.

See Bug 328605. See also Bug 221036. 

If expiration is set very long, probability of purge(push out) from cache before expiration due to cache space shortage/limitation increases. I also suspect something wrong such as partial purge in special occasions, e.g. cache entry for decompressed data(memory cache usually) and/or compressed data(disk cache usually) is purged but cache entry for control is not purged cleanly (maybe affected by bfcache). And I guess :
  This usually doesn't cause problem because expiration occurs sooner or later,
  and usual HTTP GET(without If-Mofified-Since:) is issued. 
  But if long expiration, it doesn't expire for long time, then problem appears.
  - HTTP GET is issued because no cached data, but becomes HTTP GET with
    If-Modified-Since due to garbage of un-expired date, then gets 304 response.

Question to Tino Didriksen & Brian Scott : 

(Q1) What is your cache setting(about:config)?
     browser.cache.check_doc_frequency
       3 : When the page is out of date (default of Firefox)
           (= Check with If-Modified-Since when cached data is expired)
       1 : Every time I view the page
           (= Check with If-Modified-Since always)    

(Q2) When problem occurs, what is about:cache status for the image file?
     (probably no entry is displayed by about:cache)
     When problem occurs, HTTP GET with If-Modified-Since: is issued?
     (comment #1 already says 'YES' for this question.)

     HTTP header log can be obtained by NSPR log or LiveHTTPHeaders.
     See Bug 221036 Comment #7 & Bug 221036 Comment #6.

(Q3) Can returning "Cache-Control:max-age=xx"(where xx is not so large)
     reduce probability that your problem occurs?
     There are two ways:
     - Setting in .htaccess or Apache's parameter settings.
     - Change xxxxx.gif to xxxxx.php, and call header('Cache-Control: ...'),
       and call header() for other headers, then call readfile('xxxxx.gif').

Comment 3

[Brian Scott]

Q1: browser.cache.check_doc_frequency = 3 (The default)
Q2: I will have to wait until it happens again.
Q3: Not an option on my server. Domino will not issue an expiration date for static resources. The Heuristic expiration date would be fine if the data didn't dissappear from the cache.

Comment 4

[WADA:World Anti-bad-Duping Agency]

Similar situation could be generated by deleting file in disk cache.
 1. Set cache size=1MB in preference, and clear cache.
    (about:cache/Memory cache device = Maximum storage size: 6144 KiB)
    browser.cache.check_doc_frequency = 3
    browser.sessionhistory.max_total_viewers = 0
    browser.sessionhistory.max_viewers       = 0
 2. Open image of PassionVine.jpg!OpenImageResource by comment #1 in a tab
 3. Open several local jpeg files, and make "storage in use" of "memory cache
    device" more than 6144 kiB.
 4. Close tab opened by step 2.
 5. See about:cache
    - Memory cache device : No entry for image of step 2.
    - Disk   cache device : Entry for image of step 2 exists.
 6. Delete data file in cache directry.
    (Don't touch _CACHE_001_, _CACHE_002_, _CACHE_003_ and _CACHE_MAP_)
 7. Try to open same image as step 2.
    => Page Load Error. The file ... not found.
       (No HTTP GET is seen by LiveHTTPHeaders at this point)
 8. Click "Try again"
    => HTTP GET with If-Modified-Since: is issued and 304 is returned
    => Page Load Error, The file ... not found.
 9. Shift+Reload => Displayed correctly  

Comment 5

[WADA:World Anti-bad-Duping Agency]

Problem when disk cache data is pushed out by current limitation of Bug 175600?
> Bug 175600 : Only 8192 objects can be stored in disk cache.

Comment 6

[Brian Scott]

If that's the case, then 1: Why is the cache entry not removed when the cache data is? and 2: perhaps 50MB is too big for a default cache size.

Comment 7

[Brian Scott]

Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.6) Gecko/20060728 Firefox/1.5.0.6

The problem still exists. An image came up as "not found" even though the server will still serve the file. Based on the cache info, the data was purged but the cache entry was not.


File not found
Firefox can't find the file at /monroviaweb.nsf/IndexLeft4.jpg!OpenImageResource.


about:cache
Disk cache device

Number of entries: 	6926
Maximum storage size: 	50000 KiB
Storage in use: 	49999 KiB
Cache Directory: 	C:\Documents and Settings\bscott.MONROVIA\Local Settings\Application Data\Mozilla\Firefox\Profiles\default.y5b\Cache

List Cache Entries


           Key: http://azdomino.monrovia.com/monroviaweb.nsf/IndexLeft4.jpg!OpenImageResource
     Data size: 23518 bytes
   Fetch count: 8
 Last modified: 2006-08-29 08:33:30
       Expires: 2006-08-29 10:51:00

Another oddity: about:cache lists the disk cache as 50MB, but Windows says that folder contains 77MB. There are several files in the cache folder that date back to July 26, and one of them is 25MB. Could these be orphaned by the .6 upgrade?

Comment 8

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #7)
> Number of entries:      6926
> Maximum storage size:   50000 KiB
> Storage in use:         49999 KiB

Looks to be problem when pushing out due to disk cache size limitation instead of 8192 entry limitation. 

> Another oddity: about:cache lists the disk cache as 50MB, but Windows says that
> folder contains 77MB.
Each disk file has two size property : file-size(Xi) and size-on-disk(Yi).
Probably about:cache displays sum of Xi and MS Win displays sum of Yi as folder size.

By the way, Mozilla keeps data for an URI in both Disk cache(data itself) and Memory cache(seems to be decompressed data when JPEG) concurrently, as seen in my comment #2. Please check both "Memory cache device" and "Disk cache device" when problem occurs.

Comment 9

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #7)
> The problem still exists.
Brian Scott, please try followings when problem is reproduced again.
 (1) Shutdown Firefox before execute Shift+Reload for bypass of problem.
 (2) Save back up of Firefox's cache directory.
     (back up of whole profile directory is preferable.)
 (3) Restart Firefox, and access same URI.
 (4) If problem is recreated with same URI,
     (4-1) Shutdown Firefox
     (4-2) Restore back up of cache directory
     (4-3) Restart Firefox with NSPR log - set NSPR_LOG_MODULES=all:5
     (4-4) Access same URI and reproduce the problem, then shutdown Firefox
And attach the log file to this bug. (text/plain, if Bugzilla accepts file size)   

Comment 10

[Brian Scott]

Attachment: NSPR LOG

Search on http://azdomino.monrovia.com/monroviaweb.nsf/IndexLeft4.jpg to find the problem file.

Comment 11

[Brian Scott]

The problem cache entry was in the disk cache only, it was not listed in the memory cache.

Comment 12

[WADA:World Anti-bad-Duping Agency]

CC-ing to Darin Fisher.
Can you explain what's going on by NSPR log?
More data is needed to analyze problem?

Comment 13

[Tino Didriksen]

Attachment: Log of failing image load

I added the environment variables globally and started Firefox directly to http://i.pjj.cc/370e994c2fc057915038a9859cfcb101.jpg which failed loading so it should be a fairly clean log.

The request does indeed send "If-Modified-Since: Sat, 01 Jan 2000 11:59:59 GMT" to which I reply "HTTP/1.1 304 Not Modified". The image never shows, though.

I have a copy of both profile and cache folders, so I should be able to restore to the erronous state at any time.

Comment 14

[Tino Didriksen]

Did some additional digging into the error.

SUMMARY:
"Data size" changes from 21792 bytes to the correct 24284 bytes.
"Content-Range: bytes 2492-24283/24284" comes out to those 21792 bytes...but don't know where or why it would request partial data. Could it be trying to resume at the same time as If-Modified-Since?

On the whole, I'm not sure whether what I caught here is actually related to the behavior I originally reported.

BEFORE forced reload:

[Memory cache device]
Number of entries: 	66
Maximum storage size: 	35840 KiB
Storage in use: 	518 KiB
Inactive storage: 	1 KiB

-- the image is not present in the memory cache.

[Disk cache device]
Number of entries: 	3519
Maximum storage size: 	50000 KiB
Storage in use: 	49996 KiB

Key: http://i.pjj.cc/370e994c2fc057915038a9859cfcb101.jpg
Data size: 21792 bytes
Fetch count: 9
Last modified: 2006-09-05 13:48:38
Expires: 2007-05-07 11:18:08

[Cache/_CACHE_001_ entry for the image]
Date: Tue, 05 Sep 2006 11:43:47 GMT
Server: Apache
Etag: "370e994c2fc057915038a9859cfcb101"
Content-Length: 21792
Last-Modified: Sat, 01 Jan 2000 11:59:59 GMT
Accept-Ranges: bytes
Vary: User-Agent
Content-Range: bytes 2492-24283/24284
Content-Type: image/jpeg

$ ll Cache | grep 21792
-rwx------+ 1 Tino Didriksen None    21792 Sep  5 13:48 EFBC3ABFd01

$ md5sum EFBC3ABFd01
71ceb8aebedb41f52c4fe1abe7a29fe5 *EFBC3ABFd01


AFTER forced reload:

[Memory cache device]
Number of entries: 	62
Maximum storage size: 	35840 KiB
Storage in use: 	4989 KiB
Inactive storage: 	4253 KiB

Key: http://i.pjj.cc/370e994c2fc057915038a9859cfcb101.jpg
Data size: 229160 bytes
Fetch count: 10
Last modified: 2006-09-05 16:05:14
Expires: 2007-05-07 13:47:49

[Disk cache device]
Number of entries: 	3507
Maximum storage size: 	50000 KiB
Storage in use: 	49994 KiB

Key: http://i.pjj.cc/370e994c2fc057915038a9859cfcb101.jpg
Data size: 24284 bytes
Fetch count: 5
Last modified: 2006-09-05 16:05:32
Expires: 2007-05-07 13:48:11

[Cache/_CACHE_001_ entry for the image]
Date: Tue, 05 Sep 2006 14:00:10 GMT
Server: Apache
Etag: "370e994c2fc057915038a9859cfcb101"
Content-Length: 24284
Last-Modified: Sat, 01 Jan 2000 11:59:59 GMT
Accept-Ranges: bytes
Vary: User-Agent
Content-Type: image/jpeg

$ ll Cache | grep 24284
-rwx------+ 1 Tino Didriksen None    24284 Sep  5 16:05 EFBC3ABFd01

$ md5sum EFBC3ABFd01
370e994c2fc057915038a9859cfcb101 *EFBC3ABFd01

Comment 15

[Michal Novotny [:michal]]

This seems to be duplicate of bug #321361 and/or bug #355567. Please retest with latest trunk.

Comment 16

[WADA:World Anti-bad-Duping Agency]

Michal Novotny, this bug is the "a problem in the past" in my Bug 321361 Comment #18. (I couldn't recall bug number when I wrote the comment...)
Setting dependency to Bug 321361, for ease of tracking.

Comment 17

[WADA:World Anti-bad-Duping Agency]

To Tino Didriksen(bug opener) and Brian Scott:

Bug 321361 is already fixed. Can you reproduce problem with latest-trunk?
> http://ftp.mozilla.org/pub/mozilla.org/fireox/nightly/latest-trunk/
>   If MS Win user, download win32.zip build. You can test by UNZIP only.
>   Test with new profile, to avoid corruption of daily use profile.

Comment 18

[Tino Didriksen]

I would say this is fixed one way or the other. I haven't seen the faulty behavior in a very long time, probably since Firefox 3, and I haven't changed usage pattern or profile.

Reproducing was always a matter of chance anyway; waiting for the cache to get in the faulty state before testing what effects that had.

Comment 19

[Brian Scott]

Agreed. I have not seen this behavior in a very long while.

Comment 20

[WADA:World Anti-bad-Duping Agency]

AFAIK, patch for Bug 321361 is landed on Fx Trunk only.
Problem doesn't occur always when Disk Cache size limit reached (rather rarely occurs. many other conditions affect on problem).  
I think you fortunately don't meet problem again for long time with Firefox 3.

I close as DUP of Bug 321361.
If you encounter problem again with latest-trunk or next 3.5, check Bug 321361 and open new bug if new problem, please.