718126 – aeolus-image push throws exception

Bug 718126 - aeolus-image push throws exception

Summary: aeolus-image push throws exception

Keywords:
Status:	CLOSED CURRENTRELEASE
Alias:	None
Product:	CloudForms Cloud Engine
Classification:	Retired
Component:	rubygem-aeolus-image
Sub Component:
Version:	0.3.1
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	rc
Assignee:	Jason Guiditta
QA Contact:	wes hayutin
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2011-07-01 04:47 UTC by Dave Johnson
Modified:	2012-01-26 12:19 UTC (History)
CC List:	7 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2011-07-01 15:58:39 UTC

Attachments	(Terms of Use)
Add an attachment (proposed patch, testcase, etc.)

Description Dave Johnson 2011-07-01 04:47:13 UTC

I started seeing this earlier today.  Wanted to try again tonight and still getting the same results.  Assuming it is something that was just introduced as I have reproduced multiple times on multiple servers


Tail of /var/log/imagefactory.log at the end of build (showing completed) 
=========================================================================
2011-07-01 00:32:30,813 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14053) Message: Setting metadata ({'latest_unpushed': '9ec28dcc-6075-4394-8708-17a66559a77a'}) for http://localhost:9090/images/12fad38a-798f-4e71-817e-1b603d14dd03
2011-07-01 00:32:30,814 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14053) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from BUILDING to COMPLETED
^C


Running push command shows error 
============================================================
[root@ibm-x3650-04 ~]# aeolus-image push --provider rhevm --id 12fad38a-798f-4e71-817e-1b603d14dd03
/usr/lib/ruby/gems/1.8/gems/aeolus-cli-0.0.1/lib/push_command.rb:21:in `run': undefined method `each' for #<Qmf2::QmfAgentException:0x7f5663946090> (NoMethodError)
	from /usr/lib/ruby/gems/1.8/gems/aeolus-cli-0.0.1/lib/config_parser.rb:199:in `push'
	from /usr/lib/ruby/gems/1.8/gems/aeolus-cli-0.0.1/lib/config_parser.rb:30:in `send'
	from /usr/lib/ruby/gems/1.8/gems/aeolus-cli-0.0.1/lib/config_parser.rb:30:in `process'
	from /usr/lib/ruby/gems/1.8/gems/aeolus-cli-0.0.1/bin/aeolus-image:6
	from /usr/bin/aeolus-image:19:in `load'
	from /usr/bin/aeolus-image:19

Comment 1 wes hayutin 2011-07-01 15:58:39 UTC

this is working in

[root@hp-dl160g6-01 nodes]# rpm -qa | grep aeolus
rubygem-aeolus-cli-0.0.1-1.el6.20110630225932gitafa30be.noarch
aeolus-conductor-0.3.0-0.el6.20110630225932gitafa30be.noarch
aeolus-configure-2.0.1-0.el6.20110628141215gitb8aaf85.noarch
aeolus-conductor-doc-0.3.0-0.el6.20110630225932gitafa30be.noarch
aeolus-all-0.3.0-0.el6.20110630225932gitafa30be.noarch
aeolus-conductor-daemons-0.3.0-0.el6.20110630225932gitafa30be.noarch



==> /var/log/imagefactory.log <==
 addr = redhat.com:imagefactory:83c47401-9d76-4d7a-b958-99ad70a8680b:image_factory 
 subtypes = {} 
 userId = anonymous
2011-07-01 11:29:57,806 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Getting metadata (['latest_unpushed']) from http://localhost:9090/images/695e407a-34a0-4af7-a0a1-3f64d3c06262
2011-07-01 11:29:57,807 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Querying (http://localhost:9090/target_images/_query) with expression ($build == "2d28792c-82ad-4ed3-9a69-923d85eab3dc" && $target == "rhev-m")
2011-07-01 11:29:57,838 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Getting metadata (['template']) from http://localhost:9090/target_images/d7b1401b-e2a7-4f75-b2c3-d2a3beca8c9d
2011-07-01 11:29:57,840 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-01 11:29:57,896 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-01 11:29:57,898 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14960) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from NEW to PUSHING
2011-07-01 11:29:57,899 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14960) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 0 to 0



