265028 - Clearing cache sometimes fails

Status: RESOLVED FIXED

(Core :: Networking: Cache, defect, P1)

Description

[Jesse Ruderman]

Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.7.3) Gecko/20041015
Firefox/0.10

Steps to reproduce:
1. Tools > Options > Privacy > Cache > Clear

Result (about 20% of the time): Nothing happens.  The button does not look
disabled.  The following appears in my JS console:

Error: [Exception... "Component returned failure code: 0x80004005
(NS_ERROR_FAILURE) [nsICacheService.evictEntries]"  nsresult: "0x80004005
(NS_ERROR_FAILURE)"  location: "JS frame ::
chrome://browser/content/pref/pref-privacy.js :: clearCacheOfType :: line 165" 
data: no]
Source File: chrome://browser/content/pref/pref-privacy.js
Line: 165

Comment 1

[Jesse Ruderman]

I have to restart Firefox to fix this problem.  about:cache is also broken when
this happens (nothing happens when I hit enter after typing about:cache into the
address bar).

Comment 2

[Darin Fisher]

Not sure if I'll actually have time to investigate this anytime soon, but it
sounds pretty major.

Comment 3

[Alfred Kayser]

There are so many things which could go wrong here, so
it is not so easy find which and where. 
A more detailed test case/scenario would help.

But, one of the more suspicious areas is for example:
890 nsDiskCacheDevice::ClearDiskCache()
891 {
892     if (mBindery.ActiveBindings())  return NS_ERROR_CACHE_IN_USE;

So, may be when a page is still loading, and then one tries to clear the cache
it would fail? 

Comment 4

[Darin Fisher]

> 890 nsDiskCacheDevice::ClearDiskCache()
> 891 {
> 892     if (mBindery.ActiveBindings())  return NS_ERROR_CACHE_IN_USE;

yeah, i thought about that case too... but the caller handles that error
code and walks the cache entries individually looking for inactive entries to
remove.  probably something is screwed up with that process...

Comment 5

[MW]

I'm pretty sure this is the same issue. I can confirm similar error when the
disk where the cache resides becomes full. Even after making additional disk
space available (eg. deleting other files on that disk) the error remains the
same. The most *disturbing* and *critical* aspect is that the browser will NO
LONGER cache to the disk (even if space is available, leading to (at times)
severe browser slowdown & OS performance degradation as everything now resides
in the memory cache. (Perhaps this relates to memory issues/leaks so often reported)

Based on this i think this should be rated 'critical'. Perhaps someone more
familiarlity with the code should nominate this as a 'blocker'. Suggest to add
keywords 'hang' & 'perf' and to update Summary to:

-- Clearing cache sometimes fails -  from then on all files not cached to disk
and reside in memory --

If someone feels that this should be a seperate bug please note it and I will
file seperately. 
Using Win98.

Error: [Exception... "Component returned failure code: 0xc1f30001
(NS_ERROR_NOT_INITIALIZED) [nsICacheService.evictEntries]"  nsresult:
"0xc1f30001 (NS_ERROR_NOT_INITIALIZED)"  location: "JS frame ::
chrome://browser/content/pref/pref-privacy.js :: clearCacheOfType :: line 165" 
data: no]
Source File: chrome://browser/content/pref/pref-privacy.js
Line: 165

Comment 6

[MW]

dupe/dependant on bug 213391 ??

Comment 7

[Peter van der Woude [:Peter6]]

*** Bug 203528 has been marked as a duplicate of this bug. ***

Comment 8

[Simon Paquet [:sipaq]]

*** Bug 271365 has been marked as a duplicate of this bug. ***

Comment 9

[Darin Fisher]

I don't have time to investigate this for Gecko 1.8.  Help wanted.

Comment 10

[Steve England [:stevee]]

Mozilla/5.0 (Windows; U; Windows NT 5.0; en-US; rv:1.8b2) Gecko/20050407
Firefox/1.0+

Error: uncaught exception: [Exception... "Component returned failure code:
0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsICacheService.evictEntries]"  nsresult:
"0xc1f30001 (NS_ERROR_NOT_INITIALIZED)"  location: "JS frame ::
chrome://browser/content/sanitize.js :: anonymous :: line 40"  data: no]

is what I get when I see this issue.

Comment 11

[Darin Fisher]

I see this too using firefox 1.0.  I'll add it to my list for 1.1.

Comment 12

[Alfred Kayser]

A more specific test case would be nice. 
Note, I have tested the diskcache lately a lot with a much smaller diskcache
size (say 200KB), even then I am not able to reproduce this.
To find the cause of this problem we need to instrument the caching code, but it
would require a specific test case, preferably with a small cache size, so that
we don't need to fill up the cache with 50MB's of browsing....

Comment 13

[Darin Fisher]

What I usually do to test the cache is to make a complete copy of the Cache
folder, and then use that to restore a full cache when I need it ;-)

Comment 14

[Steve England [:stevee]]

*** Bug 296540 has been marked as a duplicate of this bug. ***

Comment 15

[Bryan]

Still seeing this issue on the latest trunk builds:

Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8b2) Gecko/20050613
Firefox/1.0+ ID:2005061315

Error: uncaught exception: [Exception... "Component returned failure code:
0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsICacheService.evictEntries]"  nsresult:
"0xc1f30001 (NS_ERROR_NOT_INITIALIZED)"  location: "JS frame ::
chrome://browser/content/sanitize.js :: anonymous :: line 40"  data: no]

Bryan

Comment 16

[RC]

I'm not a techie, but I can tell you i continue to experience issues with the
"clear" button next to cache. Sometimes it clears and other times not. I've
adjusted the size of my cache file but it seems to matter not.

Comment 17

[Bryan]

Seems that I'm running into this more and more with the latest builds.  Could
this not be a potential privacy/security issue for users (think banking related
sites) that don't know they can MANUALLY delete their cached files or close FF
and then launch FF again to "Clear Cache Now".  Confirming again in the latest
build:

Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8b3) Gecko/20050708
Firefox/1.0+ ID:2005070808

