1219870 - [mozlog] bad suite state if 'suite_start' and/or 'suite_end' received via log_raw

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[Andrew Halberstadt [:ahal]]

Ran into this while working on bug 1034290. In StructuredLogger, we keep track of whether or not a suite_start/suite_end has been received and throw an error if they come in the wrong order:
https://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozlog/mozlog/structuredlog.py#232

But this check gets ignored if a log with a suite_start/suite_end action gets logged via the log_raw function. This can result in multiple suite_start/end messages being logged in the wrong order.

Comment 1

[Andrew Halberstadt [:ahal]]

Attachment: MozReview Request: Bug 1219870 - [mozlog] ensure correct suite state when logging suite_start/suite_end via StructuredLogger.log_raw, r=chmanchester

Bug 1219870 - [mozlog] ensure correct suite state when logging suite_start/suite_end via StructuredLogger.log_raw, r=chmanchester

Comment 2

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8680791 [details]
MozReview Request: Bug 1219870 - [mozlog] ensure correct suite state when logging suite_start/suite_end via StructuredLogger.log_raw, r=chmanchester

https://reviewboard.mozilla.org/r/23681/#review21229

It might be a little surprising that this invariant makes it to log_raw but the test_start/end one doesn't, what's the motivation for sending suite start/end through log_raw?

Comment 3

[Andrew Halberstadt [:ahal]]

The way it's currently set up is the python side just reads the line delimited json from reftest.js and forwards it wholesale to log_raw one line at a time.

But imo, that's beside the point.. This is a bug whether or not we currently happen to use log_raw for that purpose.

Comment 4

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8680791 [details]
MozReview Request: Bug 1219870 - [mozlog] ensure correct suite state when logging suite_start/suite_end via StructuredLogger.log_raw, r=chmanchester

https://reviewboard.mozilla.org/r/23681/#review21441

::: testing/mozbase/mozlog/mozlog/structuredlog.py:229
(Diff revision 1)
> +                self.error("Got second suite_start message before suite_end.")

You got rid of the part where we dump what was logged along with the error.

::: testing/mozbase/mozlog/mozlog/structuredlog.py:230
(Diff revision 1)
> +                return 1

We can use a boolean for this.

::: testing/mozbase/mozlog/mozlog/structuredlog.py:236
(Diff revision 1)
> +            self._state.suite_started = False
> +

Throw in a return value here. The value of a function call that doesn't execute a return statement happens to be falsy, but it might make this function a little unclear to rely on that because the function also has a side effect.

I don't really think this is a bug, but I don't think the patch does any harm.

Comment 5

[Andrew Halberstadt [:ahal]]

It's not a very important bug, no.. but it means mozlog won't error out if StructuredLog.jsm logs multiple suite_starts/ends. It certainly caused me a couple hours of my life trying to debug what was going on, as it caused a very non-obvious failure.

Comment 6

[Andrew Halberstadt [:ahal]]

Comment on attachment 8680791 [details]
MozReview Request: Bug 1219870 - [mozlog] ensure correct suite state when logging suite_start/suite_end via StructuredLogger.log_raw, r=chmanchester

Bug 1219870 - [mozlog] ensure correct suite state when logging suite_start/suite_end via StructuredLogger.log_raw, r=chmanchester

Comment 7

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/9ad72faa8cdd

Comment 8

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/9ad72faa8cdd

Comment 9

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-b2g44_v2_5/rev/9ad72faa8cdd