1604928 - Intermittent build-docker-image ConnectionError: timed out

Multiple Authors

Description

•

4 years ago

•

Edited

treeherder

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=281794780&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/DKiQpQvFSCSA6kx4ZODg0g/runs/0/artifacts/public/logs/live_backing.log


[taskcluster 2019-12-18 21:07:17.066Z] === Task Starting ===
#!/bin/bash -vex
# Set bash options to exit immediately if a pipeline exists non-zero, expand
# print a trace of commands, and make output verbose (print shell input as it's
# read)
# See https://www.gnu.org/software/bash/manual/html_node/The-Set-Builtin.html
set -x -e -v -o pipefail
+ set -x -e -v -o pipefail
# Prefix errors with taskcluster error prefix so that they are parsed by Treeherder
raise_error() {
  echo
  echo "[taskcluster-image-build:error] $1"
  exit 1
}
# Ensure that the PROJECT is specified so the image can be indexed
test -n "$PROJECT"    || raise_error "PROJECT must be provided."
+ test -n autoland
test -n "$HASH"       || raise_error "Context HASH must be provided."
+ test -n 30d2e296b90c605c9a62a7e7ebbcc7718a0b844d44d47997f746fee04434c905
test -n "$IMAGE_NAME" || raise_error "IMAGE_NAME must be provided."
+ test -n condprof
# The docker socket is mounted by the taskcluster worker in a way that prevents
# us changing its permissions to allow the worker user to access it. Create a
# proxy socket that the worker user can use.
export DOCKER_SOCKET=/var/run/docker.proxy
+ export DOCKER_SOCKET=/var/run/docker.proxy
+ DOCKER_SOCKET=/var/run/docker.proxy
socat UNIX-LISTEN:$DOCKER_SOCKET,fork,group=worker,mode=0775 UNIX-CLIENT:/var/run/docker.sock </dev/null &
# Disable check until new version is tested.
# shellcheck disable=SC2064
trap "kill $!" EXIT
+ trap 'kill 9' EXIT
LOAD_COMMAND=
+ LOAD_COMMAND=
if [ -n "$DOCKER_IMAGE_PARENT" ]; then
    test -n "$DOCKER_IMAGE_PARENT_TASK" || raise_error "DOCKER_IMAGE_PARENT_TASK must be provided."
+ socat UNIX-LISTEN:/var/run/docker.proxy,fork,group=worker,mode=0775 UNIX-CLIENT:/var/run/docker.sock
    LOAD_COMMAND="\
      /builds/worker/checkouts/gecko/mach taskcluster-load-image \
      --task-id \"$DOCKER_IMAGE_PARENT_TASK\" \
      -t \"$DOCKER_IMAGE_PARENT\" && "
fi
+ '[' -n debian10-test:dca501fdc4c91f73df1a51f934519264992f2861dc7be466ab351b90fd0882c1 ']'
+ test -n MzvRHgGER0KqbhzVlkyYqA
+ LOAD_COMMAND='      /builds/worker/checkouts/gecko/mach taskcluster-load-image       --task-id "MzvRHgGER0KqbhzVlkyYqA"       -t "debian10-test:dca501fdc4c91f73df1a51f934519264992f2861dc7be466ab351b90fd0882c1" && '
# Build image
run-task \
  --gecko-checkout "/builds/worker/checkouts/gecko" \
  --gecko-sparse-profile build/sparse-profiles/docker-image \
  -- \
  sh -x -c "$LOAD_COMMAND \
  /builds/worker/checkouts/gecko/mach taskcluster-build-image \
  -t \"${IMAGE_NAME}:${HASH}-pre\" \
  \"$IMAGE_NAME\""
