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"}
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.