1911382 - puppeteer webdriver Pup(wd) task's logs are too big to be parsed by Treeherder (>5MB gzipped)

Status: RESOLVED FIXED

(Remote Protocol :: WebDriver BiDi, defect, P2)

Description

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

Since bug 1909952 landed, the logs of Pup(wd) tasks are too big to be parsed by Treeherder (above the 5MB gzipped threshold). Example

Could the logging be reduced or the task be split into chunks?

Comment 1

[Julian Descottes [:jdescottes]]

Discussed in triage, we prefer to split the jobs in chunks and preserve the current log level.

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1909952

Comment 3

[Alastor Wu [:alwu]]

I've checked the log and didn't see any EME wpt running in Pup(wd). In addition, that task only runs test in wdspec type. According to this, EME wpt are not that type of test.

Comment 4

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

The raw log size decreased by 54kB, compressed it increased by 127kB. Does anything more dynamic get logged now?

Comment 5

[Julian Descottes [:jdescottes]]

It's hard to tell.

The log level is set to TRACE for this job, so we log all the commands, results, errors and events from WebDriver BiDi which occur during the tests. I think that especially with tests relying on network events, we might have some requests which intermittently show up (eg requests to favicons).

I looked a bit at the logs and there are two things which stand out:

• one test querySelector QueryAll $$eval should handle many elements (queryselector.spec.js) generates 7000+ lines of log. It's probably similar to another test we had to disable (https://phabricator.services.mozilla.com/D216415)
• MessageHandler logs are responsible for roughly 30% of the logs, and I'm not sure they bring a lot of value

The message handler logs fall into two main categories:

Received command script.callFunction for destination ROOT
and
Module root/script.sys.mjs found for ROOT

The module ones are especially useless I think at this point. I think they were useful in the beginning when we introduced the framework, but at this point they only indicate that the module system works as expected. They can still be useful to debug issues in development when introducing new modules, but maybe we can flag them behind another pref for now until we get chunks to work?

Comment 6

[Julian Descottes [:jdescottes]]

Attachment: Bug 1911382 - [remote] Reduce logs for MessageHandler module system

Removing those 2 logs by default reduces the log size of the pup wd job significantly (320K lines -> 200K lines)

Comment 7

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

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

Created attachment 9418200 [details]
Bug 1911382 - [remote] Reduce logs for MessageHandler module system

Removing those 2 logs by default reduces the log size of the pup wd job significantly (320K lines -> 200K lines)

Does that help without having to skip querySelector QueryAll $$eval should handle many elements (queryselector.spec.js)? Maybe we could even re-enable the other test that you was referring to earlier?

Comment 8

[Julian Descottes [:jdescottes]]

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

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

Created attachment 9418200 [details]
Bug 1911382 - [remote] Reduce logs for MessageHandler module system

Removing those 2 logs by default reduces the log size of the pup wd job significantly (320K lines -> 200K lines)

Does that help without having to skip querySelector QueryAll $$eval should handle many elements (queryselector.spec.js)? Maybe we could even re-enable the other test that you was referring to earlier?

Yes, I didn't have to skip this test. I'll try to re-enable the Aria one.
Edit: try push re-enabling the other test https://treeherder.mozilla.org/jobs?repo=try&revision=f2a7d1fa9d73f28f535eb153426f9effec920564

Comment 9

[Julian Descottes [:jdescottes]]

Re-enabling [ariaqueryhandler.spec] AriaQueryHandler queryAllArray $$eval should handle many elements generates 80k lines of logs , meaning we go to 280k lines. But it seems that those additional 80k lines are not handled well when using gzip, because the gzipped size goes well over 5 MB.

To summarize the various gzipped sizes:

• baseline: ~5MB (sometimes slightly more, slightly less)
• with the patch to just remove the logs: 4.2MB
• with remove logs + re-enable Aria test: 5.6MB

I would be in favor of landing my current patch, and then work on chunks. I think it's valuable to remove those logs by default anyway, because they don't bring value, and make the logs harder to read.

Comment 10

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

Sounds good Julian. Lets get this temporary fix in. Thanks.

Comment 11

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

Mind filing a new bug for the chunking?

Comment 12

[Julian Descottes [:jdescottes]]

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

Mind filing a new bug for the chunking?

Sure filed Bug 1912292

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/fbb6ff60d0ad
[remote] Reduce logs for MessageHandler module system r=webdriver-reviewers,whimboo

Comment 14

[Cristina Horotan [:chorotan]]

https://hg.mozilla.org/mozilla-central/rev/fbb6ff60d0ad

Comment 15

[BugBot [:suhaib / :marco/ :calixte]]

The patch landed in nightly and beta is affected.
:jdescottes, is this bug important enough to require an uplift?

• If yes, please nominate the patch for beta approval.
• If no, please set status-firefox130 to wontfix.

For more information, please visit BugBot documentation.

Comment 16

[Julian Descottes [:jdescottes]]

Considering this is only an intermittent log parsing issue, I think it can ride the trains.