Closed Bug 1043015 Opened 6 years ago Closed 6 years ago

running mochitest-remote without ssltunnel gives bizarre errors (structured logging regression, I think)

Categories

(Testing :: Mochitest, defect)

x86_64
Linux
defect
Not set

Tracking

(Not tracked)

RESOLVED FIXED
mozilla34

People

(Reporter: dbaron, Assigned: akachkach)

Details

(Keywords: regression)

Attachments

(2 files)

I just tried to run mochitest-remote without copying in assltunne to work around bug 1002545, and post-structured-logging this gives some pretty bizarre errors:

  File "/home/dbaron/builds/B2G-master-emulator/objdir-gecko-debugopt/_tests/testing/mochitest/runtests.py", line 833, in start
    log.error("INFO | runtests.py | expected to find ssltunnel at %s", ssltunnel)
TypeError: log() takes exactly 2 arguments (3 given)


and later:

  File "/home/dbaron/builds/B2G-master-emulator/../ssd/mozilla-central/mozilla/testing/mozbase/mozlog/mozlog/structured/formatters/tbplformatter.py", line 66, in suite_end
    time = int((data["time"] - start_time) / 1000)
TypeError: unsupported operand type(s) for -: 'int' and 'NoneType'
The first error appears to be a typo; s/, / % / should work.

The second error is that we're getting a suite_end message before suite_start. The logger should error for that case and refuse to emit the end message.
Well, I'm pretty sure it used to work, because I remember getting a useful error message the last time I hit the problem (although it may well have had an extra %s in it).  Perhaps log.error() used to accomodate multiple arguments and no longer does?  Fixing the typo seems reasonable, though, but have you checked that there aren't other similar log.error() or other log.*() calls?
Well I guess what actually happened was that the switch away from stdlib logging broke this because it interprets extra arguments as format parameters, but mozlog[.structured] doesn't.

I can't be sure that there aren't more examples in anywhere in mochitest (without putting in a "morning" amount of effort, rather than a "middle of the night" amount of effort), but I can't see any more in that file at least.
Indeed, switching from using the stdlib logging module to using StructuredLogger forces us to supply a single argument to logging functions (info, error, warning, etc.); I apparently forgot to refactor that one error message!

I'll try to check I didn't forget any other logging calls and will submit a patch.
(Not sure what we can do about the missing suite_start message though, does it only happen when running without ssltunnel?)
Assuming the missing suite_start is basically because we fail and then later emit a suite end message to signal we're done, I have a patch that will "fix" it by emitting an error rather than a suite_end message. I don't think mild cascading of errors is a problem, and certainly less of one than violating the protocol.
I went through the code and couldn't find another instance of this bug, so this patch just fixes the typo on the ssl tunnel error.

For the missing test_end, the StructuredLogger patch will make errors easier to understand.
Attachment #8461205 - Flags: review?(james)
Attachment #8461205 - Flags: review?(james) → review+
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/69e731a9f604
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
You need to log in before you can comment on or make changes to this bug.