Bug 210303 – Changes to shared testing JS files should not cause test failures due to console message line numbers changing

• Status: RESOLVED
• Resolution: FIXED
• Component: Tools / Tests

[Simon Fraser (smfr)]

Changing ui-helpers.js can cause other tests that include it, and which trigger console logging to fail:

--- /Volumes/Data/worker/macOS-Mojave-Release-WK2-Tests-EWS/build/layout-test-results/http/tests/adClickAttribution/anchor-tag-attributes-validation-expected.txt
+++ /Volumes/Data/worker/macOS-Mojave-Release-WK2-Tests-EWS/build/layout-test-results/http/tests/adClickAttribution/anchor-tag-attributes-validation-actual.txt
@@ -1,14 +1,14 @@
-CONSOLE MESSAGE: line 197: adcampaignid must have a non-negative value less than or equal to 63 for Ad Click Attribution.
-CONSOLE MESSAGE: line 197: adcampaignid must have a non-negative value less than or equal to 63 for Ad Click Attribution.
-CONSOLE MESSAGE: line 197: adcampaignid can not be converted to a non-negative integer which is required for Ad Click Attribution.
-CONSOLE MESSAGE: line 197: adcampaignid can not be converted to a non-negative integer which is required for Ad Click Attribution.
-CONSOLE MESSAGE: line 197: adcampaignid can not be converted to a non-negative integer which is required for Ad Click Attribution.
-CONSOLE MESSAGE: line 197: addestination could not be converted to a valid HTTP-family URL.
-CONSOLE MESSAGE: line 197: addestination could not be converted to a valid HTTP-family URL.
-CONSOLE MESSAGE: line 197: addestination could not be converted to a valid HTTP-family URL.
-CONSOLE MESSAGE: line 197: Both adcampaignid and addestination need to be set for Ad Click Attribution to work.
-CONSOLE MESSAGE: line 197: Both adcampaignid and addestination need to be set for Ad Click Attribution to work.
-CONSOLE MESSAGE: line 197: addestination can not be the same site as the current website.
+CONSOLE MESSAGE: line 207: adcampaignid must have a non-negative value less than or equal to 63 for Ad Click Attribution.
+CONSOLE MESSAGE: line 207: adcampaignid must have a non-negative value less than or equal to 63 for Ad Click Attribution.
+CONSOLE MESSAGE: line 207: adcampaignid can not be converted to a non-negative integer which is required for Ad Click Attribution.
+CONSOLE MESSAGE: line 207: adcampaignid can not be converted to a non-negative integer which is required for Ad Click Attribution.
+CONSOLE MESSAGE: line 207: adcampaignid can not be converted to a non-negative integer which is required for Ad Click Attribution.
+CONSOLE MESSAGE: line 207: addestination could not be converted to a valid HTTP-family URL.
+CONSOLE MESSAGE: line 207: addestination could not be converted to a valid HTTP-family URL.
+CONSOLE MESSAGE: line 207: addestination could not be converted to a valid HTTP-family URL.
+CONSOLE MESSAGE: line 207: Both adcampaignid and addestination need to be set for Ad Click Attribution to work.
+CONSOLE MESSAGE: line 207: Both adcampaignid and addestination need to be set for Ad Click Attribution to work.
+CONSOLE MESSAGE: line 207: addestination can not be the same site as the current website.
 Test for validity of ad click attribution attributes on anchor tags.
 
 On success, you will see a series of "PASS" messages, followed by "TEST COMPLETE".

This is annoying and we need to fix testing infrastructure to avoid it.

[Simon Fraser (smfr)]

I propose excluding line numbers from console logs when running tests.

[Devin Rousso]