2011-07-01 11:39:20,047 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Getting metadata (('ami-id',)) from http://localhost:9090/target_images/d7b1401b-e2a7-4f75-b2c3-d2a3beca8c9d
2011-07-01 11:39:20,083 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Got metadata output of: {'ami-id': 'OK 243d082b-2c94-4184-acbb-ab609e6dc67f'}
2011-07-01 11:39:20,085 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Extracted RHEVM UUID: 243d082b-2c94-4184-acbb-ab609e6dc67f 
2011-07-01 11:39:20,093 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(14960) 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-01 11:39:20,134 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Setting metadata ({'target_image': 'd7b1401b-e2a7-4f75-b2c3-d2a3beca8c9d', 'uuid': '2792d47c-832d-4500-9b90-9fde1c2411f7', 'icicle': 'none', 'target_identifier': '243d082b-2c94-4184-acbb-ab609e6dc67f', 'object_type': 'provider_image', 'provider': 'rhevm'}) for http://localhost:9090/provider_images/2792d47c-832d-4500-9b90-9fde1c2411f7
2011-07-01 11:39:20,341 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14960) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 0 to 100
2011-07-01 11:39:20,342 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Setting metadata ({'latest_build': '2d28792c-82ad-4ed3-9a69-923d85eab3dc'}) for http://localhost:9090/images/695e407a-34a0-4af7-a0a1-3f64d3c06262
2011-07-01 11:39:20,344 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Setting metadata ({'latest_unpushed': None}) for http://localhost:9090/images/695e407a-34a0-4af7-a0a1-3f64d3c06262
2011-07-01 11:39:20,386 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14960) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from PUSHING to COMPLETED
q^C
[root@hp-dl160g6-01 nodes]# cat /var/log/imagefactory.log 
2011-07-01 06:45:43,286 INFO root pid(7082) Message: Launched as daemon...
2011-07-01 06:45:43,428 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(7082) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-01 06:45:43,429 INFO imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(7082) Message: image_factory has qmf/qpid address: redhat.com:imagefactory:5c04c234-7e81-44f5-bcda-ba8baa3c6649:image_factory
2011-07-01 06:46:44,440 WARNING root pid(7082) Message: caught signal SIGTERM, stopping...
2011-07-01 06:47:37,389 INFO root pid(9312) Message: Launched as daemon...
2011-07-01 06:47:37,536 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(9312) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-01 06:47:37,536 INFO imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(9312) Message: image_factory has qmf/qpid address: redhat.com:imagefactory:6920b3a7-0ad1-4466-911b-b557a5b7d431:image_factory
2011-07-01 11:09:55,508 WARNING root pid(9312) Message: caught signal SIGTERM, stopping...
2011-07-01 11:11:19,121 INFO root pid(14960) Message: Launched as daemon...
2011-07-01 11:11:19,271 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-01 11:11:19,271 INFO imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(14960) Message: image_factory has qmf/qpid address: redhat.com:imagefactory:83c47401-9d76-4d7a-b958-99ad70a8680b:image_factory
2011-07-01 11:13:55,974 DEBUG imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(14960) Message: Method called: name = build_image 
 args = {'image': '', 'build': '', 'template': '<template>\n<name>westest02</name>\n<description>westest02</description>\n<os>\n<name>Fedora</name>\n<arch>x86_64</arch>\n<version>14</version>\n<install type="url">\n<url>http://download.devel.redhat.com/released/F-14/GOLD/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\n\n', 'targets': ['rhev-m']} 
 handle = <cqmf2.AgentEvent; proxy of <Swig Object of type 'qmf::AgentEvent *' at 0x1da1570> > 
 addr = redhat.com:imagefactory:83c47401-9d76-4d7a-b958-99ad70a8680b:image_factory 
 subtypes = {} 
 userId = anonymous
