2021067 - Buffer logs during wdspec tests and flush only on test failure

Status: NEW

(Remote Protocol :: Agent, task, P2)

Description

[Julian Descottes [:jdescottes]]

See Bug 2020914.

The logs created by wdspec tests are too big, we should buffer and only flush on failure.

Comment 1

[Julian Descottes [:jdescottes]]

Attachment: Bug 2021067 - [wdspec] WIP: Update wptrunner to buffer logs and flush on failure

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+1]]

One thing we should make sure is that all logging is buffered so that when we write it out for a failing test that the logs from Remote Agent and Firefox are still intersected and at the correct positions. Otherwise it would make it quite hard to match up our code.

Comment 3

[Julian Descottes [:jdescottes]]

(In reply to Henrik Skupin [:whimboo][⌚️UTC+1] from comment #2)

One thing we should make sure is that all logging is buffered so that when we write it out for a failing test that the logs from Remote Agent and Firefox are still intersected and at the correct positions. Otherwise it would make it quite hard to match up our code.

Off the top of my head I don't know if we can achieve this?
My goal was rather to try to log only the relevant test logs. So if a subtest failed, flush only that, and as close as possible to the failure itself.
Sounds like we would need fully synced logs with two separate buffers, I'm not sure how we can do this. Maybe you have a suggestion on how to tackle that?

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+1]]

As discussed in the meeting on Monday it would be good to have a try build with some failures forced in some of the tests. If possible lets as well set some MOZ_LOG like BCWebProgress:5 so that we can see how the output of the buffered logs look like. Based on that outcome lets see what the next steps could be.

Comment 5

[Julian Descottes [:jdescottes]]

(just unassigning as this is for next milestone)

Comment 6

[Julian Descottes [:jdescottes]]

I had two variants of this patch.

The one uploaded on phab right now attempts to only buffer the logs for a subtest and flush only that - but it didn't seem to work as expected.
The previous version was buffering and flushing per test file, and that seems to work, but of course it makes it extra hard to find the relevant logs for the specific subtest which failed.

One example is https://treeherder.mozilla.org/logviewer?job_id=551858352&repo=try&task=TqU8lejFTXyQ1U31e8v9Ig.0&lineNumber=9990

(will attach the log here as well as a backup)

Comment 7

[Julian Descottes [:jdescottes]]

Attachment: live_backing.log

Comment 8

[Henrik Skupin [:whimboo][⌚️UTC+1]]

(In reply to Julian Descottes [:jdescottes] from comment #6)

The one uploaded on phab right now attempts to only buffer the logs for a subtest and flush only that - but it didn't seem to work as expected.
The previous version was buffering and flushing per test file, and that seems to work, but of course it makes it extra hard to find the relevant logs for the specific subtest which failed.

One example is https://treeherder.mozilla.org/logviewer?job_id=551858352&repo=try&task=TqU8lejFTXyQ1U31e8v9Ig.0&lineNumber=9990

Is that example for the current version of the patch on phab or the previous one?

Comment 9

[Julian Descottes [:jdescottes]]

previous one.