Chris Manchester (limited bugmail, email directly) Assignee
	Description • 10 years ago

As seen in https://bugzilla.mozilla.org/show_bug.cgi?id=956739#c33, and associated discussion, the tbplformatter we have in mozlog.structured is not satisfying tbpl. I was looking at failing vs. passing jobs as the standard for tbpl parity when working on this. There are other purposes it needs to take into account (starring, others?).

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 1 • 10 years ago

jgriffin pointed me to https://wiki.mozilla.org/Sheriffing/Job_Visibility_Policy#6.29_Outputs_failures_in_a_TBPL-starrable_format I'll use this as a guide and post a patch this afternoon.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 3 • 10 years ago

bzexport ignored my comment. Weird. Here it is:

A straightforward change to the formatter. This depends on the "message" field of the logged message being as expected (which was not the case with my patch for marionette).

I have a try run seeded with a failure and hang running here:
https://tbpl.mozilla.org/?tree=Try&rev=4e35b593e7f5

Compare with a failure as reported with no change to logging:
https://tbpl.mozilla.org/?tree=Try&rev=6d3bc998a80e

	Ed Morley [:emorley]
	Comment 4 • 10 years ago

(Note there are no review flags set)

	James Graham [:jgraham]
	Comment 5 • 10 years ago

Comment on attachment 8446800 [details] [diff] [review]
Modify tbplformatter to comply with tbpl

Review of attachment 8446800 [details] [diff] [review]:
-----------------------------------------------------------------

I think this patch will probably make thing work for the tbpl regexp (but Ed or someone should review it to be sure), but it removes too much information that's needed by humans reading the logs.

::: testing/mozbase/mozlog/mozlog/structured/formatters/tbplformatter.py
@@ +36,5 @@
>  
>      def test_status(self, data):
>          if "expected" in data:
> +            return "TEST-UNEXPECTED-%s | %s | %s\n" % (
> +                data["status"], self.id_str(data["test"]), data.get("message", ""))

We need the subtest name in here somewhere or it's hopeless to work out what's going on from the logs. I don't know how existing testsuites deal with this, but we could take inspiration from there, or invent something that still matches the general regexp.

We also need the data that you removed, but on a separate line.

@@ +47,5 @@
>          time = data["time"] - start_time
>  
>          if "expected" in data:
> +            return "TEST-UNEXPECTED-%s | %s | %s\n" % (
> +                data["status"], self.id_str(data["test"]), data.get("message", ""))

Can we return a second line with the expected status and the duration? That's important information for a human reading the logs.

	Ahmed Kachkach [:akachkach]
	Comment 6 • 10 years ago

I think just switching those pipes to another character (like "-" or "#") would work in that case. We'd still match the regexps and we'd have the information available.

	James Graham [:jgraham]
	Comment 7 • 10 years ago

It maybe makes sense for the subtest ids, although I don't know if there are any cases where that would change the actual bug string, preventing a match with existing bugs on tbpl. Possibly not since nothing currently uses subtests.

I don't think it makes sense for duration.

I suggest we do something like:

message = data.get("message", "").split("\n", 1)
msg_id = message[0]

if len(message) == 2 and message[1].strip():
    suffix = "TEST-INFO - Extra log information:\n%s\n" % message[1]
else:
    suffix = ""

rv = """TEST-UNEXPECTED-%s | %s | %s
TEST-INFO - expected %s | duration %s
%s""" % (data["status"], self.id_str(data["test"]), msg_id, data["expected"], time, suffix)

Obviously that's only a sketch, but it seems to fulfill all the requirements here.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 9 • 10 years ago

This will not produce the same strings as before (see the slight difference in test name in the two logs linked in comment 3). Is this acceptable?

Here's what a failed marionette assertion will look like now (the "test_end" message):

TEST-UNEXPECTED-FAIL | test_capabilities.TestCapabilities.test_mandates_capabilities (expected PASS) | AssertionError: True is not false
Traceback (most recent call last):
  File "/home/cmanchester/m-c/testing/marionette/client/marionette/marionette_test.py", line 170, in run
    testMethod()
  File "/home/cmanchester/m-c/testing/marionette/client/marionette/tests/unit/test_capabilities.py", line 16, in test_mandates_capabilities
    self.assertFalse(True)
AssertionError: True is not false

TEST-FAIL | test_capabilities.TestCapabilities.test_mandates_capabilities | took 39ms

And here is what a test status message produced by a failed xpcshell test will look like (the "test_status" action):

TEST-UNEXPECTED-FAIL | /home/cmanchester/m-c/obj-x86_64-unknown-linux-gnu/_tests/xpcshell/testing/xpcshell/example/unit/test_sample.js - do_check_eq (expected PASS) | [do_check_eq : 733] 57 == 56

	Ed Morley [:emorley]
	Comment 10 • 10 years ago

TBPL extracts the second field and searches against that, so you can put whatever you like (within reason) in the third field and TBPL will still find the existing bug matches (and a human then sees the full bug summary to decide if that result matches the failure). However, the attached patch appears to change the second field, which will break existing searches.

	Ed Morley [:emorley]
	Comment 11 • 10 years ago

