187035 - Error condition in nsDiskCacheStreamIO::Flush() triggered ASSERTION: deleting dirty buffer: 'mBufDirty == PR_FALSE'

Status: RESOLVED INVALID

(Core :: Networking: Cache, defect)

Description

[timeless]

WARNING: cacheMap->DeleteStorage() failed., file
i:/build/mozilla/netwerk/cache/src/nsDiskCacheStreams.cpp, line 552
###!!! ASSERTION: Flush() failed: 'NS_SUCCEEDED(rv)', file
i:/build/mozilla/netwerk/cache/src/nsDiskCacheStreams.cpp, line 508
(this was caused by bug 187031)
###!!! ASSERTION: file descriptor not closed: '!mFD', file
i:/build/mozilla/netwerk/cache/src/nsDiskCacheStreams.cpp, line 365
Break: at file i:/build/mozilla/netwerk/cache/src/nsDiskCacheStreams.cpp, line 365
(filed as bug 187034)
###!!! ASSERTION: deleting dirty buffer: 'mBufDirty == PR_FALSE', file
i:/build/mozilla/netwerk/cache/src/nsDiskCacheStreams.cpp, line 795
Break: at file i:/build/mozilla/netwerk/cache/src/nsDiskCacheStreams.cpp, line 795

nsDebug::Assertion(const char * 0x044d6b3c, const char * 0x044d6b24, const char
* 0x044d6ae8, int 795) line 280 + 13 bytes
nsDiskCacheStreamIO::DeleteBuffer() line 795 + 35 bytes
nsDiskCacheStreamIO::Close(nsDiskCacheStreamIO * const 0x1490d388, unsigned int
0) line 369
nsDiskCacheStreamIO::~nsDiskCacheStreamIO() line 344
nsDiskCacheStreamIO::`scalar deleting destructor'(unsigned int 1) + 15 bytes
nsDiskCacheStreamIO::Release(nsDiskCacheStreamIO * const 0x1490d388) line 310 +
147 bytes
nsCOMPtr<nsIStreamIO>::~nsCOMPtr<nsIStreamIO>() line 491
nsFileTransport::~nsFileTransport() line 306 + 78 bytes
nsFileTransport::`scalar deleting destructor'(unsigned int 1) + 15 bytes
nsFileTransport::Release(nsFileTransport * const 0x1490d410) line 312 + 147 bytes
nsCOMPtr<nsITransport>::~nsCOMPtr<nsITransport>() line 491
nsCacheEntryDescriptor::nsTransportWrapper::~nsTransportWrapper() line 82 + 38 bytes
nsCacheEntryDescriptor::~nsCacheEntryDescriptor() line 54 + 11 bytes
nsCacheEntryDescriptor::`scalar deleting destructor'(unsigned int 1) + 15 bytes
nsCacheEntryDescriptor::Release(nsCacheEntryDescriptor * const 0x14a600b8) line
36 + 144 bytes
nsCOMPtr<nsICacheEntryDescriptor>::assign_assuming_AddRef(nsICacheEntryDescriptor
* 0x00000000) line 473
nsCOMPtr<nsICacheEntryDescriptor>::assign_with_AddRef(nsISupports * 0x00000000)
line 915
nsCOMPtr<nsICacheEntryDescriptor>::operator=(nsICacheEntryDescriptor *
0x00000000) line 585
nsHttpChannel::CloseCacheEntry(unsigned int 0) line 1364
nsHttpChannel::OnStopRequest(nsHttpChannel * const 0x10c50da4, nsIRequest *
0x1495f044, nsISupports * 0x00000000, unsigned int 0) line 3042
nsOnStopRequestEvent::HandleEvent() line 213
nsARequestObserverEvent::HandlePLEvent(PLEvent * 0x149e0dd4) line 116
PL_HandleEvent(PLEvent * 0x149e0dd4) line 663 + 10 bytes
PL_ProcessPendingEvents(PLEventQueue * 0x00f1bfd0) line 593 + 9 bytes
_md_TimerProc(HWND__ * 0x00d40272, unsigned int 275, unsigned int 0, unsigned
long 3862866668) line 958 + 9 bytes
USER32! 77e13eb0()
USER32! 77e14092()
USER32! 77e13f0f()
nsAppShellService::Run(nsAppShellService * const 0x02c6bd48) line 472
main1(int 3, char * * 0x002e44c0, nsISupports * 0x002d6f08) line 1543 + 32 bytes
main(int 3, char * * 0x002e44c0) line 1904 + 37 bytes
mainCRTStartup() line 338 + 17 bytes
KERNEL32! 77e87903()

So, this is caused by the original problem, namely Flush failed:
nsDiskCacheStreamIO::Flush()
...
            rv = cacheMap->DeleteStorage(record, nsDiskCache::kData);
            if (NS_FAILED(rv)) {
                NS_WARNING("cacheMap->DeleteStorage() failed.");
                return  rv;    // XXX doom cache entry
            }
...
        mBufDirty = PR_FALSE;

Comment 1

[Ere Maijala (slow)]

I saw this too when I was debugging something. It seems that an auto-
refreshing page (actually a frame of a page) was still being refreshed 
although I didn't have it open anymore (only MailNews). When I closed MailNews 
too, Mozilla didn't shut down and the refreshes continued until I opened a new 
window and chose Exit from File menu.

Comment 2

[srinivas]

(we're using ~1.7b)

WARNING: cacheMap->DeleteStorage() failed., file 
c:/cenzic/ea/mozilla/netwerk/cache/src/nsDiskCacheStreams.cpp, line 491
###!!! ASSERTION: Flush() failed: 'NS_SUCCEEDED(rv)', file 
c:/cenzic/ea/mozilla/netwerk/cache/src/nsDiskCacheStreams.cpp, line 447
Break: at file c:/cenzic/ea/mozilla/netwerk/cache/src/nsDiskCacheStreams.cpp, 
line 447

 	xpcom.dll!nsDebug::Assertion(const char * aStr=0x00e0fb28, const char 
* aExpr=0x00e0fb14, const char * aFile=0x00e0fad4, int aLine=447)  Line 109
	C++
>	necko.dll!nsDiskCacheStreamIO::CloseOutputStream
(nsDiskCacheOutputStream * outputStream=0x03b0e768)  Line 447 + 0x24	C++
 	necko.dll!nsDiskCacheOutputStream::Close()  Line 226	C++
 	necko.dll!nsCacheEntryDescriptor::nsOutputStreamWrapper::Close()  Line 
603	C++
 	necko.dll!
nsCacheEntryDescriptor::nsOutputStreamWrapper::~nsOutputStreamWrapper()  Line 
128	C++
 	necko.dll!nsCacheEntryDescriptor::nsOutputStreamWrapper::`scalar 
