This came up when adapting a harness that uses the same name for multiple tests running concurrently.

This feels like a patch of last resort. If we can fix the testsuite(s) without this that would be much better in terms of the reusability of log data to e.g. track which tests are failing over time. Also, logging a warning may turn tbpl orange, so I'm not sure that the fix as given will actually have the intended effect.

Comment on attachment 8453088 [details] [diff] [review] Warn in the structured logger for ending a test not in progress. Review of attachment 8453088 [details] [diff] [review]: ----------------------------------------------------------------- I found another way to go about this for the particular problem I encountered, but I still think it would be nice to keep track in the logger and provide a useful error (but fail) for those mis-using the api.

(In reply to Chris Manchester [:chmanchester] from comment #3) > I found another way to go about this for the particular problem I > encountered, but I still think it would be nice to keep track in the logger > and provide a useful error (but fail) for those mis-using the api. +1, if you're saying we should error out if test_end is called before test_start. If that's the case let's update the title here.

Comment on attachment 8453088 [details] [diff] [review] Warn in the structured logger for ending a test not in progress. Review of attachment 8453088 [details] [diff] [review]: ----------------------------------------------------------------- ::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py @@ +156,3 @@ > self._log_data("test_start", {"test": test}) > > def test_status(self, test, subtest, status, expected="PASS", message=None, Should also warm for a test_status for a test that isn't in progress. @@ +199,5 @@ > :param stack: a stack trace encountered during test execution. > :param extra: suite-specific data associated with the test result. > """ > + if test not in self._running_tests: > + self.warning(("Test start for %s was never logged, or test end was logged " I think a shorter message here would be better

I found that certain xpcshell tests are invoking themselves, which makes failing here hard to stomach for that particular harness. I see this patch as something aimed to help the logs be more informative as we're transitioning harnesses to structured logging, not as a complete solution.

Comment on attachment 8456301 [details] [diff] [review] Warn in the structured logger for ending a test not in progress. Review of attachment 8456301 [details] [diff] [review]: ----------------------------------------------------------------- So the problem is that the structured logging protocol rather assumes that you can work out which test a particular test_status or test_end message applies to just by looking at the id. If tests are starting themselves recursively, it's highly likely to break consumers that do things like put all the subtest results for a particular test into a dictionary; seeing test_start test_status test_status test_start test_status test_end test_end all with the same test id is likely to lead to the first two test_status messages, and the second test_end, message being lost.

(In reply to James Graham [:jgraham] from comment #7) > Comment on attachment 8456301 [details] [diff] [review] > Warn in the structured logger for ending a test not in progress. > > Review of attachment 8456301 [details] [diff] [review]: > ----------------------------------------------------------------- > > So the problem is that the structured logging protocol rather assumes that > you can work out which test a particular test_status or test_end message > applies to just by looking at the id. If tests are starting themselves > recursively, it's highly likely to break consumers that do things like put > all the subtest results for a particular test into a dictionary; seeing > test_start test_status test_status test_start test_status test_end test_end > all with the same test id is likely to lead to the first two test_status > messages, and the second test_end, message being lost. Ok, sounds like we need an actual solution for xpcshell then. I think what I was observing might just be two copies of the same test running concurrently, which could be avoided by specifying these tests to run sequentially. For the purposes of this bug, would promoting these messsages to the error level be acceptable?

Yes, I think making such things explicit errors is a good idea.

Ok, this is the same idea but logging these cases as errors. Maybe we should also throw an exception, but this is a start.

Comment on attachment 8457627 [details] [diff] [review] Warn in the structured logger for ending a test not in progress. Review of attachment 8457627 [details] [diff] [review]: ----------------------------------------------------------------- This basically seems OK, but I think we want to be sure we have the right semantics before I commit to the patch. ::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py @@ +152,5 @@ > > :param test: Identifier of the test that will run. > """ > + if test in self._running_tests: > + self.error("Test %s logged test_start while in progress." % test) Should we return here? Otherwise we risk breaking consumers. Similarly for the other times we log errors. @@ +171,5 @@ > :param stack: a stack trace encountered during test execution. > :param extra: suite-specific data associated with the test result. > """ > if status.upper() not in ["PASS", "FAIL", "TIMEOUT", "NOTRUN", "ASSERT"]: > raise ValueError("Unrecognised status %s" % status) I note that this is similar error handling using a different mechanism.

(In reply to James Graham [:jgraham] from comment #11) > Comment on attachment 8457627 [details] [diff] [review] > Warn in the structured logger for ending a test not in progress. > > Review of attachment 8457627 [details] [diff] [review]: > ----------------------------------------------------------------- > > This basically seems OK, but I think we want to be sure we have the right > semantics before I commit to the patch. > > ::: testing/mozbase/mozlog/mozlog/structured/structuredlog.py > @@ +152,5 @@ > > > > :param test: Identifier of the test that will run. > > """ > > + if test in self._running_tests: > > + self.error("Test %s logged test_start while in progress." % test) > > Should we return here? Otherwise we risk breaking consumers. > > Similarly for the other times we log errors. > > @@ +171,5 @@ > > :param stack: a stack trace encountered during test execution. > > :param extra: suite-specific data associated with the test result. > > """ > > if status.upper() not in ["PASS", "FAIL", "TIMEOUT", "NOTRUN", "ASSERT"]: > > raise ValueError("Unrecognised status %s" % status) > > I note that this is similar error handling using a different mechanism. We should either raise or log the error. Because logging such things in order, without overlap, and exactly once is a new requirement for some harnesses and not completely trivial (we've encountered issues of this flavor when working with marionette, xpcshell, and mochitests), the question on my mind is whether it will be easier to root out these problems when working on these conversions if they are a run-halting event, or an error to search for after the run completes. Because continuing the run may add helpful context, I would tend to favor the latter, as in this patch.

I can agree that continuing the run is helpful. But I don't think we should log the unexpected test_foo message itself; instead we should log an error containing the data that would have been in the test_foo message and return, so that we end up with a message like "Got a test_start event for a test that has already started (event was {"action": "test_start", "test": "broken_test", [...]})" This will be enough to signal a fatal problem to the developer / tbpl but also provides stronger invariants for consumers so that e.g. the formatter itself doesn't blow up. I am prepared to be persuaded that I am wrong here, though.

I agree with the approach. It's even more helpful for debugging, and formatters being able to rely on these invariants will probably be able to do more interesting things more easily.

I agree with the approach. Potentially more helpful for debugging, and formatters that can rely on these invariants will probably be able to do more intersting things more easily.

Sorry for the review/attachment spam, hit a bzexport error that made me think the attachment didn't get uploaded.

Comment on attachment 8459875 [details] [diff] [review] Warn in the structured logger for ending a test not in progress. Review of attachment 8459875 [details] [diff] [review]: ----------------------------------------------------------------- This looks like the right solution, but I don't think you can have the tests that depend on the serialisation of a dictionary, since the keys will appear in random order. Either remove these tests or make them robust against changes in order. ::: testing/mozbase/mozlog/tests/test_structured.py @@ +127,5 @@ > + > + def test_status_not_started(self): > + self.logger.test_status("test_UNKNOWN", "subtest", "PASS") > + self.assert_log_equals({"action": "log", > + "message": 'test_status for test_UNKNOWN logged while not in progress. Logged with data: {"test": "test_UNKNOWN", "subtest": "subtest", "status": "PASS"}', Unstable order. @@ +164,5 @@ > + def test_end_no_start(self): > + self.logger.test_end("test1", "PASS", expected="PASS") > + self.assert_log_equals({"action": "log", > + "level": "ERROR", > + "message": 'test_end for test1 logged while not in progress. Logged with data: {"test": "test1", "status": "PASS"}' I don't think this works; the order isn't guaranteed to be stable. @@ +176,5 @@ > + "test": "test2"}) > + self.logger.test_end("test2", "PASS", expected="PASS") > + self.assert_log_equals({"action": "log", > + "level": "ERROR", > + "message": 'test_end for test2 logged while not in progress. Logged with data: {"test": "test2", "status": "PASS"}' Also here.