1749266 - Intermittent pup [taskcluster:error] Task timeout after 1800 seconds. Force killing container

Status: RESOLVED FIXED

(Remote Protocol :: CDP, defect, P5)

Description

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

For bug 1580652 we currently see a lot of task timeouts and nearly all are coming from our Puppeteer job. It looks like this is a regression from bug 1732958.

Checking some of them we seem to stall in the following test:

Target Browser.waitForTarget should wait for a target
Target should create a worker from a shared worker
Target should report when a target url changes
waittask specs Page.waitFor should allow you to select an element with parenthesis-starting xpath
waittask specs Page.waitFor should wait for selector
waittask specs Frame.waitForSelector should respond to node attribute mutation
waittask specs Frame.waitForXPath should allow you to select an element with single slash
waittask specs Frame.waitForXPath should throw when frame is detached

Julian, could you please have a look?

Comment 1

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

I requested from the sheriffs the failures to be re-classified for this bug.

Comment 2

[Julian Descottes [:jdescottes]]

As discussed on elements, failing runs seem to waste around 10 minutes on a "clone" step:

[vcs 2022-01-08T11:39:54.869Z] fetching hgmointernal config from http://taskcluster/secrets/v1/secret/project/taskcluster/gecko/hgmointernal
[vcs 2022-01-08T11:39:55.013Z] hgmointernal rate miss; using public hg.mozilla.org service
[vcs 2022-01-08T11:39:55.013Z] fetching hg.mozilla.org fingerprint from http://taskcluster/secrets/v1/secret/project/taskcluster/gecko/hgfingerprint
[vcs 2022-01-08T11:39:55.091Z] executing ['hg', 'robustcheckout', '--sharebase', '/builds/worker/checkouts/hg-store', '--purge', '--config', 'hostsecurity.hg.mozilla.org:fingerprints=sha256:4D:EB:21:6E:35:2F:99:C6:8F:C3:47:9B:57:B8:6C:17:15:8F:86:09:D4:6C:17:1D:87:B0:DE:F9:0E:51:70:FC,sha256:FF:E7:8D:93:E9:56:3C:C0:19:FC:00:4C:18:B9:86:E5:08:E5:10:F5:E2:EA:48:E8:22:D3:A3:3A:CA:99:C3:4C', '--upstream', 'https://hg.mozilla.org/mozilla-unified', '--revision', '4427e203c432ae8a2db310112bbc86a598ca1203', 'https://hg.mozilla.org/mozilla-central', '/builds/worker/checkouts/gecko']
[vcs 2022-01-08T11:39:55.249Z] (using Mercurial 5.8.1)
[vcs 2022-01-08T11:39:55.249Z] ensuring https://hg.mozilla.org/mozilla-central@4427e203c432ae8a2db310112bbc86a598ca1203 is available at /builds/worker/checkouts/gecko
[vcs 2022-01-08T11:39:56.046Z] (cloning from upstream repo https://hg.mozilla.org/mozilla-unified)
[vcs 2022-01-08T11:39:56.216Z] (sharing from new pooled repository 8ba995b74e18334ab3707f27e9eb8f4e37ba3d29)
[vcs 2022-01-08T11:39:57.010Z] applying clone bundle from https://s3-external-1.amazonaws.com/moz-hg-bundles-us-east-1/mozilla-unified/4427e203c432ae8a2db310112bbc86a598ca1203.stream-v2.hg

https://firefoxci.taskcluster-artifacts.net/Jft1NJWuTm2TmGnWknp8dQ/0/public/logs/live_backing.log

A successful run will not have this 10mn clone: https://firefoxci.taskcluster-artifacts.net/GCjlo76NQ9G09xrDrQyK0w/0/public/logs/live_backing.log

Since a successful run already takes close to 30mn, the 10mn delay could be enough to make the test exceed the 1800s (=30mn) timeout. Since the last sync added new tests, I imagine we run into this issue more consistently anytime this clone happens.

My suggestion is to increase the timeout and see if it solves the issue. Alternatively we could skip failing/timeout tests, which would reduce the runtime to 10mn ish.

Comment 3

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

Slow cloning is known via bug 1487587. So yes, lets increase the timeout for the puppeteer job to circumvent this problem for now. Thanks!

Comment 4

[Julian Descottes [:jdescottes]]

Slow cloning is about clone taking 15-30mn instead of 10mn, however we have the issue even if the clone is fast.
The tests are only successful when we are able to start without cloning, by using a cached version of the repo.

That's what I assume the following log line is about:

(existing repository shared store: /builds/worker/checkouts/hg-store/8ba995b74e18334ab3707f27e9eb8f4e37ba3d29/.hg)

Comment 5

[Julian Descottes [:jdescottes]]

Attachment: Bug 1749266 - [remote] Increase timeout for puppeteer tasks to 3600 seconds

The test itself takes around 25 minutes. If the task hits the clone step, it will take an additional 10minutes.
Note that there is also a slow clone issue where clone can take between 15 and 30 mn.

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f106f16199d0
[remote] Increase timeout for puppeteer tasks to 3600 seconds r=jmaher,whimboo

Comment 7

[Alexandru Michis [:malexandru]]

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

Comment 8

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

https://hg.mozilla.org/releases/mozilla-beta/rev/8490c61e343b

Comment 9

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

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

Comment 10

[Intermittent Failures Robot]

4 failures in 3060 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 2
• mozilla-esr91: 2

Platform and build breakdown:

• linux1804-64: 4
  • opt: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1749266&startday=2022-01-10&endday=2022-01-16&tree=all