Bug 15765 – ASSERTION FAILED: m_frame->page() in FrameLoader::tokenizerProcessedData using the new GMail interface

• Status: RESOLVED
• Resolution: FIXED
• Component: Page Loading

GMail have a new UI that they are rolling out gradually. If you get the new interface and go to gmail.com with a debug build, you get

ASSERTION FAILED: m_frame->page()
(WebCore/loader/FrameLoader.cpp:3126 void WebCore::FrameLoader::tokenizerProcessedData())

No problems observed on a release build.

Backtrace:
#0  0x0206b942 in WebCore::FrameLoader::tokenizerProcessedData (this=0x1d1e7400) at WebCore/loader/FrameLoader.cpp:3126
#1  0x01b90784 in WebCore::HTMLTokenizer::timerFired (this=0x1d0dea00) at WebCore/html/HTMLTokenizer.cpp:1533
#2  0x01b9778d in WebCore::Timer<WebCore::HTMLTokenizer>::fired (this=0x1d0dead8) at Timer.h:98
#3  0x01e020ba in WebCore::TimerBase::fireTimers (fireTime=1193762420.747364, firingTimers=@0xbfffe81c) at WebCore/platform/Timer.cpp:336
#4  0x01e02162 in WebCore::TimerBase::sharedTimerFired () at WebCore/platform/Timer.cpp:357
#5  0x01e016f6 in timerFired () at WebCore/platform/mac/SharedTimerMac.cpp:84

As far as I can tell this is a document in an Iframe containing a script to remove the Iframe from the owner document. If that script gets written and run under the write() call in HTMLTokenizer::timerFired(), then you will hit the assert in FrameLoader::tokenizerProcessedData() because the page has been taken out of the frame (and the document no longer points to the frame either).

[Alexey Proskuryakov]

See also (maybe remotely related): bug 15707.

[Adam Roben (:aroben)]

<rdar://problem/5591047>

[Adam Roben (:aroben)]

As far as I can tell there is no effect of this assertion failing in release builds.

The assertion was added in r21367 <http://trac.webkit.org/projects/webkit/changeset/21367>. Previously, the code only had a null-check for m_frame->document(). It's not clear from the ChangeLog why this extra assertion was added.

[David Kilzer (:ddkilzer)]

This makes it rather difficult to log into GMail with debug builds.  :)

[Mark Rowe (bdash)]

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

[Holger Freyther]

Created attachment 18170 [details]
Remove the two asserts

I know a reduction needs to be done. But here is what is happening:

WebCore::Frame::pageDestroyed() is called because a Frame gets removed from the FrameSet as the result of JavaScript code. But there were data for the HTMLTokenizer of the Document and the m_timer was started. The timer fires after we have removed the Frame from the FrameSet.

FrameLoader::tokenizerProcessedData calls checkCompleted() and checkCompleted() is checking for if (m_frame->document()) and (m_frame->page()) at various places and I would argue that removing the asserts is fine as the methods may return 0 and checkCompleted() will continue to work

[Darin Adler]

Comment on attachment 18170 [details]
Remove the two asserts

