Bug 105280 – Console log sometimes prefixed with line number

• Status: RESOLVED
• Resolution: FIXED
• Component: WebCore Misc.

[Jussi Kukkonen (jku)]

Several XHR tests have started doing this randomly (~10% of the time) after http://trac.webkit.org/changeset/136657 on at least the EFL WK2 bot:

-CONSOLE MESSAGE: XMLHttpRequest cannot load http://localhost:8000/xmlhttprequest/resources/get.txt. Origin http://127.0.0.1:8000 is not allowed by Access-Control-Allow-Origin.
+CONSOLE MESSAGE: line 58: XMLHttpRequest cannot load http://localhost:8000/xmlhttprequest/resources/get.txt. Origin http://127.0.0.1:8000 is not allowed by Access-Control-Allow-Origin.

I can reproduce this locally. Line 58 of the test in question (http/tests/xmlhttprequest/origin-whitelisting-https.html) is end of file.


I believe this code in WebCore::Console::addMessage is relevant:
  unsigned line = 0;
  if (document && document->parsing() && !document->isInDocumentWrite() && document->scriptableDocumentParser()) {
      ScriptableDocumentParser* parser = document->scriptableDocumentParser();
      if (!parser->isWaitingForScripts() && !parser->isExecutingScript())
          line = parser->lineNumber().oneBasedInt();
  }
  addMessage(source, level, message, url, line, 0, 0, requestIdentifier);

'line' sometimes ends up being set to a value other than zero.

[Jussi Kukkonen (jku)]

