Bug 160546 – [Fetch API] Improve resource loading console logging

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

[youenn fablet]

Contrary to XMLHttpRequest, console logging of loading errors is very limited for the fetch API.

[youenn fablet]

Created attachment 285317 [details]
WIP

[Build Bot]

Comment on attachment 285317 [details]
WIP

Attachment 285317 [details] did not pass mac-ews (mac):
Output: http://webkit-queues.webkit.org/results/1810994

New failing tests:
imported/w3c/web-platform-tests/fetch/api/cors/cors-origin.html

[Build Bot]

Created attachment 285321 [details]
Archive of layout-test-results from ews102 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-ews.
Bot: ews102  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[Build Bot]

Comment on attachment 285317 [details]
WIP

Attachment 285317 [details] did not pass mac-wk2-ews (mac-wk2):
Output: http://webkit-queues.webkit.org/results/1810998

New failing tests:
imported/w3c/web-platform-tests/fetch/api/cors/cors-origin.html

[Build Bot]

Created attachment 285322 [details]
Archive of layout-test-results from ews104 for mac-yosemite-wk2

The attached test failures were seen while running run-webkit-tests on the mac-wk2-ews.
Bot: ews104  Port: mac-yosemite-wk2  Platform: Mac OS X 10.10.5

[Build Bot]

Comment on attachment 285317 [details]
WIP

Attachment 285317 [details] did not pass ios-sim-ews (ios-simulator-wk2):
Output: http://webkit-queues.webkit.org/results/1811003

New failing tests:
imported/w3c/web-platform-tests/fetch/api/cors/cors-basic-worker.html
imported/w3c/web-platform-tests/fetch/api/cors/cors-basic.html
imported/w3c/web-platform-tests/fetch/api/cors/cors-origin.html

[Build Bot]

Created attachment 285323 [details]
Archive of layout-test-results from ews121 for ios-simulator-wk2

The attached test failures were seen while running run-webkit-tests on the ios-sim-ews.
Bot: ews121  Port: ios-simulator-wk2  Platform: Mac OS X 10.11.5

[Build Bot]

Comment on attachment 285317 [details]
WIP

Attachment 285317 [details] did not pass mac-debug-ews (mac):
Output: http://webkit-queues.webkit.org/results/1811006

New failing tests:
imported/w3c/web-platform-tests/fetch/api/cors/cors-origin.html

[Build Bot]

Created attachment 285324 [details]
Archive of layout-test-results from ews117 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews117  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[youenn fablet]

As can be seen from this patch, it is nice to capture console error messages so that we ensure the loading errors are due to the right reason.

The issue is that the error messages contain URLs that vary over test runs.
It can be blob URLs, it can be test-generated URLs with tokens to retrieve server-side status information.

Also, the more error logging we might add, the more often this kind of issues will arise.

We can improve the diff tool in some ways.
Ap, I seem to remember you were reluctant to that idea.
Any other idea?

Note that other tests (at least in WPT) are marked flaky for that same reason or for assertions that fail with an error message varying for each test run.

[Alexey Proskuryakov]

> Ap, I seem to remember you were reluctant to that idea.

Could you please point to that discussion?

[youenn fablet]