Comment 18

[Darin Fisher]

A reproducible testcase would be very helpful.

Comment 19

[Bryan]

Found a site that triggers this bug.  

1)Download latest FF build
2)Launch FF :-)
3)Set your homepage to BLANK (to ensure your cache will be empty)
4)Clear your cache for good measure
5)Navigate to the following site:

WARNING: ADULT GAY SITE!!!  http://www.bigmuscle.com/big_muscle.phtml

6)Once the page has finished loading, attempt to "Clear Cache Now"
7)Observe that you are not able to "Clear Cache Now"

Comment 20

[Bryan]

I asked the guy that I occasionally support to test the latest build and he
states that with the build he has now he cannot reproduce the "Clear Cache Now"
issue (stated he went there more then twenty times and he was able to clear it
without issue).  I also walked him through going to about:cache which worked
fine.  I tested it once and I was able to click on "Clear Cache Now".  Going to
that site last night definitely broke something, including about:cache.  Gavin
was also able to reproduce the issue.  I'm wondering what fixed it in today's build?

Comment 21

[Alfred Kayser]

Try bonsai:
http://bonsai.mozilla.org/cvsquery.cgi?treeid=default&module=MozillaTinderboxAll&branch=HEAD&branchtype=match&dir=%2Fmozilla%2Fnetwerk%2Fcache&file=&filetype=match&who=&whotype=match&sortby=Date&date=hours&hours=2400&mindate=&maxdate=&cvsroot=%2Fcvsroot

As you can see there, not much as changed in the cache code near that day.

However, looking at:
http://bonsai.mozilla.org/cvsquery.cgi?treeid=default&module=MozillaTinderboxAll&branch=HEAD&branchtype=match&dir=%2Fmozilla%2Fnetwerk%2F&file=&filetype=match&who=&whotype=match&sortby=Date&hours=2400&date=month&mindate=&maxdate=&cvsroot=%2Fcvsroot
learned me that there where some fixes in bug 297078, which could relate to this
cache sizing accounting problem...

