Bug 719011

Summary: Oz aborted the build after going 300 seconds with no disk activity.
Product: [Retired] CloudForms Cloud Engine Reporter: Shveta <ssachdev>
Component: aeolus-conductorAssignee: Chris Lalancette <clalance>
Status: CLOSED CURRENTRELEASE QA Contact: Dave Johnson <dajohnso>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 0.3.1CC: akarol, dajohnso, deltacloud-maint, dgao, matt.wagner, ssachdev
Target Milestone: beta   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Shveta 2011-07-05 13:06:43 UTC 
Description of problem:


Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1.  Build image for vmware fails with error in log as pasted below
2.
3.
  
Actual results:


Expected results:


Additional info:

============================================
 aeolus-image build --target vmware --template template2.tpl 

Target Image: 8bb5ee89-6d2b-4d44-a271-054eac8facfb
Image: d16f2ce2-eaf1-4d7a-9b4e-81328b180303
Build: 46f0b256-e98a-48b7-a996-0cafa0e01867
Status: New
Percent Complete: 0
====================================================

http://pastebin.test.redhat.com/55131

========================================imagefactory.log================
2011-07-05 18:23:01,027 DEBUG imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(18826) Message: Method called: name = build_image 
 args = {'image': '', 'build': '', 'template': '<?xml version="1.0"?>\n<template>\n  <name>shveta_test_west</name>\n  <description>desc</description>\n  <os>\n    <name>Fedora</name>\n    <arch>x86_64</arch>\n    <version>14</version>\n    <install type="url">\n      <url>http://download.fedoraproject.org/pub/fedora/linux/releases/14/Fedora/x86_64/os/</url>\n    </install>\n  </os>\n  <repositories>\n    <repository name="custom">\n      <url>http://repos.fedorapeople.org/repos/aeolus/demo/webapp/</url>\n      <signed>false</signed>\n    </repository>\n  </repositories>\n</template>\n', 'targets': ['vmware']} 
 handle = <cqmf2.AgentEvent; proxy of <Swig Object of type 'qmf::AgentEvent *' at 0x1cd3b10> > 
 addr = redhat.com:imagefactory:29eb754a-2eed-4b49-8aba-8d745570169b:image_factory 
 subtypes = {} 
 userId = anonymous