(In reply to comment #0)
> 'line' sometimes ends up being set to a value other than zero.

That should be: _Apparently_ 'line' sometimes ends up being set to a value other than zero -- I have not been able to catch this in gdb.

[Mike West]

Interesting. There must be some case when the XHR callback comes through in which the ScriptableDocumentParser thinks it's active. I'll try to reproduce this locally, but it looks like it's only failing on GTK and EFL (see http://test-results.appspot.com/dashboards/flakiness_dashboard.html#group=%40ToT%20-%20webkit.org&tests=http%2Ftests%2Fxmlhttprequest%2Forigin-whitelisting-https.html).

[Jussi Kukkonen (jku)]

It's not just XHR:
http/tests/security/canvas-remote-read-remote-image-redirect.html also does this:
-CONSOLE MESSAGE: Unable to get image data from canvas because the canvas has been tainted by cross-origin data.
-CONSOLE MESSAGE: Unable to get image data from canvas because the canvas has been tainted by cross-origin data.
-CONSOLE MESSAGE: Unable to get image data from canvas because the canvas has been tainted by cross-origin data.
-CONSOLE MESSAGE: Unable to get image data from canvas because the canvas has been tainted by cross-origin data.
+CONSOLE MESSAGE: line 108: Unable to get image data from canvas because the canvas has been tainted by cross-origin data.
+CONSOLE MESSAGE: line 108: Unable to get image data from canvas because the canvas has been tainted by cross-origin data.
+CONSOLE MESSAGE: line 108: Unable to get image data from canvas because the canvas has been tainted by cross-origin data.
+CONSOLE MESSAGE: line 108: Unable to get image data from canvas because the canvas has been tainted by cross-origin data.

[Mario Sanchez Prada]

This very same issue happens every now and then (flaky) in the GTK Debug bot

[Alexey Proskuryakov]

> http/tests/security/canvas-remote-read-remote-image-redirect.html also does this:

Filed bug 121458 before finding this one.

[Carlos Alberto Lopez Perez]

This happens on the GTK release bot/build at randomly intervals. At least the following tests are affected:

http/tests/xmlhttprequest/access-control-preflight-async-method-denied.html
http/tests/xmlhttprequest/access-control-preflight-async-not-supported.html
http/tests/xmlhttprequest/cross-site-denied-response.html
http/tests/xmlhttprequest/origin-whitelisting-https.html
http/tests/xmlhttprequest/simple-cross-origin-denied-events.html
http/tests/xmlhttprequest/simple-cross-origin-denied-events-post.html

[Alexey Proskuryakov]

Also on Mac debug bots:

http/tests/websocket/tests/hybi/reserved-bits.html
http/tests/websocket/tests/hybi/deflate-frame-invalid-parameter.html
http/tests/websocket/tests/hybi/handshake-fail-by-more-protocol-header.html

[Alexey Proskuryakov]

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

[Alexey Proskuryakov]

Created attachment 244821 [details]
proposed fix

[Darin Adler]

Comment on attachment 244821 [details]
proposed fix

View in context: https://bugs.webkit.org/attachment.cgi?id=244821&action=review

> Source/WebCore/dom/ScriptableDocumentParser.h:51
> +    virtual bool consoleMessagesShouldBeAssociatedToParser() const = 0;

I don’t think “associated to” is good grammar. Should be “associated with” like the comment. Also, since this is a parser function, I suggest “associated with text position” rather than “associated to parser”. Maybe:

    virtual bool shouldAssociateConsoleMessagesWithTextPosition() const = 0;

> Source/WebCore/html/parser/HTMLDocumentParser.h:64
> +    virtual bool consoleMessagesShouldBeAssociatedToParser() const override final;

I suggest making this private since there is no need to call it on HTMLDocumentParser. Could always make it public later.

> Source/WebCore/page/PageConsoleClient.cpp:91
> +    // We definitely cannot associate the message to a location being parsed if we are not even parsing.

“with a location” rather than “to a location”.

> Source/WebCore/page/PageConsoleClient.cpp:95
> +    ScriptableDocumentParser* parser = document->scriptableDocumentParser();

What guarantees this is never null? If it’s guaranteed not to be null, why are we putting it in a pointer rather than a reference?

> Source/WebCore/page/PageConsoleClient.cpp:111
>      unsigned line = 0;
>      unsigned column = 0;

I suggest putting the initialization to 0 inside the getParserLocationForConsoleMessage function.

[Alexey Proskuryakov]

> What guarantees this is never null? If it’s guaranteed not to be null, why are we putting it in a pointer rather than a reference?

I do not have a complete guarantee, however we check for parsing() before doing this, and perhaps more importantly, all regression tests pass. I didn't want to add a null check just in case.

[Alexey Proskuryakov]

> I suggest putting the initialization to 0 inside the getParserLocationForConsoleMessage function.

I don't think that I agree. The 0/0 is not a parser location, so a "get parser location" function is not the right place to set that.

To be more generally useful, the function could return true/false, not an in-band failure signal. But we don't need it to be more generally useful.

[Alexey Proskuryakov]

Committed <http://trac.webkit.org/r178648>.

[Darin Adler]

(In reply to comment #12)
> > I suggest putting the initialization to 0 inside the getParserLocationForConsoleMessage function.
> 
> I don't think that I agree. The 0/0 is not a parser location, so a "get
> parser location" function is not the right place to set that.

Sure, but a function that conditionally leaves out arguments untouched is not a good design pattern either. I think the function should set the values to something well defined. And setting them to 0/0 would be good for all current clients.

As you say, if we wanted to generalize it for more clients later we could do something even fancier, but I don’t think it’s good to have a function with a contract that says “only sometimes set the values of these out arguments” unless there is some compelling advantage to doing so.

[Darin Adler]

(In reply to comment #11)
> > What guarantees this is never null? If it’s guaranteed not to be null, why are we putting it in a pointer rather than a reference?
> 
> I do not have a complete guarantee, however we check for parsing() before
> doing this, and perhaps more importantly, all regression tests pass. I
> didn't want to add a null check just in case.

That’s a fine answer to my first question.

What’s the answer to my second question?

[Alexey Proskuryakov]

> I don’t think it’s good to have a function with a contract that says “only sometimes set the values of these out arguments” unless there is some compelling advantage to doing so.

I thought that most "get" functions in WebKit did this, leaving the output untouched when failing. And even when there is a boolean result returned, it's still up to the caller to not accidentally use the uninitialized output arguments.

See e.g. ApplicationCacheHost::getApplicationCacheFallbackResource() or JSObject::getOwnPropertySlot().

This hasn't been a major source of problems in WebKit historically. I don't see this case as being substantially different.

> What’s the answer to my second question?

I assume that you meant changing that line to:

ScriptableDocumentParser& parser = *document->scriptableDocumentParser();

(or possibly auto&, which in my opinion makes it hard to see what types we are working on).

Transforming the result type would increase cognitive load on the reader here. Suddenly, they would have to jump between pointers and references, all just to make a couple member function calls.

To me, making a reference on the fly is not a convincing way of saying "this is really non-null, shouldn't raise red flags when reading".

[Darin Adler]

(In reply to comment #16)
> I assume that you meant changing that line to:
> 
> ScriptableDocumentParser& parser = *document->scriptableDocumentParser();
> 
> (or possibly auto&, which in my opinion makes it hard to see what types we
> are working on).
> 
> Transforming the result type would increase cognitive load on the reader
> here. Suddenly, they would have to jump between pointers and references, all
> just to make a couple member function calls.
> 
> To me, making a reference on the fly is not a convincing way of saying "this
> is really non-null, shouldn't raise red flags when reading".

I think what you might be missing is that we are transitioning to making these functions return references. So the local reference variable today is a “jump” between pointers and references, only until we change the function to return a reference, since it’s a function that is not going to return null.

Code processing something that can’t be null should change to references, and in some cases during the transition, the function it’s calling might still be a pointer. I was hoping to recruit you to help in this transition whenever you modify code or write new code.

If the thing really isn’t guaranteed to be non-null, it’s a whole different problem, and not part of the transition.

[Chris Dumez]

Reopening due to flaky tests.

[Chris Dumez]

Wrong bug.