2011-07-01 11:13:55,975 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-01 11:13:55,975 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-01 11:13:55,985 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(14960) 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-01 11:13:56,010 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Setting metadata ({'object_type': 'image', 'uuid': '695e407a-34a0-4af7-a0a1-3f64d3c06262'}) for http://localhost:9090/images/695e407a-34a0-4af7-a0a1-3f64d3c06262
2011-07-01 11:13:56,094 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(14960) 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-01 11:13:56,114 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Setting metadata ({'image': '695e407a-34a0-4af7-a0a1-3f64d3c06262', 'object_type': 'build', 'uuid': '2d28792c-82ad-4ed3-9a69-923d85eab3dc'}) for http://localhost:9090/builds/2d28792c-82ad-4ed3-9a69-923d85eab3dc
2011-07-01 11:13:56,238 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-01 11:13:56,250 DEBUG oz.Guest.FedoraGuest pid(14960) Message: libvirt bridge name is virbr0, host_bridge_ip is 192.168.122.1
2011-07-01 11:13:56,251 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Name: westest02, UUID: 7f61cd23-e0ca-4898-89bb-e0e71c1c4117
2011-07-01 11:13:56,251 DEBUG oz.Guest.FedoraGuest pid(14960) Message: MAC: 52:54:00:8f:58:10, distro: Fedora
2011-07-01 11:13:56,251 DEBUG oz.Guest.FedoraGuest pid(14960) Message: update: 14, arch: x86_64, diskimage: /var/tmp/westest02.dsk
2011-07-01 11:13:56,251 DEBUG oz.Guest.FedoraGuest pid(14960) Message: nicmodel: virtio, clockoffset: utc
2011-07-01 11:13:56,251 DEBUG oz.Guest.FedoraGuest pid(14960) Message: mousetype: ps2, disk_bus: virtio, disk_dev: vda
2011-07-01 11:13:56,251 DEBUG oz.Guest.FedoraGuest pid(14960) Message: icicletmp: /var/lib/oz/icicletmp/westest02, listen_port: 15946
2011-07-01 11:13:56,251 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Original ISO path: /var/lib/oz/isos/Fedora14x86_64-url.iso
2011-07-01 11:13:56,251 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Modified ISO cache: /var/lib/oz/isos/Fedora14x86_64-url-oz.iso
2011-07-01 11:13:56,252 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Output ISO path: /var/tmp/westest02-url-oz.iso
2011-07-01 11:13:56,252 DEBUG oz.Guest.FedoraGuest pid(14960) Message: ISO content path: /var/lib/oz/isocontent/westest02-url
2011-07-01 11:13:56,572 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Original URL http://download.devel.redhat.com/released/F-14/GOLD/Fedora/x86_64/os/ resolved to http://download.devel.redhat.com/released/F-14/GOLD/Fedora/x86_64/os/
2011-07-01 11:13:56,572 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: build_upload() called on FedoraBuilder...
2011-07-01 11:13:56,572 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Building for target rhev-m with warehouse config http://localhost:9090/
2011-07-01 11:13:56,572 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14960) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from NEW to BUILDING
2011-07-01 11:13:56,573 INFO oz.Guest.FedoraGuest pid(14960) Message: Cleaning up guest named westest02
2011-07-01 11:13:56,574 INFO oz.Guest.FedoraGuest pid(14960) Message: Generating install media
2011-07-01 11:13:56,576 INFO oz.Guest.FedoraGuest pid(14960) Message: Fetching the original media
2011-07-01 11:13:56,684 INFO oz.Guest.FedoraGuest pid(14960) Message: Fetching the original install media from http://download.devel.redhat.com/released/F-14/GOLD/Fedora/x86_64/os//images/boot.iso
2011-07-01 11:13:56,788 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 0kB of 225280kB
2011-07-01 11:13:59,188 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 10241kB of 225280kB
2011-07-01 11:14:02,941 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 20483kB of 225280kB
2011-07-01 11:14:07,325 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 30720kB of 225280kB
2011-07-01 11:14:24,646 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 40962kB of 225280kB
2011-07-01 11:14:30,794 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 51203kB of 225280kB
2011-07-01 11:14:37,003 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 61441kB of 225280kB
2011-07-01 11:14:39,652 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 71682kB of 225280kB
2011-07-01 11:14:43,627 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 81922kB of 225280kB
2011-07-01 11:14:47,392 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 92162kB of 225280kB
2011-07-01 11:14:52,092 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 102400kB of 225280kB
2011-07-01 11:14:55,337 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 112640kB of 225280kB
2011-07-01 11:14:57,117 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 122882kB of 225280kB
2011-07-01 11:15:00,089 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 133127kB of 225280kB
2011-07-01 11:15:09,086 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 143360kB of 225280kB
2011-07-01 11:15:11,357 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 153603kB of 225280kB
2011-07-01 11:15:14,462 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 163841kB of 225280kB
2011-07-01 11:15:17,249 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 174080kB of 225280kB
2011-07-01 11:15:20,038 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 184321kB of 225280kB
2011-07-01 11:15:22,147 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 194560kB of 225280kB
2011-07-01 11:15:23,792 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 204802kB of 225280kB
2011-07-01 11:15:25,530 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 215040kB of 225280kB
2011-07-01 11:15:27,505 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 225280kB of 225280kB
2011-07-01 11:15:27,505 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 225280kB of 225280kB
2011-07-01 11:15:27,505 DEBUG oz.Guest.FedoraGuest pid(14960) Message: 225280kB of 225280kB
2011-07-01 11:15:27,505 INFO oz.Guest.FedoraGuest pid(14960) Message: Copying ISO contents for modification
2011-07-01 11:15:27,506 INFO oz.Guest.FedoraGuest pid(14960) Message: Setting up guestfs handle for westest02
2011-07-01 11:15:27,507 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Adding ISO image /var/lib/oz/isos/Fedora14x86_64-url.iso
2011-07-01 11:15:27,507 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Launching guestfs
2011-07-01 11:15:42,863 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Mounting ISO
2011-07-01 11:15:42,877 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Checking if there is enough space on the filesystem
2011-07-01 11:15:42,882 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Extracting ISO contents
2011-07-01 11:15:45,294 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Putting the kickstart in place
2011-07-01 11:15:45,295 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Modifying the boot options
2011-07-01 11:15:45,296 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Generating new ISO
2011-07-01 11:15:45,605 INFO oz.Guest.FedoraGuest pid(14960) Message: Cleaning up old ISO data
2011-07-01 11:15:51,469 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14960) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 0 to 10
2011-07-01 11:15:51,470 INFO oz.Guest.FedoraGuest pid(14960) Message: Generating 10GB diskimage for westest02
2011-07-01 11:15:51,470 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Doing base install via Oz
2011-07-01 11:15:51,470 INFO oz.Guest.FedoraGuest pid(14960) Message: Running install for westest02
2011-07-01 11:15:51,470 INFO oz.Guest.FedoraGuest pid(14960) Message: Generate XML for guest westest02 with bootdev cdrom
2011-07-01 11:15:51,471 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Generated XML:
<?xml version="1.0"?>
<domain type="kvm">
  <name>westest02</name>
  <memory>1048576</memory>
  <currentMemory>1048576</currentMemory>
  <uuid>7f61cd23-e0ca-4898-89bb-e0e71c1c4117</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:8f:58:10"/>
      <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-d7b1401b-e2a7-4f75-b2c3-d2a3beca8c9d.dsk"/>
    </disk>
    <disk type="file" device="cdrom">
      <source file="/var/tmp/westest02-url-oz.iso"/>
      <target dev="hdc"/>
    </disk>
  </devices>