deleting destructor'()  + 0xf	C++
 	necko.dll!nsCacheEntryDescriptor::nsOutputStreamWrapper::Release()  
Line 555 + 0x91	C++
 	necko.dll!nsCOMPtr<nsIOutputStream>::assign_assuming_AddRef
(nsIOutputStream * newPtr=0x00000000)  Line 495	C++
 	necko.dll!nsCOMPtr<nsIOutputStream>::assign_with_AddRef(nsISupports * 
rawPtr=0x00000000)  Line 1023	C++
 	necko.dll!nsCOMPtr<nsIOutputStream>::operator=(nsIOutputStream * 
rhs=0x00000000)  Line 608	C++
 	necko.dll!nsStreamListenerTee::OnStopRequest(nsIRequest * 
request=0x0c2e4908, nsISupports * context=0x00000000, unsigned int status=0)  
Line 65	C++
 	necko.dll!nsHttpChannel::OnStopRequest(nsIRequest * 
request=0x0c2f3c10, nsISupports * ctxt=0x00000000, unsigned int status=0)  
Line 3419	C++
 	necko.dll!nsInputStreamPump::OnStateStop()  Line 499	C++
 	necko.dll!nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream * 
stream=0x0c2f39cc)  Line 339 + 0xb	C++
 	xpcom.dll!nsInputStreamReadyEvent::EventHandler(PLEvent * 
plevent=0x0c2f606c)  Line 119	C++
 	xpcom.dll!PL_HandleEvent(PLEvent * self=0x0c2f606c)  Line 673 + 0xa
	C
 	xpcom.dll!PL_ProcessPendingEvents(PLEventQueue * self=0x00a87b60)  