2011-07-05 18:23:01,029 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(18826) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-05 18:23:01,031 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(18826) Message: Creating a bucket returned status 500.  If only iwhd would provide a sane way to know if a bucket exists so we wouldn't have to try and create one every time...
2011-07-05 18:23:01,052 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(18826) Message: Setting metadata ({'object_type': 'image', 'uuid': 'd16f2ce2-eaf1-4d7a-9b4e-81328b180303'}) for http://localhost:9090/images/d16f2ce2-eaf1-4d7a-9b4e-81328b180303
2011-07-05 18:23:01,136 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(18826) Message: Creating a bucket returned status 500.  If only iwhd would provide a sane way to know if a bucket exists so we wouldn't have to try and create one every time...
2011-07-05 18:23:01,139 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(18826) Message: Setting metadata ({'image': 'd16f2ce2-eaf1-4d7a-9b4e-81328b180303', 'object_type': 'build', 'uuid': '46f0b256-e98a-48b7-a996-0cafa0e01867'}) for http://localhost:9090/builds/46f0b256-e98a-48b7-a996-0cafa0e01867
2011-07-05 18:23:01,265 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(18826) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-05 18:23:01,296 DEBUG oz.Guest.FedoraGuest pid(18826) Message: libvirt bridge name is virbr0, host_bridge_ip is 192.168.122.1
2011-07-05 18:23:01,296 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Name: shveta_test_west, UUID: 5780d910-8ba0-45fd-8f28-81139a9d93db
2011-07-05 18:23:01,296 DEBUG oz.Guest.FedoraGuest pid(18826) Message: MAC: 52:54:00:27:7c:1c, distro: Fedora
2011-07-05 18:23:01,296 DEBUG oz.Guest.FedoraGuest pid(18826) Message: update: 14, arch: x86_64, diskimage: /var/tmp/shveta_test_west.dsk
2011-07-05 18:23:01,297 DEBUG oz.Guest.FedoraGuest pid(18826) Message: nicmodel: virtio, clockoffset: utc
2011-07-05 18:23:01,297 DEBUG oz.Guest.FedoraGuest pid(18826) Message: mousetype: ps2, disk_bus: virtio, disk_dev: vda
2011-07-05 18:23:01,297 DEBUG oz.Guest.FedoraGuest pid(18826) Message: icicletmp: /var/lib/oz/icicletmp/shveta_test_west, listen_port: 31110
2011-07-05 18:23:01,297 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Original ISO path: /var/lib/oz/isos/Fedora14x86_64-url.iso
2011-07-05 18:23:01,297 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Modified ISO cache: /var/lib/oz/isos/Fedora14x86_64-url-oz.iso
2011-07-05 18:23:01,297 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Output ISO path: /var/tmp/shveta_test_west-url-oz.iso
2011-07-05 18:23:01,298 DEBUG oz.Guest.FedoraGuest pid(18826) Message: ISO content path: /var/lib/oz/isocontent/shveta_test_west-url
2011-07-05 18:23:11,187 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Original URL http://download.fedoraproject.org/pub/fedora/linux/releases/14/Fedora/x86_64/os/ resolved to http://download.eng.pnq.redhat.com/pub/fedora/linux/releases/14/Fedora/x86_64/os/
2011-07-05 18:23:11,188 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(18826) Message: build_upload() called on FedoraBuilder...
2011-07-05 18:23:11,188 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(18826) Message: Building for target vmware with warehouse config http://localhost:9090/
2011-07-05 18:23:11,188 DEBUG imagefactory.BuildJob.BuildAdaptor pid(18826) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from NEW to BUILDING
2011-07-05 18:23:11,189 INFO oz.Guest.FedoraGuest pid(18826) Message: Cleaning up guest named shveta_test_west
2011-07-05 18:23:11,191 INFO oz.Guest.FedoraGuest pid(18826) Message: Generating install media
2011-07-05 18:23:11,193 INFO oz.Guest.FedoraGuest pid(18826) Message: Fetching the original media
2011-07-05 18:23:11,196 INFO oz.Guest.FedoraGuest pid(18826) Message: Original install media available, using cached version
2011-07-05 18:23:11,197 INFO oz.Guest.FedoraGuest pid(18826) Message: Copying ISO contents for modification
2011-07-05 18:23:11,197 INFO oz.Guest.FedoraGuest pid(18826) Message: Setting up guestfs handle for shveta_test_west
2011-07-05 18:23:11,197 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Adding ISO image /var/lib/oz/isos/Fedora14x86_64-url.iso
2011-07-05 18:23:11,198 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Launching guestfs
2011-07-05 18:23:25,166 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Mounting ISO
2011-07-05 18:23:25,185 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Checking if there is enough space on the filesystem
2011-07-05 18:23:25,187 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Extracting ISO contents
2011-07-05 18:23:30,321 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Putting the kickstart in place
2011-07-05 18:23:30,322 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Modifying the boot options
2011-07-05 18:23:30,323 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Generating new ISO
2011-07-05 18:23:30,884 INFO oz.Guest.FedoraGuest pid(18826) Message: Cleaning up old ISO data
2011-07-05 18:23:30,936 DEBUG imagefactory.BuildJob.BuildAdaptor pid(18826) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 0 to 10
2011-07-05 18:23:30,937 INFO oz.Guest.FedoraGuest pid(18826) Message: Generating 10GB diskimage for shveta_test_west
2011-07-05 18:23:30,937 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(18826) Message: Doing base install via Oz
2011-07-05 18:23:30,938 INFO oz.Guest.FedoraGuest pid(18826) Message: Running install for shveta_test_west
2011-07-05 18:23:30,938 INFO oz.Guest.FedoraGuest pid(18826) Message: Generate XML for guest shveta_test_west with bootdev cdrom
2011-07-05 18:23:30,938 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Generated XML:
<?xml version="1.0"?>
<domain type="kvm">
  <name>shveta_test_west</name>
  <memory>1048576</memory>
  <currentMemory>1048576</currentMemory>
  <uuid>5780d910-8ba0-45fd-8f28-81139a9d93db</uuid>
  <clock offset="utc"/>
  <vcpu>1</vcpu>
  <features>
    <acpi/>
    <apic/>
    <pae/>
  </features>
  <os>
    <type>hvm</type>
    <boot dev="cdrom"/>
  </os>
  <on_poweroff>destroy</on_poweroff>
  <on_reboot>destroy</on_reboot>
  <on_crash>destroy</on_crash>
  <devices>
    <console device="pty"/>
    <graphics port="-1" type="vnc"/>
    <interface type="bridge">
      <source bridge="virbr0"/>
      <mac address="52:54:00:27:7c:1c"/>
      <model type="virtio"/>
    </interface>
    <input bus="ps2" type="mouse"/>
    <console type="pty">
      <target port="0"/>
    </console>
    <disk device="disk" type="file">
      <target dev="vda" bus="virtio"/>
      <source file="/var/tmp/base-image-8bb5ee89-6d2b-4d44-a271-054eac8facfb.dsk"/>
    </disk>
    <disk type="file" device="cdrom">
      <source file="/var/tmp/shveta_test_west-url-oz.iso"/>
      <target dev="hdc"/>
    </disk>
  </devices>