Comment 22

[Bryan]

This is still occuring with varying frequency...

BUILD: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9a1) Gecko/20050813
Firefox/1.0+ ID:2005081311

~B

Comment 23

[Gary Johnson]

(In reply to comment #10)
latest Build 20050823  - Windows XP HOME

Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8b4) Gecko/20050823
Firefox/1.0+

[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [n
sICacheService.evictEntries]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  locati
on: "JS frame :: chrome://browser/content/sanitize.js :: anonymous :: line 40"
data: no]
************************************************************

Comment 24

[Gary Johnson]

(In reply to comment #23)
> (In reply to comment #10)
As of Today

Steps to reproduce

go here
http://online.wsj.com/public/us

Firefox exit
hit clear private data

From my console

##!!! ASSERTION: file descriptor not closed: '!mFD', file c:/moz/mozilla/netwer
k/cache/src/nsDiskCacheStreams.cpp, line 346
++DOMWINDOW == 19
CSS Error (http://cmhtml.overture.com/partner/css/wsj4.css :5.13): Unknown prope
rty 'over-flow'.  Declaration dropped.
CSS Error (http://cmhtml.overture.com/partner/css/wsj4.css :56.34): Error in par
sing value for property 'cursor'.  Declaration dropped.
WARNING: NS_ENSURE_TRUE(mSaveLayoutState || !aState) failed, file c:/moz/mozilla
/xpfe/components/shistory/src/nsSHEntry.cpp, line 246
CSS Error (http://cmhtml.overture.com/d/search/p/wsj/html/jsads/?Partner=wsj_hom
e_ctxt&adwd=620&adht=250&ctxtUrl=no_url&ctxtCat=home&css_url=http://cmhtml.overt
ure.com/partner/css/wsj4.css&tg=1&cb=1124896125203 :10.92): Unknown property 'ov
er-flow'.  Declaration dropped.
JavaScript error: http://m.wsj.com/RealMedia/ads/adstream_sx.cgi/interactive.wsj
.com/us/27018270182701827018@x01?coreVar=core1&expandedVar=expanded1&holderVar=c
orner1, line 1: syntax error Error was suppressed by event handler

************************************************************
* Call to xpconnect wrapped JSObject produced this error:  *
[Exception... "'Component does not have requested interface' when calling method
: [nsIInterfaceRequestor::getInterface]"  nsresult: "0x80004002 (NS_NOINTERFACE)
"  location: "JS frame :: chrome://browser/content/bookmarks/bookmarks.js :: ano
nymous :: line 1821"  data: no]
************************************************************
--DOMWINDOW == 18
WARNING: dependent window created without a parent, file c:/moz/mozilla/toolkit/
components/startup/src/nsAppStartup.cpp, line 438
++WEBSHELL == 9
++DOMWINDOW == 19
++DOMWINDOW == 20
WARNING: NS_ENSURE_TRUE(NS_SUCCEEDED(rv)) failed, file c:/moz/mozilla/xpcom/io/n
sLocalFileWin.cpp, line 1392
************************************************************
* Call to xpconnect wrapped JSObject produced this error:  *
[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [n
sICacheService.evictEntries]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  locati
on: "JS frame :: chrome://browser/content/sanitize.js :: anonymous :: line 40"
data: no]
************************************************************

Comment 25

[Bryan]

> Steps to reproduce
> 
> go here
> http://online.wsj.com/public/us
> 
> Firefox exit
> hit clear private data

I can reproduce this issue with basically the same steps above:

1) Load FF
2) Navigate to http://online.wsj.com/public/us
3) Click Tools-> Options-> Privacy-> Cache-> "Clear Cache Now"
4) Observe clicking on "Clear Cache Now" does nothing (does not gray out)
5) Close FF and restart FF
6) Click Tools-> Options-> Privacy-> Cache-> "Clear Cache Now"
7) Observe clicking on "Clear Cache Now" actually clears your cache and then is
grayed out!

