Closed Bug 1075324 Opened 10 years ago Closed 10 years ago

"dumping last 7 message(s)" in mochitest logs is misleading

Categories

(Testing :: Mochitest, defect)

defect
Not set
normal
Points:
2

Tracking

(Not tracked)

RESOLVED FIXED
mozilla35
Iteration:
35.3

People

(Reporter: markh, Assigned: markh)

Details

(Whiteboard: [qa-])

Attachments

(1 file)

I was recently trying to diagnose an error from TBPL logs and got the message "dumping last 7 message(s)...", which I thought sucked - how could someone have decided only 7 lines of output was enough? :)

Obviously, this message *actually* meant - "dumping *all* messages which, in this case, is 7 lines".

I'd like to propose that this message only be printed when there are actually lines truncated.  I'm also proposing a slightly terser version of the message in that case - my idea is we output a single line:

<snipped XXX output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>

or nothing when no output is snipped.  Note that patch doesn't bother with "line(s)" - the chance of a test outputting *exactly* 101 lines *and* failing seems low and the fact it might then say "1 lines" is OK IMO.
Attachment #8497960 - Flags: review?(ahalberstadt)
Comment on attachment 8497960 [details] [diff] [review]
0004-Bug-XXXXXXX-mochitest-logs-only-report-output-was-tr.patch

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

I agree that the old message is confusing, but this isn't doing what you think it is.

::: testing/mochitest/runtests.py
@@ +184,5 @@
>          # test_status messages buffering
>          if is_error:
>              if self.buffered_messages:
> +                snipped = len(self.buffered_messages) - self.BUFFERING_THRESHOLD
> +                if snipped > 0:

There's a misunderstanding around how the buffering works. If buffering is enabled (i.e when --quiet is passed in), *all* test output is stored in a circular buffer and is only printed in the event of a failure. BUFFERING_THRESHOLD is the size of the circular buffer (yes this is also a misleading variable name, feel free to change it). We do this because some tests print tens of thousands of lines of output, if they fail, we only dump the last 100.

So while I agree with most of your points, all "len(self.buffered_messages) - self.BUFFERING_THRESHOLD > 0" means is that the test had less than a 100 lines of output. Basically if we get into this if statement, we know for sure output has been buffered.

@@ +187,5 @@
> +                snipped = len(self.buffered_messages) - self.BUFFERING_THRESHOLD
> +                if snipped > 0:
> +                  self.logger.info("<snipped {0} output lines - "
> +                                   "if you need more context, please use "
> +                                   "SimpleTest.requestCompleteLog() in your test>"

I think this message might also be confusing.. "<snipped 10 output lines" makes me think that there are 10 lines that aren't being displayed. I'd change this to "<displaying {0} snipped output lines"
Attachment #8497960 - Flags: review?(ahalberstadt) → review-
Thanks for the comment, but I'm still missing something:

(In reply to Andrew Halberstadt [:ahal] from comment #1)
> Comment on attachment 8497960 [details] [diff] [review]
> 0004-Bug-XXXXXXX-mochitest-logs-only-report-output-was-tr.patch
> 
> Review of attachment 8497960 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I agree that the old message is confusing, but this isn't doing what you
> think it is.
> 
> ::: testing/mochitest/runtests.py
> @@ +184,5 @@
> >          # test_status messages buffering
> >          if is_error:
> >              if self.buffered_messages:
> > +                snipped = len(self.buffered_messages) - self.BUFFERING_THRESHOLD
> > +                if snipped > 0:
> 
> There's a misunderstanding around how the buffering works. If buffering is
> enabled (i.e when --quiet is passed in), *all* test output is stored in a
> circular buffer and is only printed in the event of a failure.

Just to be clear, the output is buffered in a regular unbounded Python list rather than a "circular buffer", right?  The list is reset whenever dump_buffered() is called, but between such calls there's no attempt to limit the number of buffered lines.  (This might just be a terminology issues, but to me a "circular buffer" implies you can make as many .push() calls as you like, but len() will never return greater than the pre-set limit, which best I can tell isn't the case here)

Thus, len(self.buffered_messages) is the total number of lines buffered since dump_buffered() was last called.  If dump_buffered() is called with limit=False, *all* lines are dumped.  If limit=True and len(self.buffered_messages) > BUFFERING_THRESHOLD, then exactly len(self.buffered_messages)-self.BUFFERING_THRESHOLD lines will be omitted.

> BUFFERING_THRESHOLD is the size of the circular buffer (yes this is also a
> misleading variable name, feel free to change it). We do this because some
> tests print tens of thousands of lines of output, if they fail, we only dump
> the last 100.

Yep, understood.  What I'm trying to do here is avoid the implication lines were omitted when the test has produced less than 100 lines.

> So while I agree with most of your points, all "len(self.buffered_messages)
> - self.BUFFERING_THRESHOLD > 0" means is that the test had less than a 100
> lines of output. Basically if we get into this if statement, we know for
> sure output has been buffered.

I think it means that we had *more* than 100 lines of output, so dump_buffered(limit=True) is going to omit some lines.  Or to put it another way, the inverted condition "len(self.buffered_messages) - self.BUFFERING_THRESHOLD <= 0" means that dump_buffered(limit=True) and dump_buffered(limit=False) would produce the exact same output.

> @@ +187,5 @@
> > +                snipped = len(self.buffered_messages) - self.BUFFERING_THRESHOLD
> > +                if snipped > 0:
> > +                  self.logger.info("<snipped {0} output lines - "
> > +                                   "if you need more context, please use "
> > +                                   "SimpleTest.requestCompleteLog() in your test>"
> 
> I think this message might also be confusing.. "<snipped 10 output lines"
> makes me think that there are 10 lines that aren't being displayed.

I think that's exactly what the patch does - it prints the difference between how many lines were buffered and how many we actually display - ie, the number *not* displayed.  Given this doesn't seem to be a circular buffer but instead a regular unbounded list, I can't see when this would be inaccurate.

What am I missing?
Flags: needinfo?(ahalberstadt)
(In reply to Mark Hammond [:markh] from comment #2) 
> Just to be clear, the output is buffered in a regular unbounded Python list
> rather than a "circular buffer", right?  The list is reset whenever
> dump_buffered() is called, but between such calls there's no attempt to
> limit the number of buffered lines.  (This might just be a terminology
> issues, but to me a "circular buffer" implies you can make as many .push()
> calls as you like, but len() will never return greater than the pre-set
> limit, which best I can tell isn't the case here)

Yes that is correct. Sorry, I didn't look all that closely at the implementation. But it still acts like a circular buffer in that only the last N messages are dumped if limit=True (which is the case here).

> Yep, understood.  What I'm trying to do here is avoid the implication lines
> were omitted when the test has produced less than 100 lines.

Ok, I see what you're doing now. I misunderstood what you meant by "snipped" (I thought you meant buffered, but really you meant omitted even after buffering).

> What am I missing?

Nothing, mistake was on my end.. apologies!
Flags: needinfo?(ahalberstadt)
Attachment #8497960 - Flags: review- → review+
thanks!

https://hg.mozilla.org/integration/fx-team/rev/849c7d93fba1
Status: NEW → ASSIGNED
Points: --- → 2
Flags: firefox-backlog+
Whiteboard: [qa-]
Assignee: nobody → mhammond
Iteration: --- → 35.3
https://hg.mozilla.org/mozilla-central/rev/849c7d93fba1
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla35
You need to log in before you can comment on or make changes to this bug.