1041708 - Structured logging seems to eat test case name and message if a single test is executed

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Nils Ohlmeier [:drno]]

Since updating mozilla-central this morning when I execute a single test case like this:
./mach mochitest-plain dom/media/tests/mochitest/test_peerConnection_basicVideo.html

the output is filled with lines like this:

748 INFO unknown test url | TEST-PASS |

These lines should look like this:

19703 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_throwInCallbacks.html | Seven expected errors verified.

The problem here is not so much the "unkown test url" part, we have had that in the past (and as long as you run only a single test case it does not really matter), but the actual message from the test is missing. So having hundreds of lines just saying TEST-PASS is not very helpful.

Note: info() messages still come through like this:
297 INFO timeupdate fired for media element pcRemote_local_video | undefined

Although that "| undefined" is new and annoying as well.

I'm assuming these are fall outs from bug 886570 landing.

Comment 1

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1041708-Structured-logging-seems-to-eat-test-cas.patch

This should fix both issues.
Logs now look like this:

529 INFO PeerConnectionWrapper (pcLocal): 'onsignalingstatechange' event fired
530 INFO TEST-PASS | unknown test url | PeerConnectionWrapper (pcLocal): legal signaling state transition from have-local-offer to stable
531 INFO PeerConnectionWrapper (pcLocal): 'onsignalingstatechange' event 'stable' received
532 INFO PeerConnectionWrapper (pcLocal): Successfully set remote description
533 INFO TEST-PASS | unknown test url | signalingState after local setRemoteDescription is 'stable'
534 INFO Run step: PC_LOCAL_WAIT_FOR_ICE_CONNECTED

Comment 2

[Andrew Halberstadt [:ahal]]

Comment on attachment 8459780 [details] [diff] [review]
0001-Bug-1041708-Structured-logging-seems-to-eat-test-cas.patch

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

Lgtm.

::: testing/mochitest/tests/SimpleTest/SimpleTest.js
@@ +362,5 @@
>                                                   result.expected,
>                                                   diagnostic);
>      } else if (typeof dump === "function") {
> +        var diagMessage = test.name + (test.diag ? " - " + test.diag : "");
> +        var debugMsg = [result.message, url, diagMessage].join(' | ');

We don't need whatever was stored in 'diagnostic' anymore?

Comment 3

[Ahmed Kachkach [:akachkach]]

Thanks for the review,

diagnostic is still used (when a runner is present), it's just that we create a different diagnostic strubg (that includes the test name) when no parent runner is present.

Try run: https://tbpl.mozilla.org/?tree=Try&rev=911224f42b56

Comment 4

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/8b09e3fb13ff

Comment 6

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/8b09e3fb13ff

Comment 7

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/545626e39709