image builder: unhelpful apt-get update 100 error

Bug #1291297 reported by Evan
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Ubuntu CI Engine
Fix Released
High
Andy Doan
Ubuntu CI Services
Fix Released
High
Andy Doan

Bug Description

The image builder failed for me when apt-get update exited with 100. I suspect this is a transient failure, but we should:

1) capture stderr
2) print the stdout and stderr of the command on failure.

Logs:

Started by upstream project "lander_master" build number 2
originally caused by:
 Started by remote host 10.0.0.200
Building in workspace /var/lib/jenkins/jobs/lander_image_builder/workspace
[workspace] $ /bin/bash /tmp/hudson5246052765100247867.sh
+ '[' -d results ']'
+ mkdir results
+ sed 's/\\/\\\\/g'
+ echo '{"bsbuilder":' '{"ppa":' '"ppa:ev/ci-pool-001",' '"artifacts":' '[{"type":' '"LOGS",' '"name":' '"package_build.output.log",' '"reference":' '"https://region-a.geo-1.objects.hpcloudsvc.com/v1/11597203075020/ticket-2/package_build.output.log"}],' '"state":' '"COMPLETED",' '"exit":' true, '"result":' '"PASSED",' '"message":' '"The' package build was 'successful.",' '"archive":' '"ppa:ev/ci-archive",' '"subticket_status":' '[{"status":' 230, '"resource":' '"/api/v1/fullsubticket/2/",' '"name":' '"cowsay",' '"step_text":' '"Completed",' '"step":' 1000, '"version":' '"3.03+dfsg1-7~ev2",' '"message":' '"The' source packages have been built in 'https://launchpad.net/~ev/+archive/ci-pool-001.",' '"status_text":' '"Completed",' '"id":' '2}]},' '"master":' '{"ppa_assigner_url":' '"http://10.0.0.202:8080",' '"progress_trigger":' '"lander_master-2",' '"imgbuilder_url":' '"http://10.0.0.199:8080",' '"tr_url":' '"http://10.0.0.206:8080",' '"bsb_url":' '"http://10.0.0.197:8080",' '"request_id":' '"2",' '"ts_url":' '"http://10.0.0.207:8080"},' '"ppa_assigner":' '{"ppa":' '"ppa:ev/ci-pool-001",' '"result":' '"PASSED",' '"location":' '"http://10.0.0.202:8080/api/v1/ppa/2/"}}'
+ cat
++ cat params.json
++ grep -Po '(?<=ts_url": )"http:.*?"'
++ sed 's/"//g'
+ /srv/lander_jenkins_sub/lander/bin/lander_service_wrapper.py --input-file params.json --output-file results/params.json --service image_builder
09:49:22 DEBUG lander_service_wrapper: Executing service wrapper: image_builder
09:49:23 INFO lander_service_wrapper: Calling via POST [http://10.0.0.199:8080/api/v1/build_image]: {'progress_trigger': u'lander_master-2-imgbuilder', 'ppa_list': [u'ppa:ev/ci-pool-001', u'ppa:ev/ci-archive'], 'package_list': [u'cowsay'], 'cancel_url': 'http://10.0.0.200:8080/job/lander_image_builder/1/api/json', 'ticket_id': u'2', 'base_image': {'image_type': 'cloud', 'series': u'saucy', 'url_list': [u'http://cloud-images.ubuntu.com/releases/13.10/release-20131015/ubuntu-13.10-server-cloudimg-amd64-disk1.img', '']}}
09:49:23 INFO lander_service_wrapper: starting progress handler...
09:49:23 DEBUG amqplib: Start from server, version: 8.0, properties: {u'information': u'Licensed under the MPL. See http://www.rabbitmq.com/', u'product': u'RabbitMQ', u'copyright': u'Copyright (C) 2007-2011 VMware, Inc.', u'capabilities': {}, u'platform': u'Erlang/OTP', u'version': u'2.7.1'}, mechanisms: [u'PLAIN', u'AMQPLAIN'], locales: [u'en_US']
09:49:23 DEBUG amqplib: Open OK! known_hosts []
09:49:23 DEBUG amqplib: using channel_id: 1
09:49:23 DEBUG amqplib: Channel open
09:49:23 INFO root: Waiting for messages. ^C to exit.
09:49:23 INFO PROGRESS_TRIGGER: WAITING: {u'progress_trigger': u'lander_master-2-imgbuilder', u'series': u'saucy', u'image': u'http://cloud-images.ubuntu.com/releases/13.10/release-20131015/ubuntu-13.10-server-cloudimg-amd64-disk1.img', u'ppa_list': [u'ppa:ev/ci-pool-001', u'ppa:ev/ci-archive'], u'package_list': [u'cowsay'], u'cancel_url': u'http://10.0.0.200:8080/job/lander_image_builder/1/api/json', u'ticket_id': u'2'}
09:49:23 INFO PROGRESS_TRIGGER: STATUS: {u'progress_trigger': u'lander_master-2-imgbuilder', u'series': u'saucy', u'image': u'http://cloud-images.ubuntu.com/releases/13.10/release-20131015/ubuntu-13.10-server-cloudimg-amd64-disk1.img', u'ppa_list': [u'ppa:ev/ci-pool-001', u'ppa:ev/ci-archive'], u'package_list': [u'cowsay'], u'cancel_url': u'http://10.0.0.200:8080/job/lander_image_builder/1/api/json', u'ticket_id': u'2'}
09:49:23 INFO PROGRESS_TRIGGER: STATUS: {u'message': u'loading nbd...'}
09:49:23 INFO PROGRESS_TRIGGER: STATUS: {u'message': u'downloading http://cloud-images.ubuntu.com/releases/13.10/release-20131015/ubuntu-13.10-server-cloudimg-amd64-disk1.img...'}
09:50:36 INFO PROGRESS_TRIGGER: STATUS: {u'message': u'updating image http://cloud-images.ubuntu.com/releases/13.10/release-20131015/ubuntu-13.10-server-cloudimg-amd64-disk1.img...'}
09:50:36 INFO PROGRESS_TRIGGER: STATUS: {u'message': u'Adding requested packages to the image...'}
09:51:09 INFO PROGRESS_TRIGGER: COMPLETED: {u'artifacts': [{u'type': u'LOGS', u'name': u'image_builder.output.log', u'reference': u'https://region-a.geo-1.objects.hpcloudsvc.com/v1/11597203075020/ticket-2/image_builder.output.log'}], u'error_message': u'Unexpected exception occurred', u'exit': True, u'result': u'FAILED', u'traceback': u'Traceback (most recent call last):\n File "/srv/imagebuild_worker/ci-utils/ci_utils/amqp_worker.py", line 170, in _on_message\n amqp_cb, ret = self.handle_request(logger, params)\n File "./image-builder/imagebuilder/run_worker.py", line 37, in handle_request\n image_id = modify_image(image, repos, series, packages, status_cb)\n File "/srv/imagebuild_worker/image-builder/imagebuilder/cloud_image.py", line 196, in modify_image\n _run_chroot_cmds(mountpoint, ppalist, packages)\n File "/srv/imagebuild_worker/image-builder/imagebuilder/cloud_image.py", line 88, in _run_chroot_cmds\n _chrooted(chroot, "/usr/bin/apt-get update")\n File "/srv/imagebuild_worker/image-builder/imagebuilder/cloud_image.py", line 75, in _chrooted\n output = subprocess.check_output([\'chroot\', chroot] + cmd.split(" "))\n File "/usr/lib/python2.7/subprocess.py", line 544, in check_output\n raise CalledProcessError(retcode, cmd, output=output)\nCalledProcessError: Command \'[\'chroot\', \'/tmp/tmpJ4yTZe/mountpoint\', \'/usr/bin/apt-get\', \'update\']\' returned non-zero exit status 100\n'}
09:51:09 DEBUG amqplib: Closed channel #1
Build step 'Execute shell' marked build as failure
Archiving artifacts
Triggering a new build of lander_archiver #7
Finished: FAILURE

{"error_message": "Unexpected exception occurred", "artifacts": [{"type": "LOGS", "name": "image_builder.output.log", "reference": "https://region-a.geo-1.objects.hpcloudsvc.com/v1/11597203075020/ticket-2/image_builder.output.log"}], "traceback": "Traceback (most recent call last):\n File \"/srv/imagebuild_worker/ci-utils/ci_utils/amqp_worker.py\", line 170, in _on_message\n amqp_cb, ret = self.handle_request(logger, params)\n File \"./image-builder/imagebuilder/run_worker.py\", line 37, in handle_request\n image_id = modify_image(image, repos, series, packages, status_cb)\n File \"/srv/imagebuild_worker/image-builder/imagebuilder/cloud_image.py\", line 196, in modify_image\n _run_chroot_cmds(mountpoint, ppalist, packages)\n File \"/srv/imagebuild_worker/image-builder/imagebuilder/cloud_image.py\", line 88, in _run_chroot_cmds\n _chrooted(chroot, \"/usr/bin/apt-get update\")\n File \"/srv/imagebuild_worker/image-builder/imagebuilder/cloud_image.py\", line 75, in _chrooted\n output = subprocess.check_output(['chroot', chroot] + cmd.split(\" \"))\n File \"/usr/lib/python2.7/subprocess.py\", line 544, in check_output\n raise CalledProcessError(retcode, cmd, output=output)\nCalledProcessError: Command '['chroot', '/tmp/tmpJ4yTZe/mountpoint', '/usr/bin/apt-get', 'update']' returned non-zero exit status 100\n", "state": "COMPLETED", "exit": true, "result": "FAILED"}

Tags: airline
Revision history for this message
Francis Ginther (fginther) wrote :

In upstream merger testing, 'apt-get update' is know to have transient failures caused by catching the archive in the middle of an update. This error happens so frequently, the code just blindly retries. As a result, all of these calls are actually done with:

apt-get update || apt-get update || apt-get update

The failure signature of the archive update is a hash sum mistmatch. I could probably dig up the exact error message if necessary.

Evan (ev)
Changed in ubuntu-ci-services-itself:
assignee: Evan Dandrea (ev) → nobody
Revision history for this message
Andy Doan (doanac) wrote :

I'm going to do 2 changes:

1) improve the logging (i have a small patch ready for that)
2) try this "update || update || update" approach. We've seen the same thing in daily image testing, but have been lucky lately because its mostly click-packages.

Changed in ubuntu-ci-services-itself:
assignee: nobody → Andy Doan (doanac)
Andy Doan (doanac)
Changed in ubuntu-ci-services-itself:
status: New → In Progress
Andy Doan (doanac)
Changed in ubuntu-ci-services-itself:
status: In Progress → Fix Released
Ursula Junque (ursinha)
Changed in uci-engine:
assignee: nobody → Andy Doan (doanac)
importance: Undecided → High
milestone: none → phase-0
status: New → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.