</domain>

2011-07-01 11:15:51,941 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3600/3600
2011-07-01 11:16:01,972 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3590/3600
2011-07-01 11:16:12,005 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3580/3600
2011-07-01 11:16:22,035 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3570/3600
2011-07-01 11:16:32,176 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3560/3600
2011-07-01 11:16:42,207 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3550/3600
2011-07-01 11:16:52,238 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3540/3600
2011-07-01 11:17:02,269 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3530/3600
2011-07-01 11:17:12,315 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3520/3600
2011-07-01 11:17:22,345 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3510/3600
2011-07-01 11:17:32,374 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3500/3600
2011-07-01 11:17:42,404 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3490/3600
2011-07-01 11:17:52,434 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3480/3600
2011-07-01 11:18:02,464 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3470/3600
2011-07-01 11:18:12,499 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3460/3600
2011-07-01 11:18:22,528 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3450/3600
2011-07-01 11:18:32,558 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3440/3600
2011-07-01 11:18:42,589 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3430/3600
2011-07-01 11:18:52,637 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3420/3600
2011-07-01 11:19:02,678 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3410/3600
2011-07-01 11:19:12,708 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3400/3600
2011-07-01 11:19:22,739 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3390/3600
2011-07-01 11:19:32,770 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3380/3600
2011-07-01 11:19:42,797 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3370/3600
2011-07-01 11:19:52,827 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3360/3600
2011-07-01 11:20:02,858 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3350/3600
2011-07-01 11:20:12,889 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3340/3600
2011-07-01 11:20:22,916 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3330/3600
2011-07-01 11:20:32,944 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3320/3600
2011-07-01 11:20:42,974 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3310/3600
2011-07-01 11:20:53,005 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3300/3600
2011-07-01 11:21:03,038 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3290/3600
2011-07-01 11:21:13,067 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3280/3600
2011-07-01 11:21:23,096 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3270/3600
2011-07-01 11:21:33,127 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3260/3600
2011-07-01 11:21:43,156 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3250/3600
2011-07-01 11:21:53,186 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3240/3600
2011-07-01 11:22:03,215 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3230/3600
2011-07-01 11:22:13,246 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3220/3600
2011-07-01 11:22:23,274 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3210/3600
2011-07-01 11:22:33,303 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3200/3600
2011-07-01 11:22:43,333 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to finish installing, 3190/3600
2011-07-01 11:22:47,346 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Libvirt Domain Info Failed:
2011-07-01 11:22:47,346 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  code is 42
2011-07-01 11:22:47,347 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  domain is 10
2011-07-01 11:22:47,347 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  message is Domain not found: no domain with matching uuid '7f61cd23-e0ca-4898-89bb-e0e71c1c4117'
2011-07-01 11:22:47,347 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  level is 2
2011-07-01 11:22:47,347 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  str1 is Domain not found: %s
2011-07-01 11:22:47,347 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  str2 is no domain with matching uuid '7f61cd23-e0ca-4898-89bb-e0e71c1c4117'
2011-07-01 11:22:47,347 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  str3 is None
2011-07-01 11:22:47,347 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  int1 is -1
2011-07-01 11:22:47,348 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  int2 is -1
2011-07-01 11:22:47,348 INFO oz.Guest.FedoraGuest pid(14960) Message: Install of westest02 succeeded
2011-07-01 11:22:47,348 INFO oz.Guest.FedoraGuest pid(14960) Message: Generate XML for guest westest02 with bootdev hd
2011-07-01 11:22:47,365 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Generated XML:
<?xml version="1.0"?>
<domain type="kvm">
  <name>westest02</name>
  <memory>1048576</memory>
  <currentMemory>1048576</currentMemory>
  <uuid>7f61cd23-e0ca-4898-89bb-e0e71c1c4117</uuid>
  <clock offset="utc"/>
  <vcpu>1</vcpu>
  <features>
    <acpi/>
    <apic/>
    <pae/>
  </features>
  <os>
    <type>hvm</type>
    <boot dev="hd"/>
  </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:8f:58:10"/>
      <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-d7b1401b-e2a7-4f75-b2c3-d2a3beca8c9d.dsk"/>
    </disk>
  </devices>
