1607253 - Support viewing structured logs (with accurate timestamps) in log viewer

Status: NEW

(Tree Management :: Treeherder, enhancement)

Description

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

The textual logs the log viewer displays have an issue where the test/logging framework buffers messages, such as Mochitest, and when the buffer is flushed, misleading timestamps are emitted. For example, in bug 1588148 in this log the lines all suggest in isolation that they happened at 10:55:27:

[task 2019-12-29T10:55:27.592Z] 10:55:27 INFO - TEST-PASS | dom/html/test/test_formSubmission.html | Correct value in send form using XHR and FormData

But that's when the buffered messages finished:

[task 2019-12-29T10:55:27.592Z] 10:55:27 INFO - Buffered messages finished

But the structured mochitest-plain_raw.log log has the right timestamps inside it:

{"status": "PASS", "thread": "None", "subtest": "Correct value in send form using XHR and FormData", "pid": null, "source": "mochitest", "test": "dom/html/test/test_formSubmission.html", "js_source": "TestRunner.js", "time": 1577616616403, "action": "test_status"}
{"source": "mochitest", "thread": "ProcessReader", "time": 1577616927584, "action": "log", "message": "Buffered messages finished", "level": "INFO", "pid": 10192}

The timestamps are respectively (buffered message) 2019-12-29T10:50:16.403Z and (buffered messages dumped notice) 2019-12-29T10:55:27.584Z.

While it's maybe possible to fix the buffering in the pipeline that produces the textual output[1], it seems like it would also be a win to be able to view structured logs directly. I found there was already bug 1160117 along these lines but it got resolved incomplete with no discussion and in the tracking bug hierarchy it links into I haven't seen any other plans.

1: I'd expect the fix might be something like emitting all the logs as structured logs and only flattening to plaintext at the last step? Which maybe is redundant given that there's already pure structured logs available, they're just not something that are easily viewed or that our bug fixing workflow directly directs people to?

Comment 1

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Cam: can you provide details on this request, especially because bug 1160117 had been created before?