1740225 - Windows debug Wdspec headless 1 tasks have too large logs above the threshold

Status: RESOLVED FIXED

(Testing :: geckodriver, defect)

Description

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

Many of the following tasks on autoland and mozilla-central

• test-windows10-64-2004-qr/debug-web-platform-tests-wdspec-headless-fis-e10s-1
• test-windows10-64-2004-qr/debug-web-platform-tests-wdspec-headless-e10s-1
  have logs too big to be parsed (threshold is 5MB in gzipped state if I remember correct).

The first affected is this one. There is a big JSON blob at task 2021-11-08T15:24:50.896Z in the log which is not very compressible.

Is this a change from bug 1739536?

Comment 1

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

(In reply to Sebastian Hengst [:aryx] (needinfo on intermittent or backout) from comment #0)

The first affected is this one. There is a big JSON blob at task 2021-11-08T15:24:50.896Z in the log which is not very compressible.

Is this a change from bug 1739536?

No it's not because that landed yesterday and should have no affect here because it's Android only.

But as you referred to the given revision on Treeherder the problematic regression here is the landing of bug 1713920 which changes some color handling. Since then I can see the following output in the log files:

[task 2021-11-08T15:28:16.787Z] 15:28:16 INFO - PID 6800 | [Parent 7784, Main Thread] WARNING: Unknown color for nsLookAndFeel: file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp:327

And that line is listed a lot!! Emilio can you please have a look?

Comment 2

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

Interesting that this affects windows jobs because the patch / bug is titled for GTK. As such I'm going to move this bug to Core : Widget for now.

Comment 3

[Emilio Cobos Álvarez (:emilio)]

Attachment: Bug 1740225 - Don't warn when nsLookAndFeel doesn't know about a color. r=mstange

This is a expected situation specially after RemoteLookAndFeel was
enabled (which queries the whole int range).

No point in spamming the console.

Comment 4

[Emilio Cobos Álvarez (:emilio)]

If you think that warning will make a dent happy to remove it. It's an expected condition nowadays so we shouldn't warn to begin with.

Comment 5

[Emilio Cobos Álvarez (:emilio)]

But pretty sure this is not a regression from bug 1713920.

Comment 6

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

Yes, sorry, I was actually wrong here. The warning also shows up in builds before that patch landed. So it has to be something else. I might have to deeply compare the logs and why they are larger now.

Comment 7

[Phabricator Automation]

Comment on attachment 9249959 [details]
Bug 1740225 - Don't warn when nsLookAndFeel doesn't know about a color. r=mstange

Revision D130739 was moved to bug 1740245. Setting attachment 9249959 [details] to obsolete.

Comment 8

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

There are even problems for builds from late October like:

https://treeherder.mozilla.org/jobs?repo=mozilla-central&searchStr=wdh%2Cdebug&revision=28da4138ddff87ff0684b274db911cd4b602ac92&selectedTaskRun=Q_5V7gSdTXair3LP4H-o2Q.0

I'm not getting anything shown on the failure summary tab when having any WdH job selected. Is that the same issue or was there a different failure with Treeherder at that time?

Comment 9

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

Successful task && nothing in "Failure summary" tab == parsing successful && no failure lines
The affected jobs should read "Log parsing was skipped since the log exceeds the size limit." in the "Failure Summary" tab.

Comment 10

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

Ah ok. So I checked some logs and as it looks like we are always running at the limit for quite a while. As such one thing we might want to do now is to remove the logging of the async shutdown messages means that we should stop setting toolkit.asyncshutdown.log=true.

With Fission and WebRender done the shutdown behavior is much better now and removing that can save us quite a number of lines.

Comment 11

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

I pushed a try build with the removal of the pref:
https://treeherder.mozilla.org/jobs?repo=try&revision=26e1fdbbce1710ddac91a40a2f0dfffeaab01062

Comment 12

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

Reduction is about 400kB in gzip format and around 4-5 MB unpacked:

curl -I https://firefoxci.taskcluster-artifacts.net/JUHPDxVOTaWE7cvT94BBDg/0/public/logs/live_backing.log
HTTP/2 200
content-type: text/plain; charset=utf-8
content-length: 4643372
date: Thu, 11 Nov 2021 12:52:23 GMT
last-modified: Thu, 11 Nov 2021 12:46:41 GMT
etag: "b239025d64f3d3dfa0fb5b94f8b58f4e"
content-encoding: gzip

It's still not a huge reduction but maybe that's enough for now?

I've also seen that the patch for bug 1740245 has been landed and that actually helped a lot:

➜ curl -I https://firefoxci.taskcluster-artifacts.net/FRFMs959QuicW0N6O2zscA/0/public/logs/live_backing.log
HTTP/2 200
content-type: text/plain; charset=utf-8
content-length: 4239984
date: Thu, 11 Nov 2021 13:00:50 GMT
last-modified: Thu, 11 Nov 2021 06:40:15 GMT
etag: "453d511070aa56d82c39396f54e49577"
content-encoding: gzip

It's around 700kB and maybe we can leave it with that for now and do not remove the async shutdown logging as in my try build.

Aryx, what do you think?

Comment 13

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

Sorry my failure. I accidentally picked a shippable and not debug build. For a debug build it's not a big difference still:

content-length: 5094227

So we indeed should take the approach and disable async shutdown logs.

Comment 14

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

Attachment: Bug 1740225 - [wdspec] Don't print async shutdown logs for CI jobs.

Comment 15

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

Further tweaks might be needed. So we will keep this bug open for now.

Comment 16

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

Last occurrence of the exceeded log size is from November 11th:
https://treeherder.mozilla.org/jobs?repo=mozilla-central&selectedTaskRun=LVaH-HJbQ1GkXRzpzocv_A.0&searchStr=wdh1%2Cdebug&revision=300fc6bd088e8568d61395252c1b0bcb6fa9c4b5

Since the following merge to mozilla-central it's no longer happening:
https://treeherder.mozilla.org/jobs?repo=mozilla-central&selectedTaskRun=LVaH-HJbQ1GkXRzpzocv_A.0&searchStr=wdh1%2Cdebug&revision=3d82df1ca684e1d14bd77677e9532aba01c752a9

Nevertheless I'm going to land the proposed patch given that it isn't very useful anymore.

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/89df8f25b8df
[wdspec] Don't print async shutdown logs for CI jobs. r=webdriver-reviewers,jdescottes

Comment 18

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/89df8f25b8df

Comment 19

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

Aryx, please let me know if that works now. We seem to be down to a gzip size of about 4.5 MB. I hope that's enough. We can keep the bug open if you want and re-check next week. If it's not getting better we might want to also split up into 3 chunks.

Comment 20

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

Last log for windows wdspec which was above the threshold is from Monday.

Comment 21

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

And still no more failures since you have replied. So I'm going ahead and mark this bug as fixed.