1705639 - Intermittent periodic file update [taskcluster:error] Task timeout after 18000 seconds. Force killing container.

Status: RESOLVED FIXED

(Release Engineering :: Release Automation, defect)

Description

[Treeherder Bug Filer]

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=336624599&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YyTg0LH2SAiFx-fvTF4t-A/runs/0/artifacts/public/logs/live_backing.log

---

+ read -r bucket collection
+ hg_dump_url=https://hg.mozilla.org/releases/mozilla-beta/raw-file/default/services/settings/dumps/pinning-preview/pins.json
+ local_location_input=/home/worker/data/remote-settings.in/pinning-preview/pins.json
+ mkdir -p /home/worker/data/remote-settings.in/pinning-preview
+ wget -nv -qO /home/worker/data/remote-settings.in/pinning-preview/pins.json https://hg.mozilla.org/releases/mozilla-beta/raw-file/default/services/settings/dumps/pinning-preview/pins.json
+ '[' 8 -eq 8 ']'
+ rmdir /home/worker/data/remote-settings.in/pinning-preview --ignore-fail-on-non-empty
+ continue
+ IFS=/
+ read -r bucket collection
+ hg_dump_url=https://hg.mozilla.org/releases/mozilla-beta/raw-file/default/services/settings/dumps/pinning/pins.json
+ local_location_input=/home/worker/data/remote-settings.in/pinning/pins.json
+ mkdir -p /home/worker/data/remote-settings.in/pinning
+ wget -nv -qO /home/worker/data/remote-settings.in/pinning/pins.json https://hg.mozilla.org/releases/mozilla-beta/raw-file/default/services/settings/dumps/pinning/pins.json
+ '[' 0 -eq 8 ']'
+ remote_records_url=https://firefox.settings.services.mozilla.com/v1/buckets/pinning/collections/pins/records
+ local_location_output=/home/worker/data/remote-settings.out/pinning/pins.json
+ mkdir -p /home/worker/data/remote-settings.out/pinning
+ wget -nv -qO- https://firefox.settings.services.mozilla.com/v1/buckets/pinning/collections/pins/records
+ /usr/bin/jq .
+ '[' pinning = blocklists ']'
+ IFS=/
+ read -r bucket collection
+ echo 'INFO: diffing old/new remote settings dumps...'
INFO: diffing old/new remote settings dumps...
+ /usr/bin/diff -u -r /home/worker/data/remote-settings.in /home/worker/data/remote-settings.out
+ '[' -s /home/worker/artifacts/remote-settings.diff ']'
+ return 0
+ REMOTE_SETTINGS_UPDATED=true
+ '[' true == true ']'
+ compare_suffix_lists
+ HG_SUFFIX_URL=https://hg.mozilla.org/releases/mozilla-beta/raw-file/default//netwerk/dns/effective_tld_names.dat
+ cd /home/worker
+ echo 'INFO: wget -nv -O public_suffix_list.dat https://raw.githubusercontent.com/publicsuffix/list/master/public_suffix_list.dat'
INFO: wget -nv -O public_suffix_list.dat https://raw.githubusercontent.com/publicsuffix/list/master/public_suffix_list.dat
+ rm -f public_suffix_list.dat
+ wget -nv -O public_suffix_list.dat https://raw.githubusercontent.com/publicsuffix/list/master/public_suffix_list.dat
2021-04-15 15:00:16 URL:https://raw.githubusercontent.com/publicsuffix/list/master/public_suffix_list.dat [232376/232376] -> "public_suffix_list.dat" [1]
+ echo 'INFO: wget -nv -O effective_tld_names.dat https://hg.mozilla.org/releases/mozilla-beta/raw-file/default//netwerk/dns/effective_tld_names.dat'
INFO: wget -nv -O effective_tld_names.dat https://hg.mozilla.org/releases/mozilla-beta/raw-file/default//netwerk/dns/effective_tld_names.dat
+ rm -f effective_tld_names.dat
+ wget -nv -O effective_tld_names.dat https://hg.mozilla.org/releases/mozilla-beta/raw-file/default//netwerk/dns/effective_tld_names.dat
2021-04-15 15:00:18 URL:https://hg.mozilla.org/releases/mozilla-beta/raw-file/default//netwerk/dns/effective_tld_names.dat [232376/232376] -> "effective_tld_names.dat" [1]
+ echo 'INFO: diffing in-tree suffix list against the suffix list from AMO...'
INFO: diffing in-tree suffix list against the suffix list from AMO...
+ /usr/bin/diff -u public_suffix_list.dat effective_tld_names.dat
+ tee /home/worker/artifacts/effective_tld_names.diff
+ '[' -s /home/worker/artifacts/effective_tld_names.diff ']'
+ return 1
+ '[' true == false ']'
+ '[' '' == true ']'
+ clone_repo
+ cd /home/worker
+ '[' '!' -d mozilla-beta ']'
+ /usr/bin/hg robustcheckout --sharebase /tmp/hg-store -b default https://hg.mozilla.org/releases/mozilla-beta mozilla-beta
(using Mercurial 4.8.1)
ensuring https://hg.mozilla.org/releases/mozilla-beta@default is available at mozilla-beta
(sharing from new pooled repository 8ba995b74e18334ab3707f27e9eb8f4e37ba3d29)
applying clone bundle from https://s3-us-west-1.amazonaws.com/moz-hg-bundles-us-west-1/releases/mozilla-beta/d7557f06514b88d62c5a35b29291d59fc829d86d.stream-v2.hg
617572 files to transfer, 3.53 GB of data
transferred 3.53 GB in 111.4 seconds (32.5 MB/sec)
finished applying clone bundle
searching for changes
no changes found
searching for changes
no changes found
(pulling to obtain default)
(remote resolved default to d7557f06514b88d62c5a35b29291d59fc829d86d; result is not deterministic)
(revision already present locally; not pulling)
(warning: large working directory being used without fsmonitor enabled; enable fsmonitor to improve performance; see "hg help -e fsmonitor")
289122 files updated, 0 files merged, 0 files removed, 0 files unresolved
updated to d7557f06514b88d62c5a35b29291d59fc829d86d
PERFHERDER_DATA: {"framework": {"name": "vcs"}, "suites": [{"extraOptions": ["c5.4xlarge"], "hgVersion": "4.8.1", "lowerIsBetter": true, "name": "clone", "serverUrl": "hg.mozilla.org", "shouldAlert": false, "subtests": [], "value": 113.08376979827881}, {"extraOptions": ["c5.4xlarge"], "hgVersion": "4.8.1", "lowerIsBetter": true, "name": "update", "serverUrl": "hg.mozilla.org", "shouldAlert": false, "subtests": [], "value": 188.24373602867126}, {"extraOptions": ["c5.4xlarge"], "hgVersion": "4.8.1", "lowerIsBetter": true, "name": "overall", "serverUrl": "hg.mozilla.org", "shouldAlert": false, "subtests": [], "value": 302.0237760543823}, {"extraOptions": ["c5.4xlarge"], "hgVersion": "4.8.1", "lowerIsBetter": true, "name": "overall_clone", "serverUrl": "hg.mozilla.org", "shouldAlert": false, "subtests": [], "value": 302.0237760543823}, {"extraOptions": ["c5.4xlarge"], "hgVersion": "4.8.1", "lowerIsBetter": true, "name": "overall_clone_fullcheckout", "serverUrl": "hg.mozilla.org", "shouldAlert": false, "subtests": [], "value": 302.0237760543823}]}
+ /usr/bin/hg -R mozilla-beta pull
pulling from https://hg.mozilla.org/releases/mozilla-beta
searching for changes
no changes found
+ /usr/bin/hg -R mozilla-beta update -C default
0 files updated, 0 files merged, 0 files removed, 0 files unresolved
+ COMMIT_MESSAGE='No Bug, mozilla-beta repo-update'
+ '[' true == true ']'
+ stage_hsts_files
+ cd /home/worker
++ basename /home/worker/data/nsSTSPreloadList.inc
+ cp -f /home/worker/firefox/nsSTSPreloadList.inc mozilla-beta/security/manager/ssl/
+ COMMIT_MESSAGE='No Bug, mozilla-beta repo-update HSTS'
+ '[' true == true ']'
+ stage_hpkp_files
+ cd /home/worker
+ cp -f /home/worker/data/StaticHPKPins.h.out mozilla-beta/security/manager/ssl/StaticHPKPins.h
+ COMMIT_MESSAGE='No Bug, mozilla-beta repo-update HSTS HPKP'
+ '[' true == true ']'
+ stage_remote_settings_files
+ cd /home/worker
+ cp -a /home/worker/data/remote-settings.out/blocklists /home/worker/data/remote-settings.out/main /home/worker/data/remote-settings.out/pinning /home/worker/data/remote-settings.out/security-state mozilla-beta/services/settings/dumps
+ COMMIT_MESSAGE='No Bug, mozilla-beta repo-update HSTS HPKP remote-settings'
+ '[' false == true ']'
+ '[' false == true ']'
+ '[' false == true ']'
+ '[' true == true ']'
+ COMMIT_MESSAGE='No Bug, mozilla-beta repo-update HSTS HPKP remote-settings - a=repo-update'
+ /usr/bin/hg -R mozilla-beta commit -u 'ffxbld <[e-mail]>' -m 'No Bug, mozilla-beta repo-update HSTS HPKP remote-settings - a=repo-update'
+ push_repo
+ cd mozilla-beta
+ '[' '!' -r /home/worker/.arcrc ']'
++ command -v arc
+ ARC=/usr/bin/arc
+ '[' -z ryanvm ']'
++ /usr/bin/arc list
++ grep 'Needs Review'
++ grep -E 'mozilla-beta repo-update'
++ awk 'match($0, /D[0-9]+[^: ]/) { print substr($0, RSTART, RLENGTH)  }'
+ /usr/bin/arc diff --verbatim --reviewers ryanvm
Linting...
No lint engine configured for this project.
Running unit tests...
No unit test engine is configured for this project.
 SKIP STAGING  Phabricator does not support staging areas for this repository.
