1607255 - Mochitests' buffered messages end up with misleading timestamps in the live_backing.log that our bug workflow points everyone at

Status: NEW

(Testing :: Mochitest, enhancement, P3)

Description

[Andrew Sutherland [:asuth] (he/him)]

The mochitest runner buffers output from tests until the test fails, and then it dumps them. The structured log output has the correct timestamps of when the test-checks occurred, but the live_backing.log which is what everyone gets pointed at has the timestamps of when the buffered messages are logged.

An attempt is made to clarify the timeline discontinuity by including a message like "Buffered messages logged at 10:50:16" at the start of the dumped log output, but it's ambiguous about whether that corresponds to the start of the messages or the end. Also, if one is only looking at the error line, it's likely one will only see the "Buffered messages finished" line at the end, which is a good hint to people whose brains are fully caffeinated, but in many ways it's a subtle hint compared to "ALL THE TIMESTAMPS ABOVE ARE LIES".

I've filed bug 1607253 on having a structured log viewer, which seems like the best solution. I expect that the problem for this bug is the pipeline of where the logs are flattened to text and who is issuing the timestamps and logging them and it's not clear that it would be easy to comprehensively fix. But it might be possible to use some combination of either explicitly including the buffered timestamps in the flattened-to-text representation, time deltas, or just scarier bumper messages at both ends and disambiguate the start/end of the buffered messages if not providing per-message tiemstamps/deltas.

Comment 1

[Geoff Brown [:gbrown]]

I think most test log timestamps come from run-task. The mochitest "Buffered messages" times are known only to the mochitest harness -- difficult to co-ordinate with run-task. However, I wonder if run-task could be updated to do something like suspend its timestamping when it sees the "Buffered messages" line; or, perhaps more generically, run-task could not print a timestamp if the line already begins with a timestamp, and mochitest buffered messages could be timestamped in the expected format.

Comment 3

[Andrew Sutherland [:asuth] (he/him)]

As a note since I was recently wondering about the structured logs and when they were removed, the structured log removal that was the potential workaround here were announced to be scheduled to be removed on March 31, 2023 on dev-platform and it seems like they were indeed removed.