Closed Bug 969526 Opened 11 years ago Closed 9 years ago

Intermittent test_richtext.html,test_richtext2.html,test_bug436801.html | application crashed [@ KERNELBASE.dll + 0x89ae4] (ABORT: Should have mProgressTracker until we create mImage: 'mProgressTracker')

Categories

(Core :: Networking: Cache, defect)

All
Windows 8
defect
Not set
normal

Tracking

()

RESOLVED WORKSFORME

People

(Reporter: mayhemer, Unassigned, NeedInfo)

References

Details

(Keywords: intermittent-failure)

Daniel, any clue when this can happen?
Flags: needinfo?(dholbert)
Nope. I do have the 'hg blame' on the assertion, but I haven't looked at the imagelib code in ages, and I believe mStatusTracker lifetime-management has changed a bit since then. For the record -- just in case the log disappears at some point -- here's the copypasted backtrace: { 15:56:46 INFO - 1 xul.dll!imgRequest::GetStatusTracker() [imgRequest.cpp:fddd2eaf8e5d : 136 + 0x21] 15:56:46 INFO - eip = 0x7249bc9b esp = 0x143ff358 ebp = 0x143ff374 15:56:46 INFO - Found by: previous frame's frame pointer 15:56:46 INFO - 2 xul.dll!imgRequest::OnDataAvailable(nsIRequest *,nsISupports *,nsIInputStream *,unsigned __int64,unsigned int) [imgRequest.cpp:fddd2eaf8e5d : 822 + 0xa] 15:56:46 INFO - eip = 0x7249cfc0 esp = 0x143ff37c ebp = 0x143ff434 15:56:46 INFO - Found by: call frame info 15:56:46 INFO - 3 xul.dll!ProxyListener::OnDataAvailable(nsIRequest *,nsISupports *,nsIInputStream *,unsigned __int64,unsigned int) [imgLoader.cpp:fddd2eaf8e5d : 2113 + 0x1c] 15:56:46 INFO - eip = 0x72493bdb esp = 0x143ff43c ebp = 0x143ff458 15:56:46 INFO - Found by: call frame info 15:56:46 INFO - 4 xul.dll!nsStreamListenerTee::OnDataAvailable(nsIRequest *,nsISupports *,nsIInputStream *,unsigned __int64,unsigned int) [nsStreamListenerTee.cpp:fddd2eaf8e5d : 93 + 0x1f] 15:56:46 INFO - eip = 0x71e6b11c esp = 0x143ff460 ebp = 0x143ff494 15:56:46 INFO - Found by: call frame info 15:56:46 INFO - 5 xul.dll!mozilla::net::nsHttpChannel::OnDataAvailable(nsIRequest *,nsISupports *,nsIInputStream *,unsigned __int64,unsigned int) [nsHttpChannel.cpp:fddd2eaf8e5d : 5328 + 0x37] 15:56:46 INFO - eip = 0x71f21fcb esp = 0x143ff49c ebp = 0x143ff588 15:56:46 INFO - Found by: call frame info 15:56:46 INFO - 6 xul.dll!nsInputStreamPump::OnStateTransfer() [nsInputStreamPump.cpp:fddd2eaf8e5d : 593 + 0x22] 15:56:46 INFO - eip = 0x71e5645f esp = 0x143ff590 ebp = 0x143ff5dc 15:56:46 INFO - Found by: call frame info 15:56:46 INFO - 7 xul.dll!nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream *) [nsInputStreamPump.cpp:fddd2eaf8e5d : 434 + 0x9] 15:56:46 INFO - eip = 0x71e5ea06 esp = 0x143ff5e4 ebp = 0x143ff5f8 15:56:46 INFO - Found by: call frame info 15:56:46 INFO - 8 xul.dll!nsInputStreamReadyEvent::Run() [nsStreamUtils.cpp:fddd2eaf8e5d : 85 + 0x10] 15:56:46 INFO - eip = 0x71dd8d16 esp = 0x143ff600 ebp = 0x143ff610 15:56:46 INFO - Found by: call frame info 15:56:46 INFO - 9 xul.dll!nsThreadPool::Run() [nsThreadPool.cpp:fddd2eaf8e5d : 208 + 0xd] } So, we're calling GetStatusTracker from imgRequest::OnDataAvailable, and we're aborting because we don't have mImage set up yet (i.e. 'mImage && mGotData' is false), and yet we've somehow cleared our mStatusTracker. (which we're only supposed to do when we set up mImage and set mGotData to true, in OnDataAvailable.) So superficially, it looks like this invariant should hold. It could be made to fail if mImage or mGotData were cleared elsewhere, though. Punting to seth, since he's looked at this code and mStatusTracker lifetimes more recently than I have.
Flags: needinfo?(dholbert) → needinfo?(seth)
So, the fact that mStatusTracker is null suggests that we've gotten a call to OnDataAvailable before this one (which is where we cleared mStatusTracker, and set mImage/mGotData to truthy values.) One way for this assertion to fail would be: in the time between that OnDataAvailable call and the OnDataAvailable call in the backtrace, we clear mImage and/or mGotData. It doesn't look like that's possible, though (i.e. mImage and mGotData are never cleared once they've been set to truthy values, based on my code-skimming.) Does the "gum" project (where this happened) have any imagelib code that's not in m-c?
gum is kept in sync (merged) regularly ones or more a week with m-c. Only patch on gum is currently a pref flip which enables the new HTTP cache. Every thing is already on m-c.
and there is no change to imglib.
OK, thanks. So, I guess the way to get to the bottom of this is for someone to look the lifetime of mStatusTracker, mImage, and mGotData, looking for *any* way that they could get into the configuration where we fail this assertion. (I did a quick pass of that at the end of comment 2, with a bit more in comment 3, and I didn't immediately see how it's possible. But it must be possible, given that we *did* fail it. :)) (Seth may have some insights here, too.)
So I suspect this is related to the off-main-thread OnDataAvailable work in bug 867755, though that's not confirmed yet. I'll load up the relevant code and give it a look. CC'ing Steve as well.
Flags: needinfo?(seth)
Guys, thanks for looking into this! To turn the new cache on, just flip "browser.cache.use_new_backend" pref to 1 (_not_ "true").
If interested, here https://tbpl.mozilla.org/?tree=Try&rev=eef0fd08c5f7 will soon be m(4) run trying to reproduce this failure with some NSPR logging (nsHttp:5,cache2:5,imgRequest:5) in it.
Wow, this is an interesting one. I can't figure out from inspection how this can happen. Looking forward to seeing the log.
Flags: needinfo?(seth)
Summary: HTTP cache v2: Intermittent (win M4 dbg) ###!!! ABORT: Should have mStatusTracker until we create mImage: 'mStatusTracker' | test_richtext2.html | application terminated with exit code 2147483651 → HTTP cache v2: Intermittent test_richtext2.html,test_bug436801.html | application crashed [@ KERNELBASE.dll + 0x89ae4] (ABORT: Should have mStatusTracker until we create mImage: 'mStatusTracker')
Comment 11 shows this is not a cache2 issue (failed on a cs w/o cache2 being enabled). Unblocking!
No longer blocks: cache2tests
Summary: HTTP cache v2: Intermittent test_richtext2.html,test_bug436801.html | application crashed [@ KERNELBASE.dll + 0x89ae4] (ABORT: Should have mStatusTracker until we create mImage: 'mStatusTracker') → Intermittent test_richtext2.html,test_bug436801.html | application crashed [@ KERNELBASE.dll + 0x89ae4] (ABORT: Should have mStatusTracker until we create mImage: 'mStatusTracker')
Blocks: 965721
Summary: Intermittent test_richtext2.html,test_bug436801.html | application crashed [@ KERNELBASE.dll + 0x89ae4] (ABORT: Should have mStatusTracker until we create mImage: 'mStatusTracker') → Intermittent test_richtext.html,test_richtext2.html,test_bug436801.html | application crashed [@ KERNELBASE.dll + 0x89ae4] (ABORT: Should have mStatusTracker until we create mImage: 'mStatusTracker')
Assertion changed slightly in bug 1097432 (part 3).
Summary: Intermittent test_richtext.html,test_richtext2.html,test_bug436801.html | application crashed [@ KERNELBASE.dll + 0x89ae4] (ABORT: Should have mStatusTracker until we create mImage: 'mStatusTracker') → Intermittent test_richtext.html,test_richtext2.html,test_bug436801.html | application crashed [@ KERNELBASE.dll + 0x89ae4] (ABORT: Should have mProgressTracker until we create mImage: 'mProgressTracker')
Inactive; closing (see bug 1180138).
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.