</domain>

2011-07-05 18:23:42,332 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3600/3600
2011-07-05 18:23:53,276 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3590/3600
2011-07-05 18:24:03,318 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3580/3600
2011-07-05 18:24:13,350 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3570/3600
2011-07-05 18:24:23,559 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3560/3600
2011-07-05 18:24:34,335 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3550/3600
2011-07-05 18:24:44,382 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3540/3600
2011-07-05 18:24:54,699 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3530/3600
2011-07-05 18:25:05,172 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3520/3600
2011-07-05 18:25:15,408 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3510/3600
2011-07-05 18:25:25,444 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3500/3600
2011-07-05 18:25:36,097 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3490/3600
2011-07-05 18:25:46,411 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3480/3600
2011-07-05 18:25:56,452 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3470/3600
2011-07-05 18:26:06,626 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3460/3600
2011-07-05 18:26:17,213 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3450/3600
2011-07-05 18:26:27,479 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3440/3600
2011-07-05 18:26:38,262 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3430/3600
2011-07-05 18:26:48,446 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3420/3600
2011-07-05 18:26:58,475 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3410/3600
2011-07-05 18:27:08,518 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3400/3600
2011-07-05 18:27:18,777 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3390/3600
2011-07-05 18:27:29,449 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3380/3600
2011-07-05 18:27:39,502 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3370/3600
2011-07-05 18:27:49,555 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3360/3600
2011-07-05 18:27:59,982 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3350/3600
2011-07-05 18:28:10,510 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3340/3600
2011-07-05 18:28:20,544 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3330/3600
2011-07-05 18:28:30,572 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3320/3600
2011-07-05 18:28:40,599 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3310/3600
2011-07-05 18:28:50,627 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3300/3600
2011-07-05 18:29:00,655 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3290/3600
2011-07-05 18:29:10,685 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3280/3600
2011-07-05 18:29:20,713 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3270/3600
2011-07-05 18:29:30,739 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3260/3600
2011-07-05 18:29:40,771 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3250/3600
2011-07-05 18:29:50,795 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3240/3600
2011-07-05 18:30:00,821 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3230/3600
2011-07-05 18:30:10,848 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3220/3600
2011-07-05 18:30:20,878 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3210/3600
2011-07-05 18:30:30,905 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3200/3600
2011-07-05 18:30:40,932 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3190/3600
2011-07-05 18:30:50,960 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3180/3600
2011-07-05 18:31:00,987 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Waiting for shveta_test_west to finish installing, 3170/3600
2011-07-05 18:31:06,187 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(18826) Message: Exception caught in ImageFactory
2011-07-05 18:31:06,188 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(18826) Message: Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/imagefactory/builders/FedoraBuilder.py", line 173, in build_upload
    libvirt_xml = self.guest.install(self.app_config["timeout"])
  File "/usr/lib/python2.6/site-packages/oz/Guest.py", line 1038, in install
    self.wait_for_install_finish(dom, timeout)
  File "/usr/lib/python2.6/site-packages/oz/Guest.py", line 431, in wait_for_install_finish
    raise oz.OzException.OzException("No disk activity in %d seconds, failing" % (inactivity_timeout))