Appears this *might* be Windows only as this doesn't seem to occur on Linux.

~B

Comment 26

[Hessian]

(In reply to comment #25)

This ALWAYS happens when I log into Hotmail and/or MSN Groups-- basically,
anything that requires logging in at login.passport.net : sometimes if I log out
of Passport within about a minute, it won't happen, but otherwise, it definitely
will.

Please excuse that I'm not enough of a gearhead to know how to find these error
reports such as others are copy-pasting; I make most of my security decisions
based on research and intuition. I thought for awhile there that finally getting
Windows Messenger, running in background, off my start-up list would stop
Passport/Hotmail/MSN etc. (and, apparently, a few other sites as well, though
usually only after a long time,) from messing up Mozilla's ability to clear the
cache, but it apparently hasn't.

I've verified in Windows Explorer that the cache folder is not being cleared,
and neither is the Cache.Trash folder. That's unfortunately about as technical
as I know how to get... 

Comment 27

[Gary Johnson]

To ammend my lame reply to comment, here is a complete reply

Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8b4) Gecko/20050823
Firefox/1.0+
 
Firefox Debug build --disable-activex, --disable-activex-scripting 
MOZILLA_1_8_BRANCH 
Microsoft Visual C++ Toolkit 2003   the free toolkit
Instructions here http://whereswaldo.mit.edu/mozilla/msvcfree.html
 
O.S.: XP Home, Latest Updates

Description: 


Set TOOLS - OPTIONS - PRIVACY - SETTTINGS(z) - CLEAR Private Data Wehn Colsing
Deer Park


Reproducible: At least the last 3 days

Steps to Reproduce:

1. go to http://online.wsj.com/public/us
2. exit firefox 
3. hit button - clear ..

Actual Results:  
hangs 

Expected Results:  
exits after clearing data

Comment 28

[Martijn Wargers (dead)]

I've managed to distill a testcase from http://online.wsj.com/public/us, you can
find it here:
http://www.wargers.org/mozilla/test/265028_clearing_cache.php

