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?).

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.

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

(Note there are no review flags set)

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.

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.

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.

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

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.

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

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

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, ...)>

: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

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

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.

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

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.

(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.