(In reply to comment #7)
> WebCore::Frame::pageDestroyed() is called because a Frame gets removed from the
> FrameSet as the result of JavaScript code. But there were data for the
> HTMLTokenizer of the Document and the m_timer was started. The timer fires
> after we have removed the Frame from the FrameSet.

The new m_frame->page() assert is causing trouble, but the old m_frame->document() assert is not. I see no reason to remove both because one is failing.

What I would expect in a case like what you describe is that either FrameLoader::stop or FrameLoader::stopLoading would get called. The surprise here is that the frame can be removed without loading stopping.

> FrameLoader::tokenizerProcessedData calls checkCompleted() and checkCompleted()
> is checking for if (m_frame->document()) and (m_frame->page()) at various
> places and I would argue that removing the asserts is fine as the methods may
> return 0 and checkCompleted() will continue to work

Some of those checks are for *after* checkCompleted has dispatched events like the load event; they don't necessarily mean its good to call the function when page is 0.

I think it might be OK to remove the assertion, but it would be better to figure out why the load has not been stopped.

[Holger Freyther]

I tried hard to generate a reduction and I ran into a problem:

For the reduction we need WebCore::HTMLTokenizer::continueProcessing to start the m_timer. This can only happen if "currentTime() - startTime > tokenizerTimeDelay" evaluates to true. When loading something from disk we can not reliable make sure that the timer starts.

[David Kilzer (:ddkilzer)]

(In reply to comment #9)
> I tried hard to generate a reduction and I ran into a problem:
> 
> For the reduction we need WebCore::HTMLTokenizer::continueProcessing to start
> the m_timer. This can only happen if "currentTime() - startTime >
> tokenizerTimeDelay" evaluates to true. When loading something from disk we can
> not reliable make sure that the timer starts.

Use an http test--that's what they're for!  Some of them even have built-in delays (look for tests with "slow" in their name).

[Holger Freyther]

(In reply to comment #8)


> Some of those checks are for *after* checkCompleted has dispatched events like
> the load event; they don't necessarily mean its good to call the function when
> page is 0.
> 
> I think it might be OK to remove the assertion, but it would be better to
> figure out why the load has not been stopped.

Okay. FrameLoader::stopLoad gets called but there is no tokenizer() on the document (anymore), so HTMLTokenizer::stopParsing can not be called, so the timer is firing. I know that we create the HTMLTokenizer with a DocumentFragment, I have no idea where this DocumentFragment is coming from, it is not from a HTMLElement::setInnerHTML.

[Holger Freyther]

FrameLoader::stopLoading gets called before Frame::destroyed. The issue is that from within WebCore::HTMLTokenizer::timerFired the tokenizer is getting destroyed! This happens on the call to write().

Breakpoint 7, ~HTMLTokenizer (this=0x92339d8) at ../../../WebCore/html/HTMLTokenizer.cpp:1678
1678	HTMLTokenizer::~HTMLTokenizer()
(gdb) bt
#0  ~HTMLTokenizer (this=0x92339d8) at ../../../WebCore/html/HTMLTokenizer.cpp:1678
#1  0xb74a823c in WebCore::Document::implicitClose (this=0x91543b8) at ../../../WebCore/dom/Document.cpp:1398
#2  0xb761e14c in WebCore::FrameLoader::checkCallImplicitClose (this=0x911f138)
    at ../../../WebCore/loader/FrameLoader.cpp:1301
#3  0xb76260aa in WebCore::FrameLoader::checkCompleted (this=0x911f138)
    at ../../../WebCore/loader/FrameLoader.cpp:1244
#4  0xb762790b in WebCore::FrameLoader::finishedParsing (this=0x911f138)
    at ../../../WebCore/loader/FrameLoader.cpp:1194
#5  0xb74a80fa in WebCore::Document::finishedParsing (this=0x91543b8) at ../../../WebCore/dom/Document.cpp:3431
#6  0xb75dd13d in WebCore::HTMLParser::finished (this=0x87a4200) at ../../../WebCore/html/HTMLParser.cpp:1426
#7  0xb75f42d1 in WebCore::HTMLTokenizer::end (this=0x92339d8) at ../../../WebCore/html/HTMLTokenizer.cpp:1571
#8  0xb75fa111 in WebCore::HTMLTokenizer::write (this=0x92339d8, str=@0xbfe2cb4c, appendData=true)
    at ../../../WebCore/html/HTMLTokenizer.cpp:1499
#9  0xb75f49ce in WebCore::HTMLTokenizer::timerFired (this=0x92339d8)
    at ../../../WebCore/html/HTMLTokenizer.cpp:1543
#10 0xb75fbf35 in WebCore::Timer<WebCore::HTMLTokenizer>::fired (this=0x9233ab0)

(oh the statement on m_fragment/DocumentFragment was wrong)

[Holger Freyther]

Created attachment 18248 [details]
Reduction and proposed patch added

The reduction should show the issue. My conclusion resulted in the attached change to HTMLTokenizer.cpp. I believe/I'm confident that FrameLoader::checkCompleted gets called already for all the cases where HTMLTokenizer::timerFired would have called FrameLoader::tokenizerProcessedData.

The ChangeLog entry needs some work :).

[Holger Freyther]

The test case seems to the influence the ones running after this one. How can this be? Can I reset/restart the DRT somehow? How are these situations handled?

[David Kilzer (:ddkilzer)]

(In reply to comment #14)
> The test case seems to the influence the ones running after this one. How can
> this be? Can I reset/restart the DRT somehow? How are these situations handled?

The "./WebKitTools/Scripts/run-webkit-tests --help" command will give you lots of options for running DRT.  The "-1" option will run each test with its own copy of DRT.  If this fixes the issue, a change to DRT may be required to reset whatever internal state that the test is changing in DRT or WebKit.  Or it may point to a bug in your patch.

[Holger Freyther]

(In reply to comment #15)
> (In reply to comment #14)
> > The test case seems to the influence the ones running after this one. How can
> > this be? Can I reset/restart the DRT somehow? How are these situations handled?
> 
> The "./WebKitTools/Scripts/run-webkit-tests --help" command will give you lots
> of options for running DRT.  The "-1" option will run each test with its own
> copy of DRT.  If this fixes the issue, a change to DRT may be required to reset
> whatever internal state that the test is changing in DRT or WebKit.  Or it may
> point to a bug in your patch.
> 

It is not my patch and not my test. .Running "/WebKitTools/Scripts/run-webkit-tests -1 http/tests/loading" results in three failing tests. Somehow the "frame "f1" - willCloseFrame" gets lost in some test cases. Weird enough there is no such named frame in the failing test cases. So this result is triggered by a previous test case (e.g. due a FrameLoader::checkCallImplicitClose).

I think we have the following options:
   -Add my fix+test case and adjust the next failing test case (I get f1 closed not the test after this one)
   -Run DRT singly on http/tests/loading and update the results.
   -Fix the root cause (always the best). I think when starting to load the new test all active frames get closed. What DRT could do, or LayoutController on the old test is to call FrameLoader::checkCallImplicitClose. This way we could avoid the issue. There might be other things surviving from one test to another but we don't see them yet.

[David Kilzer (:ddkilzer)]

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

[Adam Roben (:aroben)]

Comment on attachment 18248 [details]
Reduction and proposed patch added

I don't know whether or not the fix is correct, but I think the test should be called gmail-assert instead of gmail-crash, since this never crashed (for me) in release builds.

[Holger Freyther]

(In reply to comment #18)
> (From update of attachment 18248 [details] [edit])
> I don't know whether or not the fix is correct, but I think the test should be
> called gmail-assert instead of gmail-crash, since this never crashed (for me)
> in release builds.

I agree. I want to come up with a fix to DRT/run-webkit-tests fix before landing this patch. Currently run-webkit-test -1 http/tests/loading and run-webkit-tests http/tests/loading give different results and I plan to fix it.

[Holger Freyther]

Created attachment 18409 [details]
Reduction and proposed patch added

-Take Adam's comment into account and rename the test case to gmail-assert-on-load.html
-Use the result from a run-webkit-tests -1 run (without the bogus sub frame close).

[Eric Seidel (no email)]

Comment on attachment 18409 [details]
Reduction and proposed patch added

timing dependent tests are generally discouraged. :(  Is it possible to sign up for a load or content load event instead?

[Holger Freyther]

(In reply to comment #21)
> (From update of attachment 18409 [details] [edit])
> timing dependent tests are generally discouraged. :(  Is it possible to sign up
> for a load or content load event instead?

We need to get into HTMLTokenizer::timerFired, the only way I know is to block while loading.

[Darin Adler]

Comment on attachment 18409 [details]
Reduction and proposed patch added

No reason to set up the local variable frame any more, since we're not using it now:

     RefPtr<Frame> frame = m_fragment ? 0 : m_doc->frame();

[Darin Adler]

Comment on attachment 18409 [details]
Reduction and proposed patch added

r=me if you eliminate the unused local variable "frame".

[Beth Dakin]

I took out the unused variable and landed in 29655. Gmail is useable again in Debug builds! Rejoice!