</domain>

2011-07-01 11:22:47,379 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Base install complete - Doing customization
2011-07-01 11:22:47,380 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14960) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 10 to 30
2011-07-01 11:22:47,380 INFO oz.Guest.FedoraGuest pid(14960) Message: Customizing image
2011-07-01 11:22:47,380 INFO oz.Guest.FedoraGuest pid(14960) Message: No additional packages or files to install, skipping customization
2011-07-01 11:22:47,380 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Customization complete
2011-07-01 11:22:47,381 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14960) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 30 to 50
2011-07-01 11:22:47,381 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Generating ICICLE
2011-07-01 11:22:47,381 INFO oz.Guest.FedoraGuest pid(14960) Message: Generating ICICLE
2011-07-01 11:22:47,381 INFO oz.Guest.FedoraGuest pid(14960) Message: Collection Setup
2011-07-01 11:22:47,383 INFO oz.Guest.FedoraGuest pid(14960) Message: Setting up guestfs handle for westest02
2011-07-01 11:22:47,383 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Adding disk image /var/tmp/base-image-d7b1401b-e2a7-4f75-b2c3-d2a3beca8c9d.dsk
2011-07-01 11:22:47,383 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Launching guestfs
2011-07-01 11:22:50,099 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Inspecting guest OS
2011-07-01 11:22:51,886 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Getting mountpoints
2011-07-01 11:22:51,887 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Root device: /dev/VolGroup00/LogVol00
2011-07-01 11:22:52,169 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Step 1: Uploading ssh keys
2011-07-01 11:22:52,196 INFO oz.Guest.FedoraGuest pid(14960) Message: Generating new openssh key
2011-07-01 11:22:52,206 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Step 2: setup sshd
2011-07-01 11:22:52,327 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Step 3: Open up the firewall
2011-07-01 11:22:52,336 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Step 4: Guest announcement
2011-07-01 11:22:52,376 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Step 5: Set SELinux to permissive mode
2011-07-01 11:22:52,412 INFO oz.Guest.FedoraGuest pid(14960) Message: Cleaning up guestfs handle for westest02
2011-07-01 11:22:52,412 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Syncing
2011-07-01 11:22:52,720 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Unmounting all
2011-07-01 11:22:52,771 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Killing guestfs subprocess
2011-07-01 11:22:53,284 INFO oz.Guest.FedoraGuest pid(14960) Message: Waiting for guest westest02 to boot
2011-07-01 11:22:53,311 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for guest westest02 to boot, 300/300
2011-07-01 11:23:03,319 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for guest westest02 to boot, 290/300
2011-07-01 11:23:13,321 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for guest westest02 to boot, 280/300
2011-07-01 11:23:23,332 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for guest westest02 to boot, 270/300
2011-07-01 11:23:33,340 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for guest westest02 to boot, 260/300
2011-07-01 11:23:43,349 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for guest westest02 to boot, 250/300
2011-07-01 11:23:53,354 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for guest westest02 to boot, 240/300
2011-07-01 11:24:02,362 DEBUG oz.Guest.FedoraGuest pid(14960) Message: IP address of guest is 192.168.122.58
2011-07-01 11:24:03,350 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Waiting for westest02 to shutdown, 60/60
2011-07-01 11:24:10,365 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Libvirt Domain Info Failed:
2011-07-01 11:24:10,366 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  code is 42
2011-07-01 11:24:10,366 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  domain is 10
2011-07-01 11:24:10,366 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  message is Domain not found: no domain with matching uuid '7f61cd23-e0ca-4898-89bb-e0e71c1c4117'
2011-07-01 11:24:10,366 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  level is 2
2011-07-01 11:24:10,366 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  str1 is Domain not found: %s
2011-07-01 11:24:10,366 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  str2 is no domain with matching uuid '7f61cd23-e0ca-4898-89bb-e0e71c1c4117'
2011-07-01 11:24:10,367 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  str3 is None
2011-07-01 11:24:10,367 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  int1 is -1
2011-07-01 11:24:10,367 DEBUG oz.Guest.FedoraGuest pid(14960) Message:  int2 is -1
2011-07-01 11:24:10,367 INFO oz.Guest.FedoraGuest pid(14960) Message: Collection Teardown
2011-07-01 11:24:10,368 INFO oz.Guest.FedoraGuest pid(14960) Message: Setting up guestfs handle for westest02
2011-07-01 11:24:10,368 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Adding disk image /var/tmp/base-image-d7b1401b-e2a7-4f75-b2c3-d2a3beca8c9d.dsk
2011-07-01 11:24:10,369 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Launching guestfs
2011-07-01 11:24:12,819 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Inspecting guest OS
2011-07-01 11:24:14,293 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Getting mountpoints
2011-07-01 11:24:14,293 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Root device: /dev/VolGroup00/LogVol00
2011-07-01 11:24:14,569 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Teardown step 1
2011-07-01 11:24:14,569 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Resetting authorized_keys
2011-07-01 11:24:14,595 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Teardown step 2
2011-07-01 11:24:14,595 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Resetting sshd_config
2011-07-01 11:24:14,635 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Resetting sshd service
2011-07-01 11:24:14,663 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Teardown step 3
2011-07-01 11:24:14,663 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Resetting iptables rules
2011-07-01 11:24:14,664 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Teardown step 4
2011-07-01 11:24:14,665 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Resetting announcement to host
2011-07-01 11:24:14,665 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Removing icicle-nc binary
2011-07-01 11:24:14,666 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Resetting crond service
2011-07-01 11:24:14,674 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Teardown step 5
2011-07-01 11:24:14,691 INFO oz.Guest.FedoraGuest pid(14960) Message: Cleaning up guestfs handle for westest02
2011-07-01 11:24:14,691 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Syncing
2011-07-01 11:24:14,862 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Unmounting all
2011-07-01 11:24:14,912 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Killing guestfs subprocess
2011-07-01 11:24:14,986 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: ICICLE generation complete
2011-07-01 11:24:14,986 INFO oz.Guest.FedoraGuest pid(14960) Message: Cleaning up after install
2011-07-01 11:24:14,987 DEBUG oz.Guest.FedoraGuest pid(14960) Message: Removing modified ISO
2011-07-01 11:24:15,025 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Generated disk image (/var/tmp/base-image-d7b1401b-e2a7-4f75-b2c3-d2a3beca8c9d.dsk)
2011-07-01 11:24:15,026 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Adding cloud-info to local image
2011-07-01 11:24:15,026 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: init guestfs
2011-07-01 11:24:15,026 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: add input image
2011-07-01 11:24:15,026 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: launch guestfs
2011-07-01 11:24:17,760 INFO imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Creating cloud-info file indicating target (rhev-m)
2011-07-01 11:24:17,764 INFO imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Updating rc.local with Audrey conditional
2011-07-01 11:24:18,432 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Storing Fedora image at http://localhost:9090/...
2011-07-01 11:24:18,620 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(14960) 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-01 11:24:18,669 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Setting metadata ({'object_type': 'template', 'uuid': 'f8a7dd46-3d4b-4fd4-8f05-da6670c15cb5'}) for http://localhost:9090/templates/f8a7dd46-3d4b-4fd4-8f05-da6670c15cb5
2011-07-01 11:24:18,713 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(14960) 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-01 11:24:18,735 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Setting metadata ({'object_type': 'icicle', 'uuid': '667d5382-18cd-4136-a545-b3be4829aef5'}) for http://localhost:9090/icicles/667d5382-18cd-4136-a545-b3be4829aef5
2011-07-01 11:24:18,819 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(14960) 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-01 11:26:13,793 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Setting metadata ({'icicle': '667d5382-18cd-4136-a545-b3be4829aef5', 'uuid': 'd7b1401b-e2a7-4f75-b2c3-d2a3beca8c9d', 'template': 'f8a7dd46-3d4b-4fd4-8f05-da6670c15cb5', 'target_parameters': '<?xml version="1.0"?>\n<domain type="kvm">\n  <name>westest02</name>\n  <memory>1048576</memory>\n  <currentMemory>1048576</currentMemory>\n  <uuid>7f61cd23-e0ca-4898-89bb-e0e71c1c4117</uuid>\n  <clock offset="utc"/>\n  <vcpu>1</vcpu>\n  <features>\n    <acpi/>\n    <apic/>\n    <pae/>\n  </features>\n  <os>\n    <type>hvm</type>\n    <boot dev="hd"/>\n  </os>\n  <on_poweroff>destroy</on_poweroff>\n  <on_reboot>destroy</on_reboot>\n  <on_crash>destroy</on_crash>\n  <devices>\n    <console device="pty"/>\n    <graphics port="-1" type="vnc"/>\n    <interface type="bridge">\n      <source bridge="virbr0"/>\n      <mac address="52:54:00:8f:58:10"/>\n      <model type="virtio"/>\n    </interface>\n    <input bus="ps2" type="mouse"/>\n    <console type="pty">\n      <target port="0"/>\n    </console>\n    <disk device="disk" type="file">\n      <target dev="vda" bus="virtio"/>\n      <source file="/var/tmp/base-image-d7b1401b-e2a7-4f75-b2c3-d2a3beca8c9d.dsk"/>\n    </disk>\n  </devices>\n</domain>\n', 'object_type': 'target_image', 'target': 'rhev-m', 'build': '2d28792c-82ad-4ed3-9a69-923d85eab3dc'}) for http://localhost:9090/target_images/d7b1401b-e2a7-4f75-b2c3-d2a3beca8c9d
2011-07-01 11:26:14,042 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Image warehouse storage complete
2011-07-01 11:26:14,042 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14960) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 50 to 100
2011-07-01 11:26:14,043 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Getting metadata (['latest_unpushed']) from http://localhost:9090/images/695e407a-34a0-4af7-a0a1-3f64d3c06262
2011-07-01 11:26:14,044 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Getting metadata (['latest_build']) from http://localhost:9090/images/695e407a-34a0-4af7-a0a1-3f64d3c06262
2011-07-01 11:26:14,046 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Setting metadata ({'latest_unpushed': '2d28792c-82ad-4ed3-9a69-923d85eab3dc'}) for http://localhost:9090/images/695e407a-34a0-4af7-a0a1-3f64d3c06262
2011-07-01 11:26:14,048 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14960) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from BUILDING to COMPLETED
2011-07-01 11:29:57,805 DEBUG imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(14960) Message: Method called: name = push_image 
 args = {'credentials': '<provider_accounts>\n<provider_account>\n<name>rhevmTest01</name>\n<provider>rhevm</provider>\n<provider_type>rhev-m</provider_type>\n<provider_credentials>\n  <rhev-m_credentials>\n    <password>100yard-</password>\n    <username>rhev.eng.bos.redhat.com</username>\n  </rhev-m_credentials>\n</provider_credentials>\n</provider_account>\n</provider_accounts>\n', 'image': '695e407a-34a0-4af7-a0a1-3f64d3c06262', 'build': '', 'providers': ['rhevm']} 
 handle = <cqmf2.AgentEvent; proxy of <Swig Object of type 'qmf::AgentEvent *' at 0x1da1570> > 
 addr = redhat.com:imagefactory:83c47401-9d76-4d7a-b958-99ad70a8680b:image_factory 
 subtypes = {} 
 userId = anonymous
