1042998 - Use StructuredLog.jsm for mochitest's structured logging

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Ahmed Kachkach [:akachkach]]

We should use the StructuredLog class implemented in bug 916265 in all JS-side structured logging (instead of using a class specific for mochitest), and also move the formatter implemented in bug 1041706 to that jsm or a separate one.

Comment 1

[Chris Manchester (limited bugmail, email directly)]

We'll either have to use SpecialPowers to access it or put the file in http://mxr.mozilla.org/mozilla-central/source/testing/mochitest/tests/SimpleTest/Makefile.in and make sure we don't become dependent on other modules.

Comment 2

[Chris Manchester (limited bugmail, email directly)]

Attachment: Use StructuredLog.jsm for mochitest logging.

This is pretty much works, but including a jsm like this is weird.

Comment 4

[Andrew Halberstadt [:ahal]]

Attachment: MozReview Request: Bug 1042998 - Use StructuredLog.jsm for mochitest logging, r=chmanchester

Bug 1042998 - Use StructuredLog.jsm for mochitest logging

Comment 5

[Andrew Halberstadt [:ahal]]

Stealing this bug.

Comment 6

[Andrew Halberstadt [:ahal]]

Try run: not stellar. I'm pretty lost as to why xpcshell selftests are breaking.. haven't looked into mochitest problems yet.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=33351482f3a7

Comment 7

[Andrew Halberstadt [:ahal]]

New try run:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=ba4fc7f838da

Fixed the xpcshell selftests issue. Opt builds look good, it's debug that have the various failures. Likely there are more types of data going through the StructuredLog.jsm. Should hopefully just be a matter of figuring out the difference between the old mochitest version and the new .jsm one.

Comment 8

[Andrew Halberstadt [:ahal]]

Still chipping away at this:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=1e47fe40e7d3

I think the Linux debug bc failures are known bustage, at least they fail on other people's try pushes too. I'm on the hook for the android and b2g mochitest-chrome bustage though.

Comment 9

[Andrew Halberstadt [:ahal]]

Finally figured it out:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=2b07c2c387bb

I'll do another full try run just in case while waiting for review.

Comment 10

[Andrew Halberstadt [:ahal]]

Comment on attachment 8657115 [details]
MozReview Request: Bug 1042998 - Use StructuredLog.jsm for mochitest logging, r=chmanchester

Bug 1042998 - Use StructuredLog.jsm for mochitest logging, r=chmanchester

Comment 11

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8657115 [details]
MozReview Request: Bug 1042998 - Use StructuredLog.jsm for mochitest logging, r=chmanchester

https://reviewboard.mozilla.org/r/18321/#review17331

::: testing/mochitest/browser-harness.xul:87
(Diff revision 2)
> -      structuredLogger: new StructuredLogger(),
> +      structuredLogger: TestRunner.structuredLogger,

If there's a structured logger available from the TestRunner global, do we need to include StructuredLog.jsm in the script tag above?

::: testing/mochitest/runtests.py:152
(Diff revision 2)
> +            #print('%s: %s' % (type(message['message']), message['message']))

Leftover debug print.

::: testing/mochitest/runtests.py:153
(Diff revision 2)
> +            if isinstance(message['message'], bytes):
> +                message['message'] = message['message'].encode('utf-8', 'replace')

I think this may have been wrong before... isn't "encode" used to go from unicode to bytes?

::: testing/mochitest/runtests.py:156
(Diff revision 2)
> +            if not isinstance(message['message'], unicode):
> +                message['message'] = unicode(message['message'])
> +

I think mozlog does this coercion for us.

::: testing/mochitest/tests/index.html:4
(Diff revision 2)
> +    <script type="application/javascript" src="SimpleTest/StructuredLog.jsm"></script>

I think I mentioned this somewhere, but I don't think this is a great way to go about this, because it means we'll break mochitests if this jsm ever starts using the Components object. It doesn't, and I don't think it's going to need to any time soon, but I think using specialpowers to access the jsm through resource://testing-common