(And yeah roll on when we don't have this pipe delimited nonsense at all...!)

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 12 • 10 years ago

Sorry, formatting was botched above.

Here's what a failed marionette assertion will look like now (the "test_end" action):

TEST-UNEXPECTED-FAIL | test_capabilities.TestCapabilities.test_mandates_capabilities (expected PASS) | AssertionError: True is not false
Traceback (most recent call last):
  File "/home/cmanchester/m-c/testing/marionette/client/marionette/marionette_test.py", line 170, in run
    testMethod()
  File "/home/cmanchester/m-c/testing/marionette/client/marionette/tests/unit/test_capabilities.py", line 16, in test_mandates_capabilities
    self.assertFalse(True)
AssertionError: True is not false

TEST-FAIL | test_capabilities.TestCapabilities.test_mandates_capabilities | took 39ms

And here is what a test status message produced by a failed xpcshell test will look like (the "test_status" action):

TEST-UNEXPECTED-FAIL | /home/cmanchester/m-c/obj-x86_64-unknown-linux-gnu/_tests/xpcshell/testing/xpcshell/example/unit/test_sample.js - do_check_eq (expected PASS) | [do_check_eq : 733] 57 == 56

	Ahmed Kachkach [:akachkach]
	Comment 13 • 10 years ago

On mochitest, with unstructured logs, a TEST-UNEXPECTED-FAIL message looks something like:

TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_fragment_play.html | big.wav#t=7,15 fragment test: seeked currentTime is 7.768979 != 7

So I guess we could keep something like:

TEST-UNEXPECTED-FAIL | <test_name> | <additional_info (expected, subtest, message, ...)>

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 15 • 10 years ago

:akachkach, can you confirm this works with your mochitest patch?

Marionette uses the second field a bit differently, so may require its own formatter, but here's what this looks like for xpcshell:

test_status:

TEST-UNEXPECTED-FAIL | /home/cmanchester/m-c/obj-x86_64-unknown-linux-gnu/_tests/xpcshell/testing/xpcshell/example/unit/test_sample.js | do_check_eq - [do_check_eq : 733] 57 == 56
TEST-INFO | expected PASS

test_end:

TEST-UNEXPECTED-FAIL | /home/cmanchester/m-c/obj-x86_64-unknown-linux-gnu/_tests/xpcshell/testing/xpcshell/example/unit/test_sample.js | xpcshell return code: 0
TEST-INFO expected PASS | took 53ms

	Ahmed Kachkach [:akachkach]
	Comment 16 • 10 years ago

Comment on attachment 8448149 [details] [diff] [review]
Modify tbplformatter to comply with tbpl

Review of attachment 8448149 [details] [diff] [review]:
-----------------------------------------------------------------

Did a try push with the mochitest patch and added errors (timeout/crash). Seems to be working fine!
(except for b2g, but that's not related to this patch. filed bug 1030330)

https://tbpl.mozilla.org/?tree=Try&rev=280964bc14c0

	James Graham [:jgraham]
	Comment 17 • 10 years ago

Comment on attachment 8448149 [details] [diff] [review]
Modify tbplformatter to comply with tbpl

Review of attachment 8448149 [details] [diff] [review]:
-----------------------------------------------------------------

Looks fine.

I'm not sure that this will be more readable output than the failure line / info / traceback suggestion I had, but I'm not sure it won't either.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 19 • 10 years ago

Comment on attachment 8448739 [details] [diff] [review]
Modify mozlog.structured's tbplformatter to comply with tbpl

Updated commit message.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 20 • 10 years ago

https://hg.mozilla.org/integration/mozilla-inbound/rev/9b21892ec1d1

	Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)
	Comment 21 • 10 years ago

https://hg.mozilla.org/mozilla-central/rev/9b21892ec1d1

	Ahmed Kachkach [:akachkach]
	Comment 22 • 10 years ago

This patch switched the test_end output to "TEST-<status> | testname | message" when we don't have an error. So something like "TEST-OK | browser/content/mytest.html | some message".

Mochitest (and probably old test-harnesses) uses "TEST-END" for finished tests when there's no error (http://dxr.mozilla.org/mozilla-central/search?q=TEST-END&redirect=true), so it's probably a good idea to keep it that way.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 23 • 10 years ago

(In reply to Ahmed Kachkach [:akachkach] from comment #22)
> This patch switched the test_end output to "TEST-<status> | testname |
> message" when we don't have an error. So something like "TEST-OK |
> browser/content/mytest.html | some message".
> 
> Mochitest (and probably old test-harnesses) uses "TEST-END" for finished
> tests when there's no error
> (http://dxr.mozilla.org/mozilla-central/search?q=TEST-END&redirect=true), so
> it's probably a good idea to keep it that way.

This isn't uniform across test harnesses: xpcshell, for instance, logs "TEST-PASS | <filename>". I'm not aware of any tools that will break if we log "TEST-OK | ...". If there aren't any, I don't think this should block mochitests or other conversions. I'd love to avoid a formatter per harness just to satisfy tbpl during the transition, but we may be headed in that direction.

In any event, I agree "TEST-OK | ..." looks a litte funny. Please file a follow up if you have a change in mind that makes the logs more legible and works across harnesses.