+ run-task --gecko-checkout /builds/worker/checkouts/gecko --gecko-sparse-profile build/sparse-profiles/docker-image -- sh -x -c '      /builds/worker/checkouts/gecko/mach taskcluster-load-image       --task-id "MzvRHgGER0KqbhzVlkyYqA"       -t "debian10-test:dca501fdc4c91f73df1a51f934519264992f2861dc7be466ab351b90fd0882c1" &&    /builds/worker/checkouts/gecko/mach taskcluster-build-image   -t "condprof:30d2e296b90c605c9a62a7e7ebbcc7718a0b844d44d47997f746fee04434c905-pre"   "condprof"'
[setup 2019-12-18T21:07:17.555Z] run-task started in /builds/worker
[cache 2019-12-18T21:07:17.558Z] cache /builds/worker/checkouts exists; requirements: gid=1000 uid=1000 version=1
[volume 2019-12-18T21:07:17.558Z] volume /builds/worker/checkouts is a cache
[volume 2019-12-18T21:07:17.558Z] changing ownership of volume /builds/worker/workspace to 1000:1000
[setup 2019-12-18T21:07:17.558Z] running as worker:worker
[vcs 2019-12-18T21:07:17.558Z] fetching hgmointernal config from http://taskcluster/secrets/v1/secret/project/taskcluster/gecko/hgmointernal
[vcs 2019-12-18T21:07:17.651Z] hgmointernal rate hit; cloning from private hgweb mirror
[vcs 2019-12-18T21:07:17.651Z] executing ['hg', 'robustcheckout', '--sharebase', '/builds/worker/checkouts/hg-store', '--purge', '--upstream', 'https://us-west-2.hgmointernal.net/mozilla-unified', '--sparseprofile', 'build/sparse-profiles/docker-image', '--revision', 'f97710c9392ec11cd21bd53207642fda49832f19', 'https://us-west-2.hgmointernal.net/integration/autoland', '/builds/worker/checkouts/gecko']
[vcs 2019-12-18T21:07:17.716Z] (using Mercurial 4.8.1)
[vcs 2019-12-18T21:07:17.716Z] ensuring https://us-west-2.hgmointernal.net/integration/autoland@f97710c9392ec11cd21bd53207642fda49832f19 is available at /builds/worker/checkouts/gecko
[vcs 2019-12-18T21:07:17.717Z] (existing repository shared store: /builds/worker/checkouts/hg-store/8ba995b74e18334ab3707f27e9eb8f4e37ba3d29/.hg)
[vcs 2019-12-18T21:07:18.096Z] (pulling to obtain f97710c9392ec11cd21bd53207642fda49832f19)
[vcs 2019-12-18T21:07:18.375Z] searching for changes
[vcs 2019-12-18T21:07:24.783Z] adding changesets
[vcs 2019-12-18T21:07:24.789Z] 
[vcs 2019-12-18T21:07:24.790Z] changesets [==============================>                               ] 1/2
[vcs 2019-12-18T21:07:24.790Z]                                                                                 
[vcs 2019-12-18T21:07:24.790Z] adding manifests
[vcs 2019-12-18T21:07:24.844Z] adding file changes
[vcs 2019-12-18T21:07:25.468Z] added 2 changesets with 23 changes to 23 files
[vcs 2019-12-18T21:07:25.771Z] new changesets 1b4c3b317568:f97710c9392e
[vcs 2019-12-18T21:07:25.772Z] (purging working directory)
[vcs 2019-12-18T21:07:26.186Z] (sparse profile build/sparse-profiles/docker-image already set; no need to update sparse config)
[vcs 2019-12-18T21:07:26.250Z] 0 files updated, 0 files merged, 0 files removed, 0 files unresolved
[vcs 2019-12-18T21:07:26.252Z] updated to f97710c9392ec11cd21bd53207642fda49832f19
[vcs 2019-12-18T21:07:26.255Z] PERFHERDER_DATA: {"framework": {"name": "vcs"}, "suites": [{"extraOptions": ["c5.xlarge"], "lowerIsBetter": true, "name": "pull", "serverUrl": "us-west-2.hgmointernal.net", "shouldAlert": false, "subtests": [], "value": 7.553670883178711}, {"extraOptions": ["c5.xlarge"], "lowerIsBetter": true, "name": "purge", "serverUrl": "us-west-2.hgmointernal.net", "shouldAlert": false, "subtests": [], "value": 0.3455178737640381}, {"extraOptions": ["c5.xlarge"], "lowerIsBetter": true, "name": "update_sparse", "serverUrl": "us-west-2.hgmointernal.net", "shouldAlert": false, "subtests": [], "value": 0.06613898277282715}, {"extraOptions": ["c5.xlarge"], "lowerIsBetter": true, "name": "overall", "serverUrl": "us-west-2.hgmointernal.net", "shouldAlert": false, "subtests": [], "value": 8.536008834838867}, {"extraOptions": ["c5.xlarge"], "lowerIsBetter": true, "name": "overall_pull", "serverUrl": "us-west-2.hgmointernal.net", "shouldAlert": false, "subtests": [], "value": 8.536008834838867}, {"extraOptions": ["c5.xlarge"], "lowerIsBetter": true, "name": "overall_pull_fullcheckout", "serverUrl": "us-west-2.hgmointernal.net", "shouldAlert": false, "subtests": [], "value": 8.536008834838867}, {"extraOptions": ["c5.xlarge"], "lowerIsBetter": true, "name": "overall_pull_populatedwdir", "serverUrl": "us-west-2.hgmointernal.net", "shouldAlert": false, "subtests": [], "value": 8.536008834838867}]}
[vcs 2019-12-18T21:07:26.478Z] TinderboxPrint:<a href=https://us-west-2.hgmointernal.net/integration/autoland/rev/f97710c9392ec11cd21bd53207642fda49832f19 title='Built from autoland revision f97710c9392ec11cd21bd53207642fda49832f19'>f97710c9392ec11cd21bd53207642fda49832f19</a>
[task 2019-12-18T21:07:26.478Z] executing ['sh', '-x', '-c', '      /builds/worker/checkouts/gecko/mach taskcluster-load-image       --task-id "MzvRHgGER0KqbhzVlkyYqA"       -t "debian10-test:dca501fdc4c91f73df1a51f934519264992f2861dc7be466ab351b90fd0882c1" &&    /builds/worker/checkouts/gecko/mach taskcluster-build-image   -t "condprof:30d2e296b90c605c9a62a7e7ebbcc7718a0b844d44d47997f746fee04434c905-pre"   "condprof"']
[task 2019-12-18T21:07:26.480Z] + /builds/worker/checkouts/gecko/mach taskcluster-load-image --task-id MzvRHgGER0KqbhzVlkyYqA -t debian10-test:dca501fdc4c91f73df1a51f934519264992f2861dc7be466ab351b90fd0882c1
[task 2019-12-18T21:08:52.981Z] Traceback (most recent call last):
[task 2019-12-18T21:08:52.981Z]   File "/builds/worker/checkouts/gecko/taskcluster/mach_commands.py", line 478, in load_image
[task 2019-12-18T21:08:52.981Z]     ok = load_image_by_task_id(task_id, tag)
[task 2019-12-18T21:08:52.981Z]   File "/builds/worker/checkouts/gecko/taskcluster/taskgraph/docker.py", line 49, in load_image_by_task_id
[task 2019-12-18T21:08:52.981Z]     result = load_image(artifact_url, tag)
[task 2019-12-18T21:08:52.981Z]   File "/builds/worker/checkouts/gecko/taskcluster/taskgraph/docker.py", line 187, in load_image
[task 2019-12-18T21:08:52.981Z]     docker.post_to_docker(download_and_modify_image(), '/images/load', quiet=0)
[task 2019-12-18T21:08:52.981Z]   File "/builds/worker/checkouts/gecko/taskcluster/taskgraph/util/docker.py", line 51, in post_to_docker
[task 2019-12-18T21:08:52.981Z]     headers={'Content-Type': 'application/x-tar'},
[task 2019-12-18T21:08:52.981Z]   File "/builds/worker/checkouts/gecko/third_party/python/requests/requests/sessions.py", line 511, in post
[task 2019-12-18T21:08:52.981Z]     return self.request('POST', url, data=data, json=json, **kwargs)
[task 2019-12-18T21:08:52.981Z]   File "/builds/worker/checkouts/gecko/third_party/python/requests/requests/sessions.py", line 468, in request
[task 2019-12-18T21:08:52.981Z]     resp = self.send(prep, **send_kwargs)
[task 2019-12-18T21:08:52.981Z]   File "/builds/worker/checkouts/gecko/third_party/python/requests/requests/sessions.py", line 576, in send
[task 2019-12-18T21:08:52.981Z]     r = adapter.send(request, **kwargs)
[task 2019-12-18T21:08:52.981Z]   File "/builds/worker/checkouts/gecko/third_party/python/requests/requests/adapters.py", line 426, in send
[task 2019-12-18T21:08:52.981Z]     raise ConnectionError(err, request=request)
[task 2019-12-18T21:08:52.981Z] ConnectionError: timed out
[task 2019-12-18T21:08:52.981Z] Downloading from https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/MzvRHgGER0KqbhzVlkyYqA/artifacts/public/image.tar.zst
kill 9
+ kill 9
[taskcluster 2019-12-18 21:08:57.246Z] === Task Finished ===
[taskcluster 2019-12-18 21:08:57.359Z] Artifact "public/image.tar.zst" not found at "/builds/worker/workspace/artifacts/image.tar.zst"
[taskcluster 2019-12-18 21:08:57.533Z] Unsuccessful task run with exit code: 1 completed in 102.822 seconds