2011-07-01 11:29:57,806 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Getting metadata (['latest_unpushed']) from http://localhost:9090/images/695e407a-34a0-4af7-a0a1-3f64d3c06262
2011-07-01 11:29:57,807 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Querying (http://localhost:9090/target_images/_query) with expression ($build == "2d28792c-82ad-4ed3-9a69-923d85eab3dc" && $target == "rhev-m")
2011-07-01 11:29:57,838 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Getting metadata (['template']) from http://localhost:9090/target_images/d7b1401b-e2a7-4f75-b2c3-d2a3beca8c9d
2011-07-01 11:29:57,840 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-01 11:29:57,896 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-01 11:29:57,898 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14960) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from NEW to PUSHING
2011-07-01 11:29:57,899 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14960) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 0 to 0
2011-07-01 11:39:20,047 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Getting metadata (('ami-id',)) from http://localhost:9090/target_images/d7b1401b-e2a7-4f75-b2c3-d2a3beca8c9d
2011-07-01 11:39:20,083 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Got metadata output of: {'ami-id': 'OK 243d082b-2c94-4184-acbb-ab609e6dc67f'}
2011-07-01 11:39:20,085 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(14960) Message: Extracted RHEVM UUID: 243d082b-2c94-4184-acbb-ab609e6dc67f 
2011-07-01 11:39:20,093 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(14960) 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-01 11:39:20,134 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Setting metadata ({'target_image': 'd7b1401b-e2a7-4f75-b2c3-d2a3beca8c9d', 'uuid': '2792d47c-832d-4500-9b90-9fde1c2411f7', 'icicle': 'none', 'target_identifier': '243d082b-2c94-4184-acbb-ab609e6dc67f', 'object_type': 'provider_image', 'provider': 'rhevm'}) for http://localhost:9090/provider_images/2792d47c-832d-4500-9b90-9fde1c2411f7
2011-07-01 11:39:20,341 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14960) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 0 to 100
2011-07-01 11:39:20,342 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Setting metadata ({'latest_build': '2d28792c-82ad-4ed3-9a69-923d85eab3dc'}) for http://localhost:9090/images/695e407a-34a0-4af7-a0a1-3f64d3c06262
2011-07-01 11:39:20,344 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(14960) Message: Setting metadata ({'latest_unpushed': None}) for http://localhost:9090/images/695e407a-34a0-4af7-a0a1-3f64d3c06262
2011-07-01 11:39:20,386 DEBUG imagefactory.BuildJob.BuildAdaptor pid(14960) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from PUSHING to COMPLETED
[root@hp-dl160g6-01 nodes]#

Comment 2 wes hayutin 2011-12-08 14:12:34 UTC

perm close

Note You need to log in before you can comment on or make changes to this bug.