(In reply to Simon Fraser (smfr) from comment #1)
> I propose excluding line numbers from console logs when running tests.
+1

[Darin Adler]

Seems OK.

I’m a little unclear on what these line numbers are.

On the other hand, when writing tests it’s important the test results do give context of what is being tested, and where messages are coming from. I’ve had a really annoying time debugging tests when something is wrong, but there is no label explaining where the value came from in a sea of test results.

For example, look at this:

https://trac.webkit.org/changeset/259184/webkit/trunk/LayoutTests/editing/mac/input/firstrectforcharacterrange-plain-expected.txt

The old expected result was ... not good.

[Simon Fraser (smfr)]

I couldn't tell what line CONSOLE MESSAGE: line 207 referred to. It's not a line in the file that I changed. So those line numbers are very mysterious.

[Devin Rousso]

Created attachment 396021 [details]
Patch

test expected files modified using a simple regex find replace of `/CONSOLE MESSAGE: line \d+: /` with "CONSOLE MESSAGE: "

[Simon Fraser (smfr)]

(In reply to Darin Adler from comment #3)
> Seems OK.
> 
> I’m a little unclear on what these line numbers are.
> 
> On the other hand, when writing tests it’s important the test results do
> give context of what is being tested, and where messages are coming from.
> I’ve had a really annoying time debugging tests when something is wrong, but
> there is no label explaining where the value came from in a sea of test
> results.
> 
> For example, look at this:
> 
> https://trac.webkit.org/changeset/259184/webkit/trunk/LayoutTests/editing/
> mac/input/firstrectforcharacterrange-plain-expected.txt
> 
> The old expected result was ... not good.

It's possible to remotely web-inspect WebKitTestRunner. Most easily done by making the test time out, and running WTR with --no-timeout, then you can just pick it as an inspection target from Safari. That's the easiest way to discover JS errors and debug tests.

[Devin Rousso]

Created attachment 396023 [details]
Patch

rebase

[Devin Rousso]

Created attachment 396060 [details]
Patch

[Devin Rousso]

Created attachment 396100 [details]
Patch

[EWS]

Committed r259900: <https://trac.webkit.org/changeset/259900>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 396100 [details].

[Radar WebKit Bug Importer]

<rdar://problem/61603950>

[Darin Adler]

I am a little sad that since we had to touch all these files anyway, we still chose to include CONSOLE on every single line. We should ask ourselves: "How would we format this if we wanted a human being to be able to read and understand it and NOT BE SHOUTED AT?" And consider tweaking the format.

[Darin Adler]

(In reply to Simon Fraser (smfr) from comment #6)
> It's possible to remotely web-inspect WebKitTestRunner. Most easily done by
> making the test time out, and running WTR with --no-timeout, then you can
> just pick it as an inspection target from Safari. That's the easiest way to
> discover JS errors and debug tests.

Seems to not respond to my concern, though.

If the test output is good I can fix a bug without a debugging session.

[Devin Rousso]

(In reply to Darin Adler from comment #12)
> I am a little sad that since we had to touch all these files anyway, we still chose to include CONSOLE on every single line. We should ask ourselves: "How would we format this if we wanted a human being to be able to read and understand it and NOT BE SHOUTED AT?" And consider tweaking the format.

`console.*` allow for a fully customizable string to be provided as the first argument, which is what will be logged as part of `CONSOLE ___`.  I would argue that if the message isn't helpful, then the message itself should be changed, not the format in which it was logged.  This includes console messages that come from within WebKit too.

I personally believe that if the line number is critical to understanding what the message is talking about, then the message has failed to be clear enough to be useful and should be changed.

Personally, I've been wanting to do something like this for a while, as we run into this a lot with Web Inspector whenever we change 'Source/JavaScriptCore/inspector/InjectedScriptSource.js', causing a large number of unrelated tests to start failing because the line number changed.

[Darin Adler]

(In reply to Devin Rousso from comment #14)
> (In reply to Darin Adler from comment #12)
> > I am a little sad that since we had to touch all these files anyway, we still chose to include CONSOLE on every single line. We should ask ourselves: "How would we format this if we wanted a human being to be able to read and understand it and NOT BE SHOUTED AT?" And consider tweaking the format.
> 
> I personally believe that if the line number is critical to understanding
> what the message is talking about, then the message has failed to be clear
> enough to be useful and should be changed.

Sure.

My comment is about the remaining text "CONSOLE:" in front of every line. I agree the line number is not needed. I am not second-guessing this change, which is already done.

Why is "CONSOLE:" still needed?

[Devin Rousso]

(In reply to Darin Adler from comment #15)
> (In reply to Devin Rousso from comment #14)
> > (In reply to Darin Adler from comment #12)
> > > I am a little sad that since we had to touch all these files anyway, we still chose to include CONSOLE on every single line. We should ask ourselves: "How would we format this if we wanted a human being to be able to read and understand it and NOT BE SHOUTED AT?" And consider tweaking the format.
> > 
> > I personally believe that if the line number is critical to understanding what the message is talking about, then the message has failed to be clear enough to be useful and should be changed.
> 
> Sure.
> 
> My comment is about the remaining text "CONSOLE:" in front of every line. I agree the line number is not needed. I am not second-guessing this change, which is already done.
> 
> Why is "CONSOLE:" still needed?

I would have it be there to help distinguish where it came from.  Other functions, such as `alert`, have their own prefixes (like "ALERT:").

[Darin Adler]

OK. I know about these all because I originally implemented them.

I don’t like them now. While I agree we want to know where the message came from, ALL CAPITALS AT THE START OF EVERY LINE doesn’t seem like human-friendly design.