Bug 160546

Summary: [Fetch API] Improve resource loading console logging
Product: WebKit Reporter: youenn fablet <youennf>
Component: WebCore Misc.Assignee: youenn fablet <youennf>
Status: RESOLVED FIXED    
Severity: Normal CC: achristensen, ap, buildbot, cdumez, commit-queue, dbates, glenn, japhet, joepeck, mkwst, rniwa, sam
Priority: P2    
Version: WebKit Nightly Build   
Hardware: Unspecified   
OS: Unspecified   
Bug Depends on: 161310    
Bug Blocks: 151937    
Attachments:
Description Flags
WIP
none
Archive of layout-test-results from ews102 for mac-yosemite
none
Archive of layout-test-results from ews104 for mac-yosemite-wk2
none
Archive of layout-test-results from ews121 for ios-simulator-wk2
none
Archive of layout-test-results from ews117 for mac-yosemite
none
Adding new ConsoleLog expectation
none
Archive of layout-test-results from ews126 for ios-simulator-elcapitan-wk2
none
Archive of layout-test-results from ews102 for mac-yosemite
none
Archive of layout-test-results from ews106 for mac-yosemite-wk2
none
Archive of layout-test-results from ews114 for mac-yosemite
none
Rebasing some tests
none
WIP: TextDiff modifier
none
Archive of layout-test-results from ews101 for mac-yosemite
none
Patch
none
Patch for landing none

Description youenn fablet 2016-08-04 05:54:31 PDT
Contrary to XMLHttpRequest, console logging of loading errors is very limited for the fetch API.
Comment 1 youenn fablet 2016-08-04 06:52:55 PDT
Created attachment 285317 [details]
WIP
Comment 2 Build Bot 2016-08-04 07:38:58 PDT
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
Comment 3 Build Bot 2016-08-04 07:39:02 PDT
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
Comment 4 Build Bot 2016-08-04 07:41:42 PDT
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
Comment 5 Build Bot 2016-08-04 07:41:46 PDT
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
Comment 6 Build Bot 2016-08-04 07:48:52 PDT
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
Comment 7 Build Bot 2016-08-04 07:48:56 PDT
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
Comment 8 Build Bot 2016-08-04 07:50:51 PDT
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
Comment 9 Build Bot 2016-08-04 07:50:54 PDT
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
Comment 10 youenn fablet 2016-08-04 08:01:54 PDT
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.
Comment 11 Alexey Proskuryakov 2016-08-04 09:19:41 PDT
> Ap, I seem to remember you were reluctant to that idea.

Could you please point to that discussion?
Comment 12 youenn fablet 2016-08-04 09:40:44 PDT
(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.
Comment 13 youenn fablet 2016-08-04 09:41:35 PDT
Maybe adding a new expectation keyword like PassWithXXX?
Comment 14 Alexey Proskuryakov 2016-08-04 10:03:13 PDT
> 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.
Comment 15 youenn fablet 2016-08-25 06:16:17 PDT
Created attachment 286964 [details]
Adding new ConsoleLog expectation
Comment 16 youenn fablet 2016-08-25 06:25:24 PDT
(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."
Comment 17 Build Bot 2016-08-25 07:08:43 PDT
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
Comment 18 Build Bot 2016-08-25 07:08:47 PDT
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
Comment 19 Build Bot 2016-08-25 07:11:10 PDT
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
Comment 20 Build Bot 2016-08-25 07:11:14 PDT
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
Comment 21 Build Bot 2016-08-25 07:12:45 PDT
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
Comment 22 Build Bot 2016-08-25 07:12:49 PDT
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
Comment 23 Build Bot 2016-08-25 07:13:53 PDT
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
Comment 24 Build Bot 2016-08-25 07:13:57 PDT
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
Comment 25 youenn fablet 2016-08-25 07:25:05 PDT
Created attachment 286972 [details]
Rebasing some tests
Comment 26 Alexey Proskuryakov 2016-08-25 10:03:21 PDT
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.
Comment 27 youenn fablet 2016-08-25 14:12:35 PDT
(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.
Comment 28 Alexey Proskuryakov 2016-08-25 14:22:47 PDT
> 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.
Comment 29 youenn fablet 2016-08-27 06:45:11 PDT
Created attachment 287201 [details]
WIP: TextDiff modifier
Comment 30 youenn fablet 2016-08-27 06:50:57 PDT
> 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?
Comment 31 Build Bot 2016-08-27 07:35:48 PDT
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
Comment 32 Build Bot 2016-08-27 07:35:55 PDT
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
Comment 33 youenn fablet 2016-12-14 06:30:55 PST
Created attachment 297085 [details]
Patch
Comment 34 youenn fablet 2016-12-16 01:14:46 PST
Created attachment 297308 [details]
Patch for landing
Comment 35 WebKit Commit Bot 2016-12-16 03:51:53 PST
Comment on attachment 297308 [details]
Patch for landing

Clearing flags on attachment: 297308

Committed r209917: <http://trac.webkit.org/changeset/209917>
Comment 36 WebKit Commit Bot 2016-12-16 03:52:03 PST
All reviewed patches have been landed.  Closing bug.