To get the bug:
- The file needs to be of type .php
- The file needs to be appr. > 15kb (that's why the junk in the file)
- It needs to have a background-image that points to itself

The file has no added php code inside it.

These are the headers I get from a php file (from Rex Swain's HTTP Viewer):
HTTP/1.1�200�OK(CR)(LF)
Date:�Tue,�30�Aug�2005�11:06:45�GMT(CR)(LF)
Server:�Apache(CR)(LF)
X-Powered-By:�PHP/4.3.11(CR)(LF)
Connection:�close(CR)(LF)
Transfer-Encoding:�chunked(CR)(LF)
Content-Type:�text/html(CR)(LF)

These are the headers I get from a html file (in which I don't get the bug):
HTTP/1.1�200�OK(CR)(LF)
Date:�Tue,�30�Aug�2005�11:08:59�GMT(CR)(LF)
Server:�Apache(CR)(LF)
Last-Modified:�Mon,�13�Jun�2005�15:45:18�GMT(CR)(LF)
ETag:�"860026-177-42adaa0e"(CR)(LF)
Accept-Ranges:�bytes(CR)(LF)
Content-Length:�375(CR)(LF)
Connection:�close(CR)(LF)
Content-Type:�text/html(CR)(LF)

Maybe it has something to do with the Transfer-Encoding: chunked header?

Comment 29

[Alfred Kayser]

First some analysis of this problem using the testcase at:
http://www.wargers.org/mozilla/test/265028_clearing_cache.php

OpenCacheEntry(image) -> result 0, 0236eb80
OpenCacheEntry(HTTP)
OpenCacheEntry(HTTP) -> request 0, 0236eb00
OpenCacheEntry(HTTP) -> result -2142568384, 00000000
OpenCacheEntry(HTTP)
OpenCacheEntry(HTTP) -> request 0, 0236eb00
OpenCacheEntry(HTTP) -> result -2142568384, 00000000
name=FEE9322Fd01

DoomEntry_Internal(0236eb28,
image:http://www.wargers.org/mozilla/test/265028_clearing_cache.php)
DoomEntry->0
DeactivateEntry(0236eb28,
image:http://www.wargers.org/mozilla/test/265028_clearing_cache.php)
IsDoomed
device->DeactivateEntry -> 0
DeactivateEntry->0
name=FEE9322Fd01

DoomEntry_Internal(023a0ec8,
HTTP:http://www.wargers.org/mozilla/test/265028_clearing_cache.php)
DoomEntry->0
DeactivateEntry(023a0ec8,
HTTP:http://www.wargers.org/mozilla/test/265028_clearing_cache.php)
IsDoomed
DiskCacheDevice::DeactivateEntry(023a0ec8)
DeleteStorage(0)
fileIndex = 0
name=FEE9322Fd01
GetFileForDiskCacheRecord (0)
file->Remove --> -2142109675
DeleteStorage(0) -> -2142109675
DeleteStorage(1)
fileIndex = 0
name=FEE9322Fm00
GetFileForDiskCacheRecord (0)
file->Remove --> -2142109678
DeleteStorage(1) -> -2142109678
DeleteStorage -> -2142109675
DiskCacheDevice::DeactivateEntry(023a0ec8) -> -2142109675
device->DeactivateEntry -> -2142109675
DeactivateEntry->-2142109675

Note, the 'php' file is both used as html file and as image (but that is not the
issue), and the size of this file is 16780 bytes (so just over 16K)...

What seems to be happening, is that in dooming the entries, the cache tries also
to delete the corresponding files... The failure code returning from
file->remove() seems to confuse the cache system a lot...

So, a quick and easy patch is to ignore failures in removing files. 
But then file is not deleted, allthough it is created.

That's why the 'DeleteDir' in ClearDiskCache fails, because the file is still
there and still open. So, somehow it is not closed as it should be!

Comment 30

[Alfred Kayser]

Found the bandit! 
In nsDiskCacheStreamIO::SetEOF(), the cache file is opened just to 'truncate' it
to some size, before it is doomed and deleted...
In nsDiskCacheStreamIO::Close: the following assertion was complaining...
    NS_ASSERTION(!mFD, "file descriptor not closed");

So, I made a patch to close the mFD when it is openly opened within SetEOF for
the purpose of truncating, so that we don't dangle this file descriptor...

Comment 31

[Alfred Kayser]

Attachment: Very simple and safe patch, after some very complex analysis

Note, thanks for the people providing the testcases, this really helped to nail
this issue.

Concerning that is a very simple and safe patch, solving a serious issue in the
cache, I request that this is also considered for 1.8 / FF1.5 releases...

Comment 32

[Alfred Kayser]

Attachment: Previous was wrong patchfile, this one only contains the 'Close in SetEOF' fix

Comment 33

[Alfred Kayser]

This problem is for all platforms, all applications and serious enough to
include in 1.8 (and FF 1.5 !!)

Comment 34

[Darin Fisher]

Comment on attachment 194426 [details] [diff] [review]
Previous was wrong patchfile, this one only contains the 'Close in SetEOF' fix

nice!!	r+sr=darin

we want this in firefox 1.5 for sure.  would be good to get some testing in the
beta(s) as well.

Comment 35

[Brendan Eich [:brendan]]

Comment on attachment 194426 [details] [diff] [review]
Previous was wrong patchfile, this one only contains the 'Close in SetEOF' fix

a=me, good catch!

/be

Comment 36

[Darin Fisher]

fixed-on-trunk, fixed1.8

Comment 37

[Christian :Biesinger (don't email me, ping me on IRC)]

(In reply to comment #33)
> This problem is for all platforms

really? on many platforms, you can delete files even though an FD is open.

Comment 38

[Alfred Kayser]

Concerning 'All platforms': file locking may not happen on all platforms, still
the filedescriptor is not closed, and therefor at least counts as a memory leak
for all platforms, but also system resources leak for most platforms.