Line 608 + 0x9	C
 	xpcom.dll!_md_EventReceiverProc(HWND__ * hwnd=0x059b03b8, unsigned int 
uMsg=49573, unsigned int wParam=0, long lParam=11041632)  Line 1414 + 0x9
	C
 	user32.dll!77d43a50() 	
 	user32.dll!77d43b1f() 	
 	user32.dll!77d43d79() 	
 	shlwapi.dll!70a71a39() 	
 	user32.dll!77d43fd4() 	
 	user32.dll!77d43ddf() 	
 	gkwidget.dll!nsAppShell::Run()  Line 135	C++
 	appshell.dll!nsAppShellService::Run()  Line 524	C++
 	mozilla.exe!main1(int argc=2, char * * argv=0x002a53b0, nsISupports * 
nativeApp=0x00a3e9e8)  Line 1303 + 0x20	C++
 	mozilla.exe!main(int argc=2, char * * argv=0x002a53b0)  Line 1791 + 
0x25	C++
 	mozilla.exe!mainCRTStartup()  Line 398 + 0x11	C
 	kernel32.dll!77e814c7() 	

Comment 3

[Ben Fowler]

Attachment: Patch to convert assertions to warnings

As of today's date, I am seeing ASSERTIONS on lines 464, 486, 489 and 752
of this file.

Are some of these error condtions that should be handled?

exempli gratia:

463	rv = Flush();
464	NS_ASSERTION(NS_SUCCEEDED(rv), "Flush() failed");

I appreciate that if we are closing the output stream, should the flush
fail then there is not much that we can do at this level. Isn't it sufficient
to report the condition (out of disk space perhaps)? Is the assertion a)
wrong in the sense of asserting on an non-inconsistent internal state
and b) wrong in that goes away in non-debug builds.

I found these assertions whilst investigating the crash in Bug 261812 .

I enclose a patch, but I am not confident that the code style quite matches
that in the existing file.

Comment 4

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

Comment on attachment 160869 [details] [diff] [review]
Patch to convert assertions to warnings

+	 if( NS_SUCCEEDED(rv) ) {
+	 } else {

this makes no sense. just use NS_FAILED(rv).

+	 if( NS_SUCCEEDED(rv) ) {

this is not the style of the file (as visible in the patch!), style is:
  if (NS_SUCCEEDED(rv)) {

Comment 5

[Ben Fowler]

Many thanks.

There is (more importantly) a logic error in that I need to test for
deleting a dirty buffer (mBufDirty not PR_FALSE).

O.K.

1.
http://lxr.mozilla.org/seamonkey/source/netwerk/cache/src/nsDiskCacheStreams.cpp#464
Is this debugging code needed at all? Isn't it enough to return the
value of rv to the caller who can handle it as required in either a debug
or non-debug build?

2.
http://lxr.mozilla.org/seamonkey/source/netwerk/cache/src/nsDiskCacheStreams.cpp#486

The problem here is that in non-debug builds the return value is being ignored.
If it is known not to be useful then asserting on it is not going to
be of value. If we need to know that flush to file has in fact failled
then a log or warning message would seen appropriate, but more importantly
there needs to be an explanation as to why the error is not being 
communicated to the caller. It is handled differently on line 517

3.
http://lxr.mozilla.org/seamonkey/source/netwerk/cache/src/nsDiskCacheStreams.cpp#489
I am wondering whether this is an example of a normal program state
in the sense that PR_Close may be known to handle a null filehandle correctly
and mFD will only be null after a previous call to this or a similar
function. (id est it's idempotent). In which case, surely no diagnostic 
is needed

4.
http://lxr.mozilla.org/seamonkey/source/netwerk/cache/src/nsDiskCacheStreams.cpp#752

What should DeleteBuffer( ) do when passed a dirty buffer.
      a) Attempt to flush it?
      b) Warn and continue?
      c) Warn and abort silently?
      d) Silently delete the buffer?

I really don't think that assertion is the right thing ...

If the design allows this function to delete dirty buffers then surely
d) is right. It is up to caller to log or handle the necessity
of deleting a buffer where flushing it has failed.

Returning some kind of notification either implies changing the return
type from void or requiring the caller to check that the deletion
took place.

I would be happy to submit a cleaned up patch, but it would only be
worth reviewing if it could be agreed that these assertions are either
unncessary or could be changed to warnings.

I used NS_SUCCEEDED because the code I was working on did. Also some
people just prefer to check for absence of errors ahead of checking
for or handling error conditions.

Comment 6

[Patrick McManus [:mcmanus]]

new cache code these days