Bogdan Tara[:bogdan_tara | bogdant]

Updated

•

4 years ago

Flags: needinfo?(mozilla)

Bogdan Tara[:bogdan_tara | bogdant]

Comment 1

•

4 years ago

ps: not sure about the product and component here. Sorry

Tom Prince [:tomprince]

Assignee

Comment 2

•

4 years ago

This appears to happen when the docker-image parent is too big.

Component: General → Task Configuration

Flags: needinfo?(mozilla)

Summary: Intermittent condprof ConnectionError: timed out → Intermittent build-docker-image ConnectionError: timed out

Comment hidden (Intermittent Failures Robot)

Tom Prince [:tomprince]

Assignee

Comment 4

•

4 years ago

Attached file Bug 1604928: Increase docker-image load timeout; r?Callek — Details

requests-unixsocket has a default timeout that is too large to reliably
load the larger docker-images we have. Double the timeout to enable
images to build reliably.

Phabricator Automation

Updated

•

4 years ago

Assignee: nobody → mozilla

Status: NEW → ASSIGNED

Pulsebot

Comment 5

•

4 years ago

Pushed by mozilla@hocat.ca:
https://hg.mozilla.org/integration/autoland/rev/fcd6b4e770b3
Increase docker-image load timeout; r=Callek

Cristina Coroiu [:ccoroiu]

Comment 6

•

4 years ago

bugherder

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

Status: ASSIGNED → RESOLVED

Closed: 4 years ago

status-firefox73: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → mozilla73

Ryan VanderMeulen [:RyanVM]

Comment 7

•

4 years ago

bugherder uplift

https://hg.mozilla.org/releases/mozilla-esr68/rev/54676ee97433

status-firefox-esr68: --- → fixed

Bugzilla

Quick Search

Intermittent build-docker-image ConnectionError: timed out

Categories

(Firefox Build System :: Task Configuration, defect, P5)

Tracking

(firefox-esr68 fixed, firefox73 fixed)

People

(Reporter: intermittent-bug-filer, Assigned: tomprince)

References

Details

(Keywords: intermittent-failure)

Crash Data

Security

(public)

User Story

Attachments

(1 file)

Description

Updated

Comment 1

Comment 2

Comment 3

Comment 4

Updated

Comment 5

Comment 6

Comment 7

Attachment

General

Description

File Name

Content Type