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

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: full output of ./mach mochitest-remote layout/style/test

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'

Comment 1

[James Graham [:jgraham]]

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.

Comment 2

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

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?

Comment 3

[James Graham [:jgraham]]

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.

Comment 4

[Ahmed Kachkach [:akachkach]]

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?)

Comment 5

[James Graham [:jgraham]]

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.

Comment 6

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1043015-running-mochitest-remote-without-ssltunn.patch

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.

Comment 7

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/69e731a9f604

Comment 8

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/69e731a9f604