OzException: No disk activity in 300 seconds, failing

2011-07-05 18:31:06,189 INFO oz.Guest.FedoraGuest pid(18826) Message: Cleaning up guest named shveta_test_west
2011-07-05 18:31:06,786 DEBUG imagefactory.BuildJob.BuildAdaptor pid(18826) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from BUILDING to FAILED
2011-07-05 18:31:06,787 INFO oz.Guest.FedoraGuest pid(18826) Message: Cleaning up after install
2011-07-05 18:31:06,787 DEBUG oz.Guest.FedoraGuest pid(18826) Message: Removing modified ISO
2011-07-05 18:31:06,833 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(18826) Message: Exception caught in ImageFactory
2011-07-05 18:31:06,834 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(18826) Message: Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/imagefactory/builders/FedoraBuilder.py", line 125, in build_image
    self.build_upload(build_id)
  File "/usr/lib/python2.6/site-packages/imagefactory/builders/FedoraBuilder.py", line 173, in build_upload
    libvirt_xml = self.guest.install(self.app_config["timeout"])
  File "/usr/lib/python2.6/site-packages/oz/Guest.py", line 1038, in install
    self.wait_for_install_finish(dom, timeout)
  File "/usr/lib/python2.6/site-packages/oz/Guest.py", line 431, in wait_for_install_finish
    raise oz.OzException.OzException("No disk activity in %d seconds, failing" % (inactivity_timeout))
OzException: No disk activity in 300 seconds, failing

2011-07-05 18:31:06,834 DEBUG imagefactory.BuildJob.BuildAdaptor pid(18826) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from FAILED to FAILED
Comment 1 Matt Wagner 2011-07-06 18:39:31 UTC 
Oz aborted the build after going 300 seconds with no disk activity. It's likely not specifically tied to vmware.

If you can reproduce this bug, would you look for a .png screenshot that Oz saves when the build fails, and attach that? It's rumored to be saved in /, but it might be worth checking /tmp or /var/lib/oz or whatnot if it's not in /.
Comment 2 wes hayutin 2011-07-06 21:54:28 UTC 
buu
Comment 3 wes hayutin 2011-07-06 21:54:52 UTC 
Shveta.. lets try to recreate
Comment 4 wes hayutin 2011-07-12 18:12:55 UTC 
removing from tracker
Comment 5 Dave Johnson 2011-07-14 17:50:50 UTC 
unable to reproduce, believe this was a result of disabling the iptables when configure script was failing to open up port 443 in iptables
Comment 6 wes hayutin 2011-08-01 19:59:56 UTC 
release pending...
Comment 7 wes hayutin 2011-08-01 20:00:19 UTC 
release pending.. 2
Comment 8 wes hayutin 2011-08-01 20:00:24 UTC 
release pending...
Comment 10 wes hayutin 2011-12-08 13:58:47 UTC 
perm close
Comment 11 wes hayutin 2011-12-08 14:01:06 UTC 
closing out old bugs