[taskcluster:error] Task timeout after 18000 seconds. Force killing container.
[taskcluster 2021-04-15 15:05:57.980Z] === Task Finished ===
[taskcluster 2021-04-15 15:05:57.980Z] Unsuccessful task run with exit code: -1 completed in 18011.371 seconds```

Comment 1

[Alexandru Michis [:malexandru]]

This started appearing intermittently on beta, Bug 1694217 tracked a similar failure and was deemed to be a blocking issue (https://bugzilla.mozilla.org/show_bug.cgi?id=1694217#c4).
Joel, should this be tracked as such?

Comment 2

[Julien Cristau [:jcristau]]

+ /usr/bin/diff -u /home/worker/firefox/nsSTSPreloadList.inc /home/worker/data/nsSTSPreloadList.inc
--- /home/worker/firefox/nsSTSPreloadList.inc	2021-04-15 14:57:20.809561978 +0000
+++ /home/worker/data/nsSTSPreloadList.inc	2021-04-15 10:06:09.417561978 +0000

(nevermind that we're calling diff new old instead of diff old new; that threw me off a bit)

getHSTSPreloadList.js looks like it takes 4h50min, out of a 5h limit for the task. We seem to have over 100k sites on the list now, we might need to find ways to speed up that process?

Comment 3

[Julien Cristau [:jcristau]]

For comparison yesterday's central job (https://firefoxci.taskcluster-artifacts.net/Z_VLUy3HRKGL1DPyKYDYIQ/0/public/logs/live_backing.log) completed in 17877.953 seconds, less than 2 minutes short of 5 hours, so it got lucky.

Comment 4

[Julien Cristau [:jcristau]]

[Tracking Requested - why for this release]:

88 will be fine as we only update HSTS pins on esr78, central and beta, not on mozilla-release.

Comment 5

[Julien Cristau [:jcristau]]

Attachment: Bug 1705639 - bump max run time for periodic-update job. r?#releng,ryanvm

Updating the HSTS preload list is now taking close to the previous limit
of 5 hours, so bump it to 6 hours as a stopgap, and adjust the start
time to keep its end time from going too late in the day.

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0700e49c5a70
bump max run time for periodic-update job. r=RyanVM,releng-reviewers,jmaher DONTBUILD

Comment 7

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/0700e49c5a70

Comment 8

[Intermittent Failures Robot]

1 failures in 4255 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

• linux64: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1705639&startday=2021-04-12&endday=2021-04-18&tree=all

Comment 9

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-esr78/rev/e0249662fb42