(In reply to comment #11)
> > Ap, I seem to remember you were reluctant to that idea.
> 
> Could you please point to that discussion?

Sorry, I don't have a specific pointer and this is vague in my mind.
The idea was that we should keep tooling simple.
For the diff tool, that was meaning byte comparison.

We could relax this comparison for a known list of tests (adding other tests for precise console log validation).
But this would certainly add some complexity.

[youenn fablet]

Maybe adding a new expectation keyword like PassWithXXX?

[Alexey Proskuryakov]

> The idea was that we should keep tooling simple.

This seems like a good idea to me. That said, we should already have at least one special case - I think that we ignore content of certain callbacks when diffing on Windows.

Whenever possible, we should of course try to change the tests to actually have stable output.

[youenn fablet]

Created attachment 286964 [details]
Adding new ConsoleLog expectation

[youenn fablet]

(In reply to comment #14)
> > The idea was that we should keep tooling simple.
> 
> This seems like a good idea to me. That said, we should already have at
> least one special case - I think that we ignore content of certain callbacks
> when diffing on Windows.
> 
> Whenever possible, we should of course try to change the tests to actually
> have stable output.

In the latest patch, I updated webkitpy infrastructure to take a new ConsoleLog modifier similarly to Slow. When this modifier is set, console log lines are removed from the generated and expected text output before comparing them.

This part is not yet finalised, I need to add unit testing and some change logs.
ap, do you have any feedback before I do so?

If we do further load error logging by removing lines 95 and 96 of ThreadableLoader::logError, we can see some new logged errors coming from the underlying HTTP library like:
- "too many HTTP redirects"
- "The certificate for this server is invalid. You might be connecting to a server that is pretending to be “127.0.0.1” which could put your confidential information at risk."

[Build Bot]

Comment on attachment 286964 [details]
Adding new ConsoleLog expectation

Attachment 286964 [details] did not pass ios-sim-ews (ios-simulator-wk2):
Output: http://webkit-queues.webkit.org/results/1939971

New failing tests:
imported/w3c/web-platform-tests/fetch/api/cors/cors-basic-worker.html
imported/w3c/web-platform-tests/fetch/api/cors/cors-basic.html
fast/frames/frame-unload-crash.html

[Build Bot]

Created attachment 286967 [details]
Archive of layout-test-results from ews126 for ios-simulator-elcapitan-wk2

The attached test failures were seen while running run-webkit-tests on the ios-sim-ews.
Bot: ews126  Port: ios-simulator-elcapitan-wk2  Platform: Mac OS X 10.11.5

[Build Bot]

Comment on attachment 286964 [details]
Adding new ConsoleLog expectation

Attachment 286964 [details] did not pass mac-ews (mac):
Output: http://webkit-queues.webkit.org/results/1940039

New failing tests:
fast/frames/frame-unload-crash.html

[Build Bot]

Created attachment 286968 [details]
Archive of layout-test-results from ews102 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-ews.
Bot: ews102  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[Build Bot]

Comment on attachment 286964 [details]
Adding new ConsoleLog expectation

Attachment 286964 [details] did not pass mac-wk2-ews (mac-wk2):
Output: http://webkit-queues.webkit.org/results/1940036

New failing tests:
fast/frames/frame-unload-crash.html

[Build Bot]

Created attachment 286969 [details]
Archive of layout-test-results from ews106 for mac-yosemite-wk2

The attached test failures were seen while running run-webkit-tests on the mac-wk2-ews.
Bot: ews106  Port: mac-yosemite-wk2  Platform: Mac OS X 10.10.5

[Build Bot]

Comment on attachment 286964 [details]
Adding new ConsoleLog expectation

Attachment 286964 [details] did not pass mac-debug-ews (mac):
Output: http://webkit-queues.webkit.org/results/1940028

New failing tests:
fast/frames/frame-unload-crash.html

[Build Bot]

Created attachment 286970 [details]
Archive of layout-test-results from ews114 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews114  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[youenn fablet]

Created attachment 286972 [details]
Rebasing some tests

[Alexey Proskuryakov]

Comment on attachment 286972 [details]
Rebasing some tests

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

> LayoutTests/TestExpectations:505
> +imported/w3c/web-platform-tests/fetch/api/cors/cors-preflight.html [ ConsoleLog ]

This doesn't seem clear enough to me. How can this be renamed for the effect to be immediately obvious? There is so much information to convey that maybe it's not even possible.

1. Which console log? This is an overloaded notion, including at least console.log(), stdout/stderr, and logs in Mac Console.app.

2. What about the console log? Does the attribute mean that there should be a log in console, or that there shouldn't be one, or that something about the test will be logged to console, or that we ignore the logs when diffing against the expected result?

> LayoutTests/fast/frames/frame-unload-crash-expected.txt:2
> -CONSOLE MESSAGE: line 13: XMLHttpRequest cannot load frame-unload-crash-2.html due to access control checks.
> +CONSOLE MESSAGE: line 13: XMLHttpRequest cannot load frame-unload-crash-2.html. Access control checks.

This change looks like a regression to me.

[youenn fablet]

(In reply to comment #26)
> Comment on attachment 286972 [details]
> Rebasing some tests
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=286972&action=review
> 
> > LayoutTests/TestExpectations:505
> > +imported/w3c/web-platform-tests/fetch/api/cors/cors-preflight.html [ ConsoleLog ]
> 
> This doesn't seem clear enough to me. How can this be renamed for the effect
> to be immediately obvious? There is so much information to convey that maybe
> it's not even possible.
>
> 1. Which console log? This is an overloaded notion, including at least
> console.log(), stdout/stderr, and logs in Mac Console.app.

This is console.log() and is only meaningful for text diff tests.

> 2. What about the console log? Does the attribute mean that there should be
> a log in console, or that there shouldn't be one, or that something about
> the test will be logged to console, or that we ignore the logs when diffing
> against the expected result?

This is the latter.
Maybe something like: JSConsoleLogTextFailure? or TextDiff=NoConsoleLog?

> > LayoutTests/fast/frames/frame-unload-crash-expected.txt:2
> > -CONSOLE MESSAGE: line 13: XMLHttpRequest cannot load frame-unload-crash-2.html due to access control checks.
> > +CONSOLE MESSAGE: line 13: XMLHttpRequest cannot load frame-unload-crash-2.html. Access control checks.
> 
> This change looks like a regression to me.

This change is an expected.
Before the patch, XMLHttpRequest is outputting the message based on the error type (AccessControl)
After the patch, this is done by ThreadableLoader::logError, which does the same thing with a somewhat different formatting.

[Alexey Proskuryakov]

> This change is an expected.

What I'm saying is that the new text is substantially worse. It's not correct grammatically, and it's not even clear what it means.

[youenn fablet]

Created attachment 287201 [details]
WIP: TextDiff modifier

[youenn fablet]

> What I'm saying is that the new text is substantially worse. It's not
> correct grammatically, and it's not even clear what it means.

I updated ThreadableLoader::logError code to use the previous message.
Formatting could probably be further improved (replacing . by : for instance).

(In reply to comment #29)
> Created attachment 287201 [details]
> WIP: TextDiff modifier

This patch allows defining TextDiff=NoJSConsoleLog expectation modifier.
The intent seems much clearer than NoConsoleLog. Is it clear enough?

[Build Bot]

Comment on attachment 287201 [details]
WIP: TextDiff modifier

Attachment 287201 [details] did not pass mac-ews (mac):
Output: http://webkit-queues.webkit.org/results/1953960

New failing tests:
imported/w3c/web-platform-tests/fetch/api/cors/cors-basic-worker.html

[Build Bot]

Created attachment 287202 [details]
Archive of layout-test-results from ews101 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-ews.
Bot: ews101  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[youenn fablet]

Created attachment 297085 [details]
Patch

[youenn fablet]

Created attachment 297308 [details]
Patch for landing

[WebKit Commit Bot]

Comment on attachment 297308 [details]
Patch for landing

Clearing flags on attachment: 297308

Committed r209917: <http://trac.webkit.org/changeset/209917>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.