::: testing/modules/StructuredLog.jsm:38
(Diff revision 2)
> -StructuredLogger.prototype.testStart = function (test) {
> -  this._runningTests.add(test);
> +StructuredLogger.prototype = {
> +  testStart: function (test) {

I actually prefer the Foo.prototype.bar = function () { ... syntax. I think there's a lot of both in the code base, but is there a particular reason to change it here?

::: testing/modules/StructuredLog.jsm:94
(Diff revision 2)
> +    var data = {tests: tests};

Right... using this in content means s/let/var/, yuck.

::: testing/modules/StructuredLog.jsm:148
(Diff revision 2)
> +  isValid: function(message) {
> +    return message.action !== undefined && VALID_ACTIONS.indexOf(message.action) >= 0;
> +  },

Where is this called?

Comment 12

[Andrew Halberstadt [:ahal]]

https://reviewboard.mozilla.org/r/18321/#review17331

> If there's a structured logger available from the TestRunner global, do we need to include StructuredLog.jsm in the script tag above?

I think I tried importing it globally in TestRunner.js but couldn't get it to work across all platform and flavour combinations. See comment below as well.

> I think this may have been wrong before... isn't "encode" used to go from unicode to bytes?

Good catch. It worked in my try run because of the unicode coercion right after, but that may have failed on certain systems.

> I think mozlog does this coercion for us.

True, but all of the mochitest outputHandlers get called before the message ever reaches mozlog, so we need to do it a little earlier on.

> I think I mentioned this somewhere, but I don't think this is a great way to go about this, because it means we'll break mochitests if this jsm ever starts using the Components object. It doesn't, and I don't think it's going to need to any time soon, but I think using specialpowers to access the jsm through resource://testing-common

Ok, I'll take another look. But I've spent the better part of a week trying to get this imported across android/b2g/desktop on all flavours.. my frustration level at this problem is currently very high :p. So if I can't get it working right away, mind if I land as is and file a follow-up?

> I actually prefer the Foo.prototype.bar = function () { ... syntax. I think there's a lot of both in the code base, but is there a particular reason to change it here?

Not particularly.. I guess it's a matter of taste. I got used to it this way when working with the gaia automation, so figured might as well copy them. Now I find the Foo.prototype.bar method somewhat wordy and ugly looking.

> Where is this called?

It's not, but it used to exist in the mochitest version.. figured it could potentially be useful to a consumer, but I can remove it if you prefer.

Comment 13

[Andrew Halberstadt [:ahal]]

So when I import StructuredLog.jsm via SpecialPowers.Cu.import, I get errors like:
TEST-UNEXPECTED-FAIL: setup.js | error parsing http://mochi.test:8888/tests.json (TypeError: TestRunner.structuredLogger.info is not a function)
JavaScript error: http://mochi.test:8888/tests/SimpleTest/TestRunner.js, line 348: TypeError: TestRunner.structuredLogger.info is not a function

I'm not entirely sure why.. Also when importing via specialpowers you can't modify the structuredLogger object, i.e we can't add the 'disableBuffering' and 'enableBuffering' functions (though this is easily worked around).

Chris any ideas? Or is it ok if I land the patch with the server.js hack, and file a follow-up bug to fix it properly later? I really don't want to waste much more time on this.

Comment 14

[Chris Manchester (limited bugmail, email directly)]

I can probably find time to figure out the problem with specialpowers, but maybe not in the next week or two.

What is this blocking? As far as I can tell this bug is mostly about cleaning things up by de-duplicating code, so I don't think landing temporary hacks really makes sense, but I don't think I'm up to speed on the overall plan here.

Comment 15

[Andrew Halberstadt [:ahal]]

It technically isn't blocking anything, but I want to use StructuredLog.jsm for reftest. If we don't land this now, we'll have to deal with all of xpcshell, mochitest and reftest at the same time when we land it in the future. Plus if we don't land this now, there's a high probability that we'll forget about it again like last time.

I also don't really think serving it to content is that big of a hack. It's fine if you disagree, but as long as you agree this is an incremental improvement over the status quo.. then we might as well land it while the try run is still green.

Here is said try run btw:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=6c33a90b793b

Comment 16

[Chris Manchester (limited bugmail, email directly)]

I'd really rather figure out the specialpowers thing. I'm blocked on other stuff right now, I'll give it a go this week.

Comment 17

[Andrew Halberstadt [:ahal]]

Comment on attachment 8657115 [details]
MozReview Request: Bug 1042998 - Use StructuredLog.jsm for mochitest logging, r=chmanchester

Bug 1042998 - Use StructuredLog.jsm for mochitest logging, r=chmanchester

Comment 18

[Chris Manchester (limited bugmail, email directly)]

Attachment: Patch to access StructuredLog.jsm from SpecialPowers

This approach works well locally. We can get jmaher to sign off on it as well, there might be a simpler approach. If this causes problems on android/b2g for some reason we can just drop it.

Comment 19

[Andrew Halberstadt [:ahal]]

Didn't work quite as well on try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=a7f6a570b626

Let me know how you want to proceed.

Comment 20

[Chris Manchester (limited bugmail, email directly)]

The b-c issue looks trivial, but it looks like the testing modules dir isn't even set on b2g/Android, so that could be a huge hassle to deal with.

I still have reservations, but we can take some form of the original patch.

Comment 21

[Andrew Halberstadt [:ahal]]

Comment on attachment 8657115 [details]
MozReview Request: Bug 1042998 - Use StructuredLog.jsm for mochitest logging, r=chmanchester

Bug 1042998 - Use StructuredLog.jsm for mochitest logging, r=chmanchester

Comment 22

[Andrew Halberstadt [:ahal]]

Apparently Chris got the specialpowers method working, but it slowed everything down, and even caused some b2g emulator mochitests to reach the per test timeout. Per discussion, re-requesting review.

Comment 23

[Chris Manchester (limited bugmail, email directly)]

Attachment: Access StructuredLog.jsm through specialpowers rather than serving it as a content script

The aformentioned patch in case we need to come back to this.

Comment 24

[Chris Manchester (limited bugmail, email directly)]

https://reviewboard.mozilla.org/r/18321/#review17331

> It's not, but it used to exist in the mochitest version.. figured it could potentially be useful to a consumer, but I can remove it if you prefer.

Let's remove it. Dead code makes code hard to understand.

Comment 25

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8657115 [details]
MozReview Request: Bug 1042998 - Use StructuredLog.jsm for mochitest logging, r=chmanchester

https://reviewboard.mozilla.org/r/18321/#review18455

::: testing/mochitest/runtests.py:155
(Diff revision 4)
> +            if not isinstance(message['message'], unicode):

Can this be `elif` ?

Comment 26

[Andrew Halberstadt [:ahal]]

Comment on attachment 8657115 [details]
MozReview Request: Bug 1042998 - Use StructuredLog.jsm for mochitest logging, r=chmanchester

Bug 1042998 - Use StructuredLog.jsm for mochitest logging, r=chmanchester

Comment 27

[Andrew Halberstadt [:ahal]]

Here's an updated try run:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=895a627d439d

Pretty sure the intermittents are unrelated. All those emulator debug xpcshell failures also show up on previous pushes.

Comment 28

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/7a6ec65f10fd

Comment 29

[Andrew Halberstadt [:ahal]]

Oh, the other thing I just remembered w.r.t to SpecialPowers... there was talk of trying to kill it due to security concerns with the new addon signing requirements. I imagine this might never happen, and if it does, would be a long way away. But it still might be a good idea to avoid it whenever possible.

Comment 30

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/7a6ec65f10fd