Closed Bug 1033126 Opened 10 years ago Closed 10 years ago

XPCShell should use mozlog.structured

Categories

(Testing :: XPCShell Harness, defect)

Product:
Testing
Component:
XPCShell Harness
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED
Milestone:
mozilla36

People

(Reporter: chmanchester, Assigned: chmanchester)

References

(Blocks 2 open bugs)

Details

Attachments

(2 files, 11 obsolete files)

Convert xpcshell tests to use mozlog.structured format for logging.
125.80 KB, patch
chmanchester
: review+
Details | Diff | Splinter Review
xunit-remove.diff
1.12 KB, patch
Details | Diff | Splinter Review 
The XPCShell harness has log data in a structured format, but doesn't expose it in a useful way, and doesn't implement the format specified by the mozlog.structured. 

XPCShell tests should use mozlog.structured for test results and general logging.
Currently xpcshell test failures are slightly annoying, since the log output often has the failure message spread across two lines, eg:

https://tbpl.mozilla.org/php/getParsedLog.php?id=42860586&tree=Mozilla-Inbound
TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/dom/plugins/test/unit/test_bug455213.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/head.js | "Plug-in for testing purposes.â„¢ (हिनà¥\x8Dदी 中文 العربية)" == "Plug-in for testing purposes.™ (हिन्दी 中文 العربية)" - See following stack:

With the second line causing false positives, since TBPL will try searching for intermittent failure bugs containing "head.js". In addition, having the failure split across two lines makes the failure slower to grok (plus the SnR is low, with things like "(with xpcshell return code: 0), see following log:" adding very little value).

Anyway, if when implementing this bug:
a) It's hard to match the current xpcshell format, since it's so different from the current structured format.
b) Or, it's easy to fix this at the same time.

...then I just wanted to say that not preserving the exact format for xpcshell would actually be a good thing, unlike the mochitests bug etc :-)
OS: Mac OS X → All
Hardware: x86 → All
Sounds interesting. I guess while I'm awaiting review on that mochitest bug, I could give this a look (except if you're planning to take care of it, chmanchester). Would need some help to get started, but it certainly look smaller than mochitest.
(In reply to Ahmed Kachkach [:akachkach] from comment #2)
> Sounds interesting. I guess while I'm awaiting review on that mochitest bug,
> I could give this a look (except if you're planning to take care of it,
> chmanchester). Would need some help to get started, but it certainly look
> smaller than mochitest.

I'm well on my way here (it followed on directly from some work last summer), but if you're interested in working on converting other harnesses to structured logging, I know there are a few in the pipeline, so maybe check with ahal or jgriffin on that.
In this patch each test assertion is logged as a test_status message, and general exceptions/errors in the javascript runner are conveyed by logging at the error level.

This approach fixes the issue of failure logs always pointing to head.js, although it will still log multiple lines per failure (one for the file plus one for each failed assertion or exception/error). We could fix this in a formatter -- the file status is logged as a test_end, each assertion a test_status, so maybe only test_end should emit "TEST-UNEXPECTED-FOO".

Try is looking pretty good:

https://tbpl.mozilla.org/?tree=Try&rev=7d45b3ac76cf
Assignee: nobody → cmanchester
Status: NEW → ASSIGNED
Attachment #8449492 - Flags: feedback?(james)
Comment on attachment 8449492 [details] [diff] [review]
Convert xpchshell tests to use mozlog.structured format for logging.

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

Looks pretty good to me.

::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
@@ +113,5 @@
>          """A list of handlers that will be called when a
>          message is logged from this logger"""
>          return self._handlers[self.name]
>  
> +    def log_raw(self, data):

This is part of the mochitest patch too, right?

::: testing/xpcshell/mach_commands.py
@@ +120,5 @@
>  
>          # Obtain a reference to the xpcshell test runner.
>          import runxpcshelltests
>  
> +        logger = structured.commandline.setup_logging("XPCShell",

Presumably you can't actually pass logging command line args in here. We need to sort out bug 1027665 but I don't know what the right fix is. Being able to do things like --log-xunit=file.xml seems useful.

::: testing/xpcshell/runxpcshelltests.py
@@ +256,4 @@
>  
>      def testTimeout(self, test_file, proc):
>          if not self.retry:
> +            self.logger.error("%s | Test timed out" % test_file)

So can't we set the test status to TIMEOUT in this case? Or does that happen elsewhere?

@@ +449,5 @@
> +                                       line,
> +                                       command=self.complete_command)
> +        else:
> +            if 'message' in line:
> +                line['message'] = cleanup_encoding(line['message'])

So I'm assuming that this is being called with an object decoded from JSON, and that cleanup_encoding does more or less what it sounds like. But the JSON had to be UTF8 encoded or we couldn't parse it. Are we really only cleaning up things here that are valid UTF8 but were intended to be some other encoding? And is there some reason that we can't just force the output to be actual UTF8.

@@ +452,5 @@
> +            if 'message' in line:
> +                line['message'] = cleanup_encoding(line['message'])
> +            self.logger.log_raw(line)
> +            if 'extra' in line and 'stack' in line['extra']:
> +                self.logger.process_output(self.proc_ident,

Elsewhere stacks have just gone in the message.

Doesn't this mean that the stack will get double logged? I suppose that's not a big issue, but maybe there's a better solution.

@@ +460,5 @@
> +    def log_full_output(self, output):
> +        """Log output any buffered output from the test process"""
> +        if not output:
> +            return
> +        self.logger.info(">>>>>>>")

I assume this is what we had before. It seems quite verbose to me, but whatever.

@@ +482,5 @@
> +        if not line_string or line_string == '\n':
> +            return
> +
> +        if not line_string.startswith('{'):
> +            # Premature optimization is the root of all evil, but only 97% of the time.

It's not premature if you have data to suggest that it's worthwhile. Do you?

@@ +512,3 @@
>          self.report_message(line_object)
>  
> +        if action == 'log' and line_object['message'] == 'CHILD-TEST-STARTED':

What does this actually mean? Is there something more structured that we ought to be doing here?

@@ +525,3 @@
>          # Check for skipped tests
>          if 'disabled' in self.test_object:
> +            self.logger.info('skipping %s | %s' %

You could produce a test_start and test_end message with the status SKIP here.

@@ +624,3 @@
>                      return
>  
> +                self.logger.test_end(name, status, expected=expected, message=message)

Seems like you could break this out of the if, unless you really want the full output to come after the test end?

@@ -998,3 @@
>              proc.terminate()
>  
> -    def writeXunitResults(self, results, name=None, filename=None, fh=None):

\o/
Attachment #8449492 - Flags: feedback?(james) → feedback+
(In reply to James Graham [:jgraham] from comment #5)
> Comment on attachment 8449492 [details] [diff] [review]
> Convert xpchshell tests to use mozlog.structured format for logging.
> 
> Review of attachment 8449492 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks pretty good to me.
> 
> ::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py
> @@ +113,5 @@
> >          """A list of handlers that will be called when a
> >          message is logged from this logger"""
> >          return self._handlers[self.name]
> >  
> > +    def log_raw(self, data):
> 
> This is part of the mochitest patch too, right?
> 
> ::: testing/xpcshell/mach_commands.py
> @@ +120,5 @@
> >  
> >          # Obtain a reference to the xpcshell test runner.
> >          import runxpcshelltests
> >  
> > +        logger = structured.commandline.setup_logging("XPCShell",
> 
> Presumably you can't actually pass logging command line args in here. We
> need to sort out bug 1027665 but I don't know what the right fix is. Being
> able to do things like --log-xunit=file.xml seems useful.
Yes, this is a little abusive of the API as written. I looked at bug 10227665 a bit yesterday, it's conceivable we could replace all of mach's logging with mozlog.structured, but maybe there's an easier middle ground.
> 
> ::: testing/xpcshell/runxpcshelltests.py
> @@ +256,4 @@
> >  
> >      def testTimeout(self, test_file, proc):
> >          if not self.retry:
> > +            self.logger.error("%s | Test timed out" % test_file)
> 
> So can't we set the test status to TIMEOUT in this case? Or does that happen
> elsewhere?
> 
> @@ +449,5 @@
> > +                                       line,
> > +                                       command=self.complete_command)
> > +        else:
> > +            if 'message' in line:
> > +                line['message'] = cleanup_encoding(line['message'])
> 
> So I'm assuming that this is being called with an object decoded from JSON,
> and that cleanup_encoding does more or less what it sounds like. But the
> JSON had to be UTF8 encoded or we couldn't parse it. Are we really only
> cleaning up things here that are valid UTF8 but were intended to be some
> other encoding? And is there some reason that we can't just force the output
> to be actual UTF8.
I can check with someone who understands this fix better, but it looks like cleanup_encoding is meant to be called right before printing a message. I was misusing it at some point working on this and found that calling it before calling json.loads actually invalidated the json in lines containing escaped double quotes.
> 
> @@ +452,5 @@
> > +            if 'message' in line:
> > +                line['message'] = cleanup_encoding(line['message'])
> > +            self.logger.log_raw(line)
> > +            if 'extra' in line and 'stack' in line['extra']:
> > +                self.logger.process_output(self.proc_ident,
> 
> Elsewhere stacks have just gone in the message.
> 
> Doesn't this mean that the stack will get double logged? I suppose that's
> not a big issue, but maybe there's a better solution.
I don't think stacks are double logged here, but they might be harder (visually) to associate with their originating failure message. I will post some sample output and solicit feedback.
> 
> @@ +460,5 @@
> > +    def log_full_output(self, output):
> > +        """Log output any buffered output from the test process"""
> > +        if not output:
> > +            return
> > +        self.logger.info(">>>>>>>")
> 
> I assume this is what we had before. It seems quite verbose to me, but
> whatever.
> 
> @@ +482,5 @@
> > +        if not line_string or line_string == '\n':
> > +            return
> > +
> > +        if not line_string.startswith('{'):
> > +            # Premature optimization is the root of all evil, but only 97% of the time.
> 
> It's not premature if you have data to suggest that it's worthwhile. Do you?
> 
> @@ +512,3 @@
> >          self.report_message(line_object)
> >  
> > +        if action == 'log' and line_object['message'] == 'CHILD-TEST-STARTED':
> 
> What does this actually mean? Is there something more structured that we
> ought to be doing here?
> 
> @@ +525,3 @@
> >          # Check for skipped tests
> >          if 'disabled' in self.test_object:
> > +            self.logger.info('skipping %s | %s' %
> 
> You could produce a test_start and test_end message with the status SKIP
> here.
> 
> @@ +624,3 @@
> >                      return
> >  
> > +                self.logger.test_end(name, status, expected=expected, message=message)
> 
> Seems like you could break this out of the if, unless you really want the
> full output to come after the test end?
This is a little funny because tests are retried if they fail the first time... which makes me realize I must be logging multiple test_starts as is. I guess this should log test_end with a status of skip when retrying.
> 
> @@ -998,3 @@
> >              proc.terminate()
> >  
> > -    def writeXunitResults(self, results, name=None, filename=None, fh=None):
> 
> \o/
Depends on: 1034221
Update to deal with timeouts correctly, unbitrot and other small fixes.
Attachment #8449492 - Attachment is obsolete: true
gos, maybe you'd take a look at this one?
Attachment #8452576 - Flags: feedback?(gps)
Attachment #8450597 - Attachment is obsolete: true
Comment on attachment 8452576 [details] [diff] [review]
Convert xpchshell tests to use mozlog.structured format for logging.

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

Very nice!

I didn't look over this in super detail. I don't think I know enough about what all you've been up to lately to add that much value.

If automation and developers are happy with the change, everything here seems like a giant, largely invisible refactor. But we both know it is more important than that :)

I am curious what the overall performance impact of this is. I doubt it will be enough to raise any flags. But always good to measure.

::: testing/mozbase/mozlog/mozlog/structured/handlers/__init__.py
@@ +62,5 @@
>              return
>          with self._lock:
>              #XXX Should encoding be the formatter's responsibility?
>              try:
> +                self.stream.write(formatted.encode("utf-8", "replace"))

You should add an explicit test for this behavior. We have a large number of Unicode bugs that creep in. Having test coverage to catch changes in behavior would help catch unexpected surprises.

I approve of "replace" here.

::: testing/xpcshell/head.js
@@ +51,2 @@
>  }
> +let _LoggerClass = Components.utils.import("resource://testing-common/StructuredLog.jsm", null).StructuredLogger;

What happens to performance of xpcshell tests when we introduce this import? Historically adding global imports to xpcshell tests has a measurable impact on run-time.

@@ +558,5 @@
>          // has already been logged so there is no need to log it again. It's
>          // possible that this will mask an NS_ERROR_ABORT that happens after a
>          // do_check failure though.
>          if (!_quit || e != Components.results.NS_ERROR_ABORT) {
> +          let extra = undefined;

You don't need "= undefined". "let extra;" will create a variable that is undefined.
Attachment #8452576 - Flags: feedback?(gps) → feedback+
This patch:
     Disallows tests with the same path (used as an id) running concurrently
     Puts mozlog in tests.zip
     Fixes paired test_start/test_end logging in the presence of retried tests.
     Adds basic selftests for logging unicode and timeouts

I'll flag for review once we have bug 1043039 or an equivalent fix in place and try looks ok.
Attachment #8452576 - Attachment is obsolete: true
The request in bug 1034221 (turning off xpcshell on tegras since they don't use mozharness) was completed in bug 1033507.
Depends on: 1033507
No longer depends on: 1034221
A few different try runs with this patch have an intermittent OS X 10.8 debug timeout in the vicinity of failures associated with bug 1026805 but attributed to a nearby test file that's not a known intermittent:

Failure on try with this patch:
https://tbpl.mozilla.org/php/getParsedLog.php?id=45511977&tree=Try&full=1

Failure on recent m-c:
https://tbpl.mozilla.org/php/getParsedLog.php?id=44630106&tree=Mozilla-Central&full=1#error1

With this patch the file just prior to the one on m-c is blamed for the timeout (both are in the sequential section of tests at the end of the test run). So it looks like I'm misattributing timeouts, but I can't reproduce this by introducing hangs in test files locally or on try or hacking up mach to run until failure, so I'm still looking into it.

There are also consistent uninformative timeouts in the b2g emulator tests that I'm trying to reproduce locally.
My working theory on the b2g emulator (ICS debug) timeouts is that times for these runs has recently approached the global 2 hour timeout (bug 1050827 suggests this), and whatever overhead introduced by structured logging pushes the run closer to that threshold, making somewhat frequent bustage very frequent. This try push tells that story pretty well, with each passing run very close to the threshold:

https://tbpl.mozilla.org/?tree=Try&rev=1a9af7ab0719

I think I can either invest some time profiling and optimizing the harness and mozlog and hope that is fruitful, or find a way to make these runs acceptable to our infrastructure by increasing the global timeout or running these in chunks.

ahal, maybe you have some advice on how to deal with this? Much appreciated!
Flags: needinfo?(ahalberstadt)
Huh, I had no idea X was taking so long. The most common approach is to just chunk the suite, though if there are easy perf wins we can make, that is obviously preferred.

So it looks like structured logging is relatively consistently adding ~10 minutes to the run? This looks like a good opportunity to do some profiling as there are clear numbers we can use for comparison.
Flags: needinfo?(ahalberstadt)
It sort of sounds like we need to do both, because anything we learn here about structured logging performance could be relevant to other harnesses/contexts, and because assuming there isn't an unrelated regression/optimization to address it, the current rate of timeouts is probably not acceptable.

The good news is that I'm able to consistently (over the course of 5-10 local runs) reproduce the performance penalty on a pretty small set of tests, so I'm at least slightly optimistic I'll be able to identify the source. I started experimenting on the js side by inlining the js logging mechanism to avoid the import and reduce the number of function calls. The results were inconclusive locally, but I pushed this version to try to see how the emulator tests fare:

https://tbpl.mozilla.org/?tree=Try&rev=74e12b0b3140

Next I'm going to record some profiles of the python side and do some experiments there.
I'm pretty sure I found the source of overhead locally (unnecessarily formatting stacks in head.js with my changes), but let's see how the emulator tests do:

https://tbpl.mozilla.org/?tree=Try&rev=4c3b384055c1

Retried the X2 tests as well because test_URIs.js had needed a longer timeout in prior versions.
This includes the main changes to the python runners and head.js. Happy to split further if that would be helpful.
Attachment #8475251 - Flags: review?(ted)
Attachment #8462236 - Attachment is obsolete: true
This is just the modifications to mach_commands.py. I haven't had an opportunity to test this for the Android or B2G cases.
Attachment #8475261 - Flags: review?(ted)
This makes selftests compatible with the logging changes. Selftests are pretty specific to the tbplformatter as a result, but that's ok for now.
Attachment #8475263 - Flags: review?(ted)
My first foray into Makefile hacks was disturbingly effective, but I expect there's a better way to achieve this.
Attachment #8475267 - Flags: review?(ted)
Comment on attachment 8475267 [details] [diff] [review]
Put mozlog in the xpcshell directory of tests.zip for tests not using mozharness

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

::: testing/xpcshell/Makefile.in
@@ +17,5 @@
>    moz-http2 \
>    $(NULL)
>  
> +# Mozlog is copied over manually for the sake of automation jobs not
> +# using mozharness.

I don't think we have any of these anymore. Can you see if this is still necessary? (bug 1049739 fixed the emulator tests.)
Attachment #8475267 - Flags: review?(ted)
(In reply to Ted Mielczarek [:ted.mielczarek] from comment #21)
> Comment on attachment 8475267 [details] [diff] [review]
> Put mozlog in the xpcshell directory of tests.zip for tests not using
> mozharness
> 
> Review of attachment 8475267 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: testing/xpcshell/Makefile.in
> @@ +17,5 @@
> >    moz-http2 \
> >    $(NULL)
> >  
> > +# Mozlog is copied over manually for the sake of automation jobs not
> > +# using mozharness.
> 
> I don't think we have any of these anymore. Can you see if this is still
> necessary? (bug 1049739 fixed the emulator tests.)

The word in bug 1033147 was "at least Thunderbird".
No longer depends on: 1052800
Comment on attachment 8475263 [details] [diff] [review]
Modify and add selftests for xpcshell structured logging

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

Boy, having selftests makes invasive harness changes a lot less scary, doesn't it?

I think given the existence of structured logs, it would make sense to write future tests to check the test results using those logs. Assuming we have tests for the TBPL/mach formatters, we shouldn't need to test that output format.

Can you file a followup to convert the tests here to use the structured logs instead of the formatted logs? We could keep one sanity test that checks the formatted logs, but the rest could use the structured data and ought to be clearer to write. Seems like that would be a good candidate for a mentored bug.

::: testing/xpcshell/selftest.py
@@ +82,5 @@
> +SIMPLE_LOOPING_TEST = '''
> +function run_test () { run_next_test(); }
> +
> +add_test(function test_loop () {
> +  while (1) { ; }

If you don't need an actual iloop but just a test that doesn't finish it would be nicer to write this like:
function run_test() { do_test_pending(); }

The harness will spin the event loop forever waiting for that test to finish, but it won't burn 100% CPU.

@@ +475,5 @@
> +        self.assertTestResult(True, verbose=True)
> +
> +    def testHangingTimeout(self):
> +        """
> +        Check that a test that diverges results in an appropriate error log.

This isn't a complete sentence.

@@ +490,5 @@
> +        self.assertEquals(0, self.x.passCount)
> +        self.assertEquals(0, self.x.todoCount)
> +        self.assertInLog("TEST-UNEXPECTED-TIMEOUT")
> +
> +        self.x.harness_timeout = 5 * 60

5 minutes seems really long. Can we just make this wait a few seconds instead?
Attachment #8475263 - Flags: review?(ted) → review+
Comment on attachment 8475267 [details] [diff] [review]
Put mozlog in the xpcshell directory of tests.zip for tests not using mozharness

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

::: testing/xpcshell/Makefile.in
@@ +17,5 @@
>    moz-http2 \
>    $(NULL)
>  
> +# Mozlog is copied over manually for the sake of automation jobs not
> +# using mozharness.

Ok, at least comment to the effect that this is to support Thunderbird tests. Depressing. How do those tests work currently? Are they just pulling some random old version of mozlog?
Attachment #8475267 - Flags: review+
(In reply to Ted Mielczarek [:ted.mielczarek] from comment #24)
> Comment on attachment 8475267 [details] [diff] [review]
> Put mozlog in the xpcshell directory of tests.zip for tests not using
> mozharness
> 
> Review of attachment 8475267 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: testing/xpcshell/Makefile.in
> @@ +17,5 @@
> >    moz-http2 \
> >    $(NULL)
> >  
> > +# Mozlog is copied over manually for the sake of automation jobs not
> > +# using mozharness.
> 
> Ok, at least comment to the effect that this is to support Thunderbird
> tests. Depressing. How do those tests work currently? Are they just pulling
> some random old version of mozlog?

Before this patch xpcshell doesn't use mozlog.

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #23)
> Comment on attachment 8475263 [details] [diff] [review]
> Modify and add selftests for xpcshell structured logging
> 
> Review of attachment 8475263 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Boy, having selftests makes invasive harness changes a lot less scary,
> doesn't it?
> 
> I think given the existence of structured logs, it would make sense to write
> future tests to check the test results using those logs. Assuming we have
> tests for the TBPL/mach formatters, we shouldn't need to test that output
> format.
> 
> Can you file a followup to convert the tests here to use the structured logs
> instead of the formatted logs? We could keep one sanity test that checks the
> formatted logs, but the rest could use the structured data and ought to be
> clearer to write. Seems like that would be a good candidate for a mentored
> bug.

bug 1060390

> 
> ::: testing/xpcshell/selftest.py
> @@ +82,5 @@
> > +SIMPLE_LOOPING_TEST = '''
> > +function run_test () { run_next_test(); }
> > +
> > +add_test(function test_loop () {
> > +  while (1) { ; }
> 
> If you don't need an actual iloop but just a test that doesn't finish it
> would be nicer to write this like:
> function run_test() { do_test_pending(); }
> 
> The harness will spin the event loop forever waiting for that test to
> finish, but it won't burn 100% CPU.
> 
> @@ +475,5 @@
> > +        self.assertTestResult(True, verbose=True)
> > +
> > +    def testHangingTimeout(self):
> > +        """
> > +        Check that a test that diverges results in an appropriate error log.
> 
> This isn't a complete sentence.
> 
> @@ +490,5 @@
> > +        self.assertEquals(0, self.x.passCount)
> > +        self.assertEquals(0, self.x.todoCount)
> > +        self.assertInLog("TEST-UNEXPECTED-TIMEOUT")
> > +
> > +        self.x.harness_timeout = 5 * 60
> 
> 5 minutes seems really long. Can we just make this wait a few seconds
> instead?
Comment on attachment 8475261 [details] [diff] [review]
Convert xpcshell's mach_commands.py to work with structured logging

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

::: testing/xpcshell/mach_commands.py
@@ +77,5 @@
>          if build_path not in sys.path:
>              sys.path.append(build_path)
>  
> +
> +

What's up with this whitespace?
Attachment #8475261 - Flags: review?(ted) → review+
Comment on attachment 8475251 [details] [diff] [review]
Convert xpcshell tests to use mozlog.structured format for logging

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

Overall this seems fine, but I really don't think we should do the get_test_from_queue thing. I have a lot of comments (but this is a pretty big patch).

::: dom/encoding/test/unit/head.js
@@ +87,5 @@
>  }
>  
>  function run_test() {
>    tests.forEach(function(t) {
> +    _testLogger.info("test group: " + t.msg,

Maybe we could expose this as info() in the global scope? (We really should fix that bug about scoping head.js's symbols to avoid tests using harness internals like this...)

::: testing/modules/StructuredLog.jsm
@@ +115,5 @@
>  
>    if (extra !== null) {
> +    for (let field in extra) {
> +      data[field] = extra[field];
> +    }

I think it'd be good to split this out into a separate patch. Also it would be nice if there was a comment for this method that indicated what the extra parameter was for.

::: testing/xpcshell/head.js
@@ +176,5 @@
>  function _do_main() {
>    if (_quit)
>      return;
>  
> +  _testLogger.info("(xpcshell/head.js) | running event loop");

Seems weird to have the head.js bit in the message string. (I get that you're trying to reproduce the existing output as faithfully as possible, but...)

@@ -419,3 @@
>          }
> -      } else {
> -        msgObject.source_file = "xpcshell/head.js";

Is there a reason you're removing this?

@@ +450,5 @@
>    var truePassedChecks = _passedChecks - _falsePassedChecks;
>    if (truePassedChecks > 0) {
> +    _testLogger.info("(xpcshell/head.js) | " + truePassedChecks + " (+ " +
> +                     _falsePassedChecks + ") check(s) passed");
> +    _testLogger.info("(xpcshell/head.js) | " + _todoChecks + " check(s) todo");

I think we should rip all this code out and let the Python harness deal with it.

@@ +465,3 @@
>   */
>  function _load_files(aFiles) {
>    function loadTailFile(element, index, array) {

While you're here, could you rename this to just load_file() or something?

@@ +480,5 @@
>  
> +  if (aFiles instanceof Array) {
> +    aFiles.forEach(loadTailFile);
> +  } else {
> +    loadTailFile(aFiles);

I don't understand why this change is needed.

@@ +633,5 @@
>  }
>  
>  function do_note_exception(ex, text) {
> +  let filename = Components.stack.caller.filename;
> +  _testLogger.info(text + "Swallowed exception " + _exception_message(ex),

It might be nice if the StructuredLogger API had a log.exception method for this that worked like the one in Python's logging module.

::: testing/xpcshell/runxpcshelltests.py
@@ +23,5 @@
>  from multiprocessing import cpu_count
>  from optparse import OptionParser
>  from subprocess import Popen, PIPE, STDOUT
>  from tempfile import mkdtemp, gettempdir
> +from threading import Timer, Thread, Event, current_thread

While you're here, can you reformat the lines you're touching to use parens and one-thing-per-line?
from threading import (
    Timer,
...
)

@@ +31,5 @@
>      HAVE_PSUTIL = True
>  except ImportError:
>      HAVE_PSUTIL = False
>  
> +from automation import Automation

Guess I should fix that kill_and_get_stack thing.

@@ +244,5 @@
>          """
>          return mozcrash.check_for_crashes(dump_directory, symbols_path, test_name=test_name)
>  
>      def logCommand(self, name, completeCmd, testdir):
> +        self.logger.info("%s | full command: %r" % (name, completeCmd))

Is changing log to logger just so you made sure you found all the callers? It adds a few characters to every line...

@@ -548,5 @@
>          global gotSIGINT
>  
>          name = self.test_object['path']
>  
> -        self.xunit_result = {'name': self.test_object['name'], 'classname': 'xpcshell'}

It might have been nice to remove the xunit output in a separate precededing patch to keep this patch better-focused. (Don't worry about it at this point.)

@@ +515,4 @@
>          # Check for skipped tests
>          if 'disabled' in self.test_object:
> +            self.logger.test_start(name)
> +            self.logger.test_end(name, 'SKIP', message=self.test_object['disabled'])

We could probably output a better message for tests with no disabled text (those that just have 'disabled=' in the manifest). Maybe a followup?

@@ +522,5 @@
>              self.keep_going = True
>              return
>  
>          # Check for known-fail tests
> +        expect_pass = self.test_object['expected'] == 'pass'

It would be cool if we could harmonize manifestparser and mozlog.structured here somehow, so that we didn't have to do this little dance. Maybe allowing you to pass a test object from manifestparser into the mozlog.structured methods and have it do the right thing for cases like this?

@@ +575,4 @@
>                  stdout=self.pStdout, stderr=self.pStderr, env=self.env, cwd=test_dir, timeout=testTimeoutInterval)
>  
> +            if not proc or not hasattr(proc, "pid"):
> +                self.proc_ident = self.test_object["path"]

In what situation would we hit this?

@@ +601,4 @@
>  
> +            return_code = self.getReturnCode(proc)
> +            passed = ((not self.has_failure_output) and
> +                      (return_code == 0))

You could probably fit this all on one line now.

@@ +614,3 @@
>                  if self.retry:
> +                    self.logger.test_end(name, 'SKIP', expected=expected,
> +                                         message="Test failed or timed out, will retry")

This doesn't feel like a totally correct mapping, in that we didn't skip the test, we did run it and it failed but we're going to run it again. Maybe we need to figure out a properly semantic log entry for this? I'm OK with punting that to a followup.

@@ +623,2 @@
>  
> +                self.failCount = 1

Was the original code wrong, or did you break this while hacking on other things?

@@ +644,4 @@
>  
>              if self.checkForCrashes(self.tempDir, self.symbolsPath, test_name=name):
>                  if self.retry:
> +                    self.logger.test_end(name, 'SKIP', expected=expected)

Isn't this going to produce incorrect output in the retry case? You'll have double test_end output, right?

@@ +925,5 @@
> +
> +    def get_test_from_queue(self, running_test_names, tests_queue):
> +        """
> +        Find a test in the test queue that doesn't share a name with
> +        a running test to maintain coherence in the logs.

This is kind of gross, honestly. Having our test scheduling based around test names seems really weird. Can we not use relative path names in the logs to make this not a problem? We obviously can't have two tests with the exact same pathname.

@@ +1286,5 @@
> +        self.logger.info("INFO | Result summary:")
> +        self.logger.info("INFO | Passed: %d" % self.passCount)
> +        self.logger.info("INFO | Failed: %d" % self.failCount)
> +        self.logger.info("INFO | Todo: %d" % self.todoCount)
> +        self.logger.info("INFO | Retried: %d" % len(self.try_again_list))

Ideally we'd produce this as a summary of all the structured log output instead of hand-maintaining .{pass,fail}Count etc. Fine with doing that in a followup.
Attachment #8475251 - Flags: review?(ted)
Comment on attachment 8475267 [details] [diff] [review]
Put mozlog in the xpcshell directory of tests.zip for tests not using mozharness

We were hacking sys.path all along, and I have only to move the import further down in the file (bug 849900).
Attachment #8475267 - Attachment is obsolete: true
Thanks for the thorough review. Making some responses and notes to myself as I address these.

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #27)
> Comment on attachment 8475251 [details] [diff] [review]
> Convert xpcshell tests to use mozlog.structured format for logging
> 
> Review of attachment 8475251 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Overall this seems fine, but I really don't think we should do the
> get_test_from_queue thing. I have a lot of comments (but this is a pretty
> big patch).
> 
> ::: dom/encoding/test/unit/head.js
> @@ +87,5 @@
> >  }
> >  
> >  function run_test() {
> >    tests.forEach(function(t) {
> > +    _testLogger.info("test group: " + t.msg,
> 
> Maybe we could expose this as info() in the global scope? (We really should
> fix that bug about scoping head.js's symbols to avoid tests using harness
> internals like this...)

Now that I'm thinking about it maybe we can just let do_print optionally take an object as its second argument.

> 
> ::: testing/modules/StructuredLog.jsm
> @@ +115,5 @@
> >  
> >    if (extra !== null) {
> > +    for (let field in extra) {
> > +      data[field] = extra[field];
> > +    }
> 
> I think it'd be good to split this out into a separate patch. Also it would
> be nice if there was a comment for this method that indicated what the extra
> parameter was for.

I need to come up with something less hacky for logging exceptions/errors/stacks in general.

> 
> ::: testing/xpcshell/head.js
> @@ +176,5 @@
> >  function _do_main() {
> >    if (_quit)
> >      return;
> >  
> > +  _testLogger.info("(xpcshell/head.js) | running event loop");
> 
> Seems weird to have the head.js bit in the message string. (I get that
> you're trying to reproduce the existing output as faithfully as possible,
> but...)

Removed.

> 
> @@ -419,3 @@
> >          }
> > -      } else {
> > -        msgObject.source_file = "xpcshell/head.js";
> 
> Is there a reason you're removing this?
> 
> @@ +450,5 @@
> >    var truePassedChecks = _passedChecks - _falsePassedChecks;
> >    if (truePassedChecks > 0) {
> > +    _testLogger.info("(xpcshell/head.js) | " + truePassedChecks + " (+ " +
> > +                     _falsePassedChecks + ") check(s) passed");
> > +    _testLogger.info("(xpcshell/head.js) | " + _todoChecks + " check(s) todo");
> 
> I think we should rip all this code out and let the Python harness deal with
> it.

Gone.

> 
> @@ +465,3 @@
> >   */
> >  function _load_files(aFiles) {
> >    function loadTailFile(element, index, array) {
> 
> While you're here, could you rename this to just load_file() or something?
> 
> @@ +480,5 @@
> >  
> > +  if (aFiles instanceof Array) {
> > +    aFiles.forEach(loadTailFile);
> > +  } else {
> > +    loadTailFile(aFiles);
> 
> I don't understand why this change is needed.
> 

_TEST_FILE had been a one element array to make it loadable by this function, but I'd like to use it directly as the test name when logging test status for python.

> @@ +633,5 @@
> >  }
> >  
> >  function do_note_exception(ex, text) {
> > +  let filename = Components.stack.caller.filename;
> > +  _testLogger.info(text + "Swallowed exception " + _exception_message(ex),
> 
> It might be nice if the StructuredLogger API had a log.exception method for
> this that worked like the one in Python's logging module.
> 
> ::: testing/xpcshell/runxpcshelltests.py
> @@ +23,5 @@
> >  from multiprocessing import cpu_count
> >  from optparse import OptionParser
> >  from subprocess import Popen, PIPE, STDOUT
> >  from tempfile import mkdtemp, gettempdir
> > +from threading import Timer, Thread, Event, current_thread
> 
> While you're here, can you reformat the lines you're touching to use parens
> and one-thing-per-line?
> from threading import (
>     Timer,
> ...
> )
> 
> @@ +31,5 @@
> >      HAVE_PSUTIL = True
> >  except ImportError:
> >      HAVE_PSUTIL = False
> >  
> > +from automation import Automation
> 
> Guess I should fix that kill_and_get_stack thing.
> 
> @@ +244,5 @@
> >          """
> >          return mozcrash.check_for_crashes(dump_directory, symbols_path, test_name=test_name)
> >  
> >      def logCommand(self, name, completeCmd, testdir):
> > +        self.logger.info("%s | full command: %r" % (name, completeCmd))
> 
> Is changing log to logger just so you made sure you found all the callers?
> It adds a few characters to every line...

Pretty much. Now that they're all changed I can revert it.

> 
> @@ -548,5 @@
> >          global gotSIGINT
> >  
> >          name = self.test_object['path']
> >  
> > -        self.xunit_result = {'name': self.test_object['name'], 'classname': 'xpcshell'}
> 
> It might have been nice to remove the xunit output in a separate precededing
> patch to keep this patch better-focused. (Don't worry about it at this
> point.)
> 
> @@ +515,4 @@
> >          # Check for skipped tests
> >          if 'disabled' in self.test_object:
> > +            self.logger.test_start(name)
> > +            self.logger.test_end(name, 'SKIP', message=self.test_object['disabled'])
> 
> We could probably output a better message for tests with no disabled text
> (those that just have 'disabled=' in the manifest). Maybe a followup?
> 
> @@ +522,5 @@
> >              self.keep_going = True
> >              return
> >  
> >          # Check for known-fail tests
> > +        expect_pass = self.test_object['expected'] == 'pass'
> 
> It would be cool if we could harmonize manifestparser and mozlog.structured
> here somehow, so that we didn't have to do this little dance. Maybe allowing
> you to pass a test object from manifestparser into the mozlog.structured
> methods and have it do the right thing for cases like this?

bug 1066161

> 
> @@ +575,4 @@
> >                  stdout=self.pStdout, stderr=self.pStderr, env=self.env, cwd=test_dir, timeout=testTimeoutInterval)
> >  
> > +            if not proc or not hasattr(proc, "pid"):
> > +                self.proc_ident = self.test_object["path"]
> 
> In what situation would we hit this?

"proc" is just a file when running remotely so doesn't have a pid attribute. The "not proc" case is suspect, I need to look at this again.

> 
> @@ +601,4 @@
> >  
> > +            return_code = self.getReturnCode(proc)
> > +            passed = ((not self.has_failure_output) and
> > +                      (return_code == 0))
> 
> You could probably fit this all on one line now.
> 
> @@ +614,3 @@
> >                  if self.retry:
> > +                    self.logger.test_end(name, 'SKIP', expected=expected,
> > +                                         message="Test failed or timed out, will retry")
> 
> This doesn't feel like a totally correct mapping, in that we didn't skip the
> test, we did run it and it failed but we're going to run it again. Maybe we
> need to figure out a properly semantic log entry for this? I'm OK with
> punting that to a followup.

Mozlog should probably have an encoding for retries, but I think logging these as expected fails for now is closer to what we mean.

> 
> @@ +623,2 @@
> >  
> > +                self.failCount = 1
> 
> Was the original code wrong, or did you break this while hacking on other
> things?

I think the change is a no-op. It's unrelated, I'll revert it.

> 
> @@ +644,4 @@
> >  
> >              if self.checkForCrashes(self.tempDir, self.symbolsPath, test_name=name):
> >                  if self.retry:
> > +                    self.logger.test_end(name, 'SKIP', expected=expected)
> 
> Isn't this going to produce incorrect output in the retry case? You'll have
> double test_end output, right?

Right.

> 
> @@ +925,5 @@
> > +
> > +    def get_test_from_queue(self, running_test_names, tests_queue):
> > +        """
> > +        Find a test in the test queue that doesn't share a name with
> > +        a running test to maintain coherence in the logs.
> 
> This is kind of gross, honestly. Having our test scheduling based around
> test names seems really weird. Can we not use relative path names in the
> logs to make this not a problem? We obviously can't have two tests with the
> exact same pathname.

We have a set of tests running from the exact same paths in toolkit/mozapps/extensions (I don't know the specifics, but xpcshell-unpack.ini and xpcshell.ini include the same manifest, and something from last summer makes me think it's on purpose). This could be achieved with a little bit of re-writing to get unique test names, but we log the test name directly, and it was requested that these don't change so that the bug starring interface continues to work as expected. Maybe we can get away with it in this case.

> 
> @@ +1286,5 @@
> > +        self.logger.info("INFO | Result summary:")
> > +        self.logger.info("INFO | Passed: %d" % self.passCount)
> > +        self.logger.info("INFO | Failed: %d" % self.failCount)
> > +        self.logger.info("INFO | Todo: %d" % self.todoCount)
> > +        self.logger.info("INFO | Retried: %d" % len(self.try_again_list))
> 
> Ideally we'd produce this as a summary of all the structured log output
> instead of hand-maintaining .{pass,fail}Count etc. Fine with doing that in a
> followup.

I don't think we can standardize or dispatch with these right away (it looks like at some point all the mozharness summary regexs were written to comply with the state of logging in each test harness) but the patches in bug 1024055 and bug 1063535 refactor mozharness in ways that will make this mode of summary logging completely obsolete.
This is updated from the review, running through try now. I'll re-request once everything looks green. A few notes:

* I don't see an easy win for logging exceptions in StructuredLog.jsm because of the way the stack formatting stuff is tied up with head.js. I added a comment about logging a stack for the benefit of python formatters and made the way "extra" works a little less hacky.
* This takes the "rewrite test names" approach for our concurrently run test paths and implements a distinction between the path to the test file and the test name throughout. I think this is the best way forward.
* Did some refactoring to work around https://bugzilla.mozilla.org/show_bug.cgi?id=1066728#c3 and log everything correctly even if killAndGetStackNoScreenshot never returns. I'm assuming at this point the situation is hard enough not deal with that we can't resolve it right away. Would love to be wrong!
Attachment #8475251 - Attachment is obsolete: true
So we can let others pass in structured data as the second argument. Looks like these never had their intended result.
Attachment #8489761 - Flags: review?(ted)
:edmorley, perhaps you can advise on the test name rewriting issue? I'd like to rewrite test names a little bit for those running concurrently from the same file, so where right now we get:


TEST-INFO | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_hotfix.js | running test …
TEST-INFO | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_hotfix.js | running test …
TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_hotfix.js | test passed (time: 10019.392ms)
TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_hotfix.js | test passed (time: 10860.917ms)

(with lots of stuff intermingled). We would get something like:

TEST-INFO | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_hotfix.js | running test …
TEST-INFO | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_hotfix.js-1 | running test …
TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_hotfix.js | test passed (time: 10019.392ms)
TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_hotfix.js-1 | test passed (time: 10860.917ms)

Adding "-1" to the end of the path when they're run concurrently so we can keep track of them correctly in mozlog. From digging around in the tbpl source code it looks like this would break the bug suggester for starring, would putting something at the beginning of the path be better?
Flags: needinfo?(emorley)
To check I understand the context - we're running multiple xpcshell tests in parallel (for performance reasons), and are looking to tweak the output to make it easier to untangle one process' output from another, since they are currently interleaved?

I'm not overly keen on renaming the test name - the name is supposed to be identical each time it is run, and not varied just dependant on which process ID is handling it. As such, perhaps we're better off using a prefix at start of line? (eg like make).
Flags: needinfo?(emorley)
(In reply to Ed Morley [:edmorley] from comment #33)
> To check I understand the context - we're running multiple xpcshell tests in
> parallel (for performance reasons), and are looking to tweak the output to
> make it easier to untangle one process' output from another, since they are
> currently interleaved?

We're running tests in parallel, but the problem is that we have some tests that we run more than once (with different head files to produce different behavior) so if we wind up interleaving the test_start and test_end for those we confuse the log parser.
Oh ok - so the tests are actually being run in different configurations, rather than just in arbitrary process N. So this is more on par with the jittests being run against multiple js shell params - which use the third field in the pipe delimited string, eg:
https://tbpl.mozilla.org/php/getParsedLog.php?id=48210001&tree=Mozilla-Inbound#error2

The jittest output previously use to be of form:
T-E-F | testname | params: Message

Whereas they are now (not as keen on this, but nvm):
T-E-F | testname | Message (blah blah... params)
(In reply to Ed Morley [:edmorley] from comment #33)
> To check I understand the context - we're running multiple xpcshell tests in
> parallel (for performance reasons), and are looking to tweak the output to
> make it easier to untangle one process' output from another, since they are
> currently interleaved?
> 
> I'm not overly keen on renaming the test name - the name is supposed to be
> identical each time it is run, and not varied just dependant on which
> process ID is handling it. As such, perhaps we're better off using a prefix
> at start of line? (eg like make).

Moving to mozlog structured logging puts more about what's happening in a test run in the logging system so it can do more work for us in a way that's uniform across test harnesses. Here the formatter is figuring out how long a test took to run based on its test_start/test_end pair so the harness doesn't have to. For this to work, each test needs a unique identifier for the run, or at least, only one test with a certain identifier can be running at once. This is pretty much a requirement for moving to structured logging.

The approach is to use the full path to the test file as the id, because we don't usually expect to have two tests with the exact same pathname, or if we sometimes run a test multiple times, we wouldn't expect them to be running concurrently. But as usual our reasonable assumptions don't hold.

The workarounds I've thought of so far are:

Don't let tests with the same path name run at the same time. I did this is a prior version of the patch, but it's really unfortunate.

Invent identifiers that aren't just path names and log those directly. This is my current idea, but is also undesirable. It's only a handful of tests, so I guess I'd like to understand exactly what breaks when we rename these. A one time change to unique identifiers (we could make them deterministic rather than rewriting them dynamically) seems like it might be the right compromise.

Come up with a way in mozlog that would allow us to log a test identifier the formatter knows about, but an id string that isn't necessarily unique. This could require extensive modifications to mozlog.
It's important that the identifiers are unique and consistent across runs. A goal is to be able to track the behaviour of specific tests (e.g. are they intermittent, do they fail when the code breaks). If testharness + test id isn't unique and unchanging we can still human-format results but we can't do any of this more sophisticated analysis.
(In reply to James Graham [:jgraham] from comment #37)
> It's important that the identifiers are unique and consistent across runs. A
> goal is to be able to track the behaviour of specific tests (e.g. are they
> intermittent, do they fail when the code breaks). If testharness + test id
> isn't unique and unchanging we can still human-format results but we can't
> do any of this more sophisticated analysis.

We need at least the unique part even to use our human-formatters, without it we log things incorrectly or crash just trying to figure out how long a test ran.
Yeah that makes sense, it seems like prefixing the test name might be the best bet then? (that way iirc the test name extraction will still work, per comment 32).

I look forward to the day when we can throw away all this parsing and have treeherder intelligently search the bug cache for combinations of "test name", "test name + test step", "test name + test step + params", so that we can solve the false-positive/false-negative issues that the current delimited format / test name extraction algorithm tries to work around.
So the uniqueness here comes from the manifest name + the test name. We can't have the same test listed twice in a single manifest, to have duplicate tests you have to have them in separate manifests. We could combine the manifest name with the test name to get a unique id.
I guess we should rewrite the test id to prepend the original manifest name when there are dupes (but not otherwise, so we don't change more output than necessary). At the moment the test object just has the name of the included manifest, so it's still exactly the same, but it also informs me it's a dupe manifest, so maybe with a change to the manifestparser we can get something.
Optimising for the short term by having a special case in the naming scheme doesn't seem like a good idea. In the long term just having one approach that's used everywhere helps people understand the derivation of the ids and, more importantly, makes it much less likely that the same test will swap ids in the future due to a second configuration of the same test being added.
(In reply to James Graham [:jgraham] from comment #42)
> Optimising for the short term by having a special case in the naming scheme
> doesn't seem like a good idea. In the long term just having one approach
> that's used everywhere helps people understand the derivation of the ids
> and, more importantly, makes it much less likely that the same test will
> swap ids in the future due to a second configuration of the same test being
> added.

I agree it's not great but I don't really see another way that satisfies the requirements at hand. The approach so far has been not to change what's logged as an id at all to satisfy existing systems, but here that's clearly insufficient, so I'm proposing a one time change just to get them unique. It sounds like uniqueness can reliably be determined from a combination of manifest names and paths. Maybe every test id should have a manifest associated with it for uniformity? Sometimes special cases are special (we already have reftest specific test id facilities in mozlog).

I think of optimizing for the short term as reaching a worthy middle ground that is a prerequisite for further improvements. For instance, it looks like having a test file name alone somewhere in the log would be most helpful to the bug suggester, but even thinking about replacing that mechanism with one driven by structured logs doesn't seem to make sense until we have a quorum of test harnesses logging structured data. At least that's the idea. Clearly it's an uphill battle.
I came across this working on bug 1034278 as well. Uniqueness there appears to come from something different still: a test file together with a set of jit flags.
Comment on attachment 8489761 [details] [diff] [review]
Convert callers of do_print to pass a single argument

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

nit: most of these look like they want a trailing space in the first string.
Attachment #8489761 - Flags: review?(ted) → review+
Ok, this is a lot like the patch in comment 30, but fixes an issue there by seperating the timeout path from the usual one further. I could probably take this further to get things nicer about being explicit in the case of a retry and de-duplicating the logging of test end, but I think this preserves the existing behavior.

This assumes the patch in bug 1066728 will be the answer for getting unique identifiers out of manifests, but that should be resolved before this lands.

Here is on try:
https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=08018c344a48
Attachment #8493911 - Flags: review?(ted)
Attachment #8489759 - Attachment is obsolete: true
(In reply to Chris Manchester [:chmanchester] from comment #46)
> Created attachment 8493911 [details] [diff] [review]
> Convert xpcshell tests to use mozlog.structured format for logging
> 
> Ok, this is a lot like the patch in comment 30, but fixes an issue there by
> seperating the timeout path from the usual one further. I could probably
> take this further to get things nicer about being explicit in the case of a
> retry and de-duplicating the logging of test end, but I think this preserves
> the existing behavior.
> 
> This assumes the patch in bug 1066728 will be the answer for getting unique
> identifiers out of manifests, but that should be resolved before this lands.

I mean bug 1068923 

> 
> Here is on try:
> https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=08018c344a48
Comment on attachment 8493911 [details] [diff] [review]
Convert xpcshell tests to use mozlog.structured format for logging

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

::: testing/xpcshell/runxpcshelltests.py
@@ +162,5 @@
>          else:
>              self.exception = None
>              self.traceback = None
>          if self.retry:
> +            self.log.info("%s failed or timed out, will retry." %

nit: You've used double quotes in a few places in your patch. (I know this file is sort of a mess of both, feel free to mass-replace them as a followup with rs=me.)

@@ +263,5 @@
> +                                                 self.appPath,
> +                                                 self.debuggerInfo)
> +
> +    def postCheck(self, proc):
> +        """Checks for a still-running test process, kills it an fails the test if found.

typo: 'and'

@@ +265,5 @@
> +
> +    def postCheck(self, proc):
> +        """Checks for a still-running test process, kills it an fails the test if found.
> +        We can sometimes get here before the process has terminated, which would
> +        cause removeDir() to fail - so check for the process & kill it it needed.

plz use full words and not symbols in comments

@@ +962,5 @@
> +        """Calculate a unique identifier for a test based on the information
> +        from a manifest."""
> +        path = replaceBackSlashes(test_object['path']);
> +        if 'dupe-manifest' in test_object:
> +            return '%s %s' % (test_object['dupe-manifest'], path)

Does this actually do what you want? The dupe-manifest key has an empty value in all the in-tree instances:
http://dxr.mozilla.org/mozilla-central/search?tree=mozilla-central&q=dupe-manifest&redirect=true
Attachment #8493911 - Flags: review?(ted) → review+
(In reply to Ted Mielczarek [:ted.mielczarek] from comment #48)
> Comment on attachment 8493911 [details] [diff] [review]
> Convert xpcshell tests to use mozlog.structured format for logging
> 
> Review of attachment 8493911 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: testing/xpcshell/runxpcshelltests.py
> @@ +162,5 @@
> >          else:
> >              self.exception = None
> >              self.traceback = None
> >          if self.retry:
> > +            self.log.info("%s failed or timed out, will retry." %
> 
> nit: You've used double quotes in a few places in your patch. (I know this
> file is sort of a mess of both, feel free to mass-replace them as a followup
> with rs=me.)
> 
> @@ +263,5 @@
> > +                                                 self.appPath,
> > +                                                 self.debuggerInfo)
> > +
> > +    def postCheck(self, proc):
> > +        """Checks for a still-running test process, kills it an fails the test if found.
> 
> typo: 'and'
> 
> @@ +265,5 @@
> > +
> > +    def postCheck(self, proc):
> > +        """Checks for a still-running test process, kills it an fails the test if found.
> > +        We can sometimes get here before the process has terminated, which would
> > +        cause removeDir() to fail - so check for the process & kill it it needed.
> 
> plz use full words and not symbols in comments
> 
> @@ +962,5 @@
> > +        """Calculate a unique identifier for a test based on the information
> > +        from a manifest."""
> > +        path = replaceBackSlashes(test_object['path']);
> > +        if 'dupe-manifest' in test_object:
> > +            return '%s %s' % (test_object['dupe-manifest'], path)
> 
> Does this actually do what you want? The dupe-manifest key has an empty
> value in all the in-tree instances:
> http://dxr.mozilla.org/mozilla-central/search?tree=mozilla-central&q=dupe-
> manifest&redirect=true

It does something like what I want with my patch for bug 1068923, but I really need to push that through or ask for more help. I'm finding the dupe manifest situation pretty frustrating and don't really see a clean solution.
Squashed patch with various review comment incorporated.
Attachment #8475263 - Attachment is obsolete: true
Comment on attachment 8509750 [details] [diff] [review]
Convert xpcshell tests to use mozlog.structured format for logging.

r=ted
Attachment #8509750 - Flags: review+
Attachment #8493911 - Attachment is obsolete: true
Attachment #8489761 - Attachment is obsolete: true
Attachment #8475261 - Attachment is obsolete: true
Hi Chris,

seems this patch didn't apply cleanly:

renamed 1033126 -> xpc_selftests.patch
applying xpc_selftests.patch
patching file testing/xpcshell/runxpcshelltests.py
Hunk #6 FAILED at 625
1 out of 16 hunks FAILED -- saving rejects to file testing/xpcshell/runxpcshelltests.py.rej
patch failed, unable to continue (try -v)
patch failed, rejects left in working dir
errors during apply, please fix and refresh xpc_selftests.patch

could you take a look at this and maybe rebase ?
Flags: needinfo?(cmanchester)
Keywords: checkin-needed
I weirdly don't see the same bitrot locally. Given the nature of the change, may be better not to land on a Friday, so I'll push or re-request checkin-needed Monday.
Flags: needinfo?(cmanchester)
https://hg.mozilla.org/mozilla-central/rev/b2dc4f1dc9b3
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla36
This broke |make xpcshell-tests|, which Thunderbird, Instantbird etc have to use as |mach xpcshell-tests| is restricted to Firefox, Android or B2G builds.

The attached patch simply removes the xunit command line flags to get |make xpcshell-tests| to run again. However, I don't know if anything in c-c-land depends on those.
Flags: needinfo?(Pidgeot18)
Attachment #8512579 - Flags: feedback?(cmanchester)
(In reply to aleth [:aleth] from comment #57)
> The attached patch simply removes the xunit command line flags to get |make
> xpcshell-tests| to run again. However, I don't know if anything in c-c-land
> depends on those.

In particular, does this break TBPL/treeherder's test result parsing for c-c?
This looks good and shouldn't be a problem for TBPL/treeherder consumers. The patch landed in this bug removes support for the xunit output generated in runxpcshelltests.py, not removing the command line options in testsuite-targets.mk was an oversight.

Would you mind filing a follow up for getting the fix reviewed/landed? Let me know and I'll do so today if you prefer. Thanks.
Flags: needinfo?(aleth)
Depends on: 1090302
Filed bug 1090302.
Flags: needinfo?(aleth)
Attachment #8512579 - Flags: feedback?(cmanchester)
Depends on: 1091077
Depends on: 1090784
Depends on: 1091974
(In reply to aleth [:aleth] from comment #57)
> The attached patch simply removes the xunit command line flags to get |make
> xpcshell-tests| to run again. However, I don't know if anything in c-c-land
> depends on those.

Local developers depend on make xpcshell-tests. The buildbot tests don't.
Flags: needinfo?(Pidgeot18)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: