Bug 719450

Summary: vmware push: fails w/ "TypeNotFound: Type not found: 'resPoolEntity'"
Product: [Retired] CloudForms Cloud Engine Reporter: wes hayutin <whayutin>
Component: iwhdAssignee: Ian McLeod <imcleod>
Status: CLOSED CURRENTRELEASE QA Contact: wes hayutin <whayutin>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 0.3.1CC: akarol, dajohnso, deltacloud-maint, ssachdev, zaitcev
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-07-07 17:38:35 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description wes hayutin 2011-07-06 21:56:40 UTC 
Description of problem:
[root@dell-pe2950-01 ~]# cat /etc/vmware.json
{"vmware": {"api-url": "https://10.16.120.136/sdk",
    "username": "Administrator", "password": "snip!",
    "datastore": "datastore1", "network_name": "VM Network" } }
 
https://10.16.120.136/ui/#
 
 
 
[root@dell-pe2950-01 yum.repos.d]# echo $API_PROVIDER
10.16.120.136
[root@dell-pe2950-01 yum.repos.d]# deltacloudd  -i vsphere -r $HOSTNAME -p 3006 -t 500 -e production
Starting Deltacloud API :: vsphere :: 10.16.120.136 :: http://dell-pe2950-01.rhts.eng.bos.redhat.com:3006/api
 
>> Thin web server (v1.2.5 codename This Is Not A Web Server)
>> Debugging ON
>> Maximum connections set to 1024
>> Listening on dell-pe2950-01.rhts.eng.bos.redhat.com:3006, CTRL+C to stop

2011-07-06 17:28:37,237 DEBUG imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(30644) Message: Method called: name = push_image
 args = {'credentials': '<provider_accounts>\n<provider_account>\n<name>wes_vmware</name>\n<provider>vmware</provider>\n<provider_type>vmware</provider_type>\n<provider_credentials>\n  <vmware_credentials>\n    <password>R3dhat!</password>\n    <username>Administrator</username>\n  </vmware_credentials>\n</provider_credentials>\n</provider_account>\n</provider_accounts>\n', 'image': '2dfe86ed-08c0-4d70-819b-cab448625c0c', 'build': '', 'providers': ['vmware']}
 handle = <cqmf2.AgentEvent; proxy of <Swig Object of type 'qmf::AgentEvent *' at 0x2d3d480> >
 addr = redhat.com:imagefactory:320c00ad-1027-415d-8a41-a3bb9a6d26bf:image_factory
 subtypes = {}
 userId = anonymous
2011-07-06 17:28:37,238 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(30644) Message: Getting metadata (['latest_unpushed']) from http://localhost:9090/images/2dfe86ed-08c0-4d70-819b-cab448625c0c
2011-07-06 17:28:37,245 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(30644) Message: Querying (http://localhost:9090/target_images/_query) with expression ($build == "da2ffe35-da28-4b1c-948f-c98087f1aefd" && $target == "vmware")
2011-07-06 17:28:37,249 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(30644) Message: Getting metadata (['template']) from http://localhost:9090/target_images/b8f539b9-7523-4cae-bdb4-0b251497cb97
2011-07-06 17:28:37,251 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(30644) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-06 17:28:37,255 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(30644) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-06 17:28:37,257 DEBUG imagefactory.BuildJob.BuildAdaptor pid(30644) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from NEW to PUSHING
2011-07-06 17:28:37,259 DEBUG imagefactory.BuildJob.BuildAdaptor pid(30644) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 0 to 0
2011-07-06 17:28:37,260 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(30644) Message: Image file /var/tmp/vmware-image-b8f539b9-7523-4cae-bdb4-0b251497cb97.vmdk already present - skipping warehouse download
2011-07-06 17:28:47,447 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(30644) Message: Exception caught in ImageFactory
2011-07-06 17:28:47,448 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(30644) Message: Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/imagefactory/builders/FedoraBuilder.py", line 975, in push_image_upload
    self.vmware_push_image_upload(target_image_id, provider, credentials)
  File "/usr/lib/python2.7/site-packages/imagefactory/builders/FedoraBuilder.py", line 908, in vmware_push_image_upload
    guest_id='otherLinux64Guest', imagefilename=input_image)
  File "/usr/lib/python2.7/site-packages/imagefactory/VMWare.py", line 170, in import_vm
    lease_mo_ref = self.vim.invoke('ImportVApp', _this=resource_pool, spec = importspec, folder = dc.vmFolder)
  File "/usr/lib/python2.7/site-packages/psphere/vim25.py", line 54, in invoke
    result = self.vsoap.invoke(method, _this=_this, **kwargs)
  File "/usr/lib/python2.7/site-packages/psphere/soap.py", line 45, in invoke
    result = getattr(self.client.service, method)(**kwargs)
  File "/usr/lib/python2.7/site-packages/suds/client.py", line 542, in __call__
    return client.invoke(args, kwargs)
  File "/usr/lib/python2.7/site-packages/suds/client.py", line 595, in invoke
    soapenv = binding.get_message(self.method, args, kwargs)
  File "/usr/lib/python2.7/site-packages/suds/bindings/binding.py", line 120, in get_message
    content = self.bodycontent(method, args, kwargs)
  File "/usr/lib/python2.7/site-packages/suds/bindings/document.py", line 63, in bodycontent
    p = self.mkparam(method, pd, value)
  File "/usr/lib/python2.7/site-packages/suds/bindings/document.py", line 105, in mkparam
    return Binding.mkparam(self, method, pdef, object)
  File "/usr/lib/python2.7/site-packages/suds/bindings/binding.py", line 287, in mkparam
    return marshaller.process(content)
  File "/usr/lib/python2.7/site-packages/suds/mx/core.py", line 62, in process
    self.append(document, content)
  File "/usr/lib/python2.7/site-packages/suds/mx/core.py", line 75, in append
    self.appender.append(parent, content)
  File "/usr/lib/python2.7/site-packages/suds/mx/appender.py", line 102, in append
    appender.append(parent, content)
  File "/usr/lib/python2.7/site-packages/suds/mx/appender.py", line 243, in append
    Appender.append(self, child, cont)
  File "/usr/lib/python2.7/site-packages/suds/mx/appender.py", line 182, in append
    self.marshaller.append(parent, content)
  File "/usr/lib/python2.7/site-packages/suds/mx/core.py", line 74, in append
    if self.start(content):
  File "/usr/lib/python2.7/site-packages/suds/mx/literal.py", line 87, in start
    raise TypeNotFound(content.tag)
TypeNotFound: Type not found: 'resPoolEntity'
 
2011-07-06 17:28:47,449 DEBUG imagefactory.BuildJob.BuildAdaptor pid(30644) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from PUSHING to FAILED
2011-07-06 17:28:47,449 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(30644) Message: Exception caught in ImageFactory
2011-07-06 17:28:47,450 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(30644) Message: Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/imagefactory/builders/FedoraBuilder.py", line 482, in push_image
    self.push_image_upload(target_image_id, provider, credentials)
  File "/usr/lib/python2.7/site-packages/imagefactory/builders/FedoraBuilder.py", line 975, in push_image_upload
    self.vmware_push_image_upload(target_image_id, provider, credentials)
  File "/usr/lib/python2.7/site-packages/imagefactory/builders/FedoraBuilder.py", line 908, in vmware_push_image_upload
    guest_id='otherLinux64Guest', imagefilename=input_image)
  File "/usr/lib/python2.7/site-packages/imagefactory/VMWare.py", line 170, in import_vm
    lease_mo_ref = self.vim.invoke('ImportVApp', _this=resource_pool, spec = importspec, folder = dc.vmFolder)
  File "/usr/lib/python2.7/site-packages/psphere/vim25.py", line 54, in invoke
    result = self.vsoap.invoke(method, _this=_this, **kwargs)
  File "/usr/lib/python2.7/site-packages/psphere/soap.py", line 45, in invoke
    result = getattr(self.client.service, method)(**kwargs)
  File "/usr/lib/python2.7/site-packages/suds/client.py", line 542, in __call__
    return client.invoke(args, kwargs)
  File "/usr/lib/python2.7/site-packages/suds/client.py", line 595, in invoke
    soapenv = binding.get_message(self.method, args, kwargs)
  File "/usr/lib/python2.7/site-packages/suds/bindings/binding.py", line 120, in get_message
    content = self.bodycontent(method, args, kwargs)
  File "/usr/lib/python2.7/site-packages/suds/bindings/document.py", line 63, in bodycontent
    p = self.mkparam(method, pd, value)
  File "/usr/lib/python2.7/site-packages/suds/bindings/document.py", line 105, in mkparam
    return Binding.mkparam(self, method, pdef, object)
  File "/usr/lib/python2.7/site-packages/suds/bindings/binding.py", line 287, in mkparam
    return marshaller.process(content)
  File "/usr/lib/python2.7/site-packages/suds/mx/core.py", line 62, in process
    self.append(document, content)
  File "/usr/lib/python2.7/site-packages/suds/mx/core.py", line 75, in append
    self.appender.append(parent, content)
  File "/usr/lib/python2.7/site-packages/suds/mx/appender.py", line 102, in append
    appender.append(parent, content)
  File "/usr/lib/python2.7/site-packages/suds/mx/appender.py", line 243, in append
    Appender.append(self, child, cont)
  File "/usr/lib/python2.7/site-packages/suds/mx/appender.py", line 182, in append
    self.marshaller.append(parent, content)
  File "/usr/lib/python2.7/site-packages/suds/mx/core.py", line 74, in append
    if self.start(content):
  File "/usr/lib/python2.7/site-packages/suds/mx/literal.py", line 87, in start
    raise TypeNotFound(content.tag)
TypeNotFound: Type not found: 'resPoolEntity'
 
2011-07-06 17:28:47,451 DEBUG imagefactory.BuildJob.BuildAdaptor pid(30644) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from FAILED to FAILED
Comment 1 wes hayutin 2011-07-07 00:15:25 UTC 
Ian create a resource pool on the vmware server.
Its visible on the vmware console under "Resource Allocation" 
its called "Test Pool imcleod"..

Tried a to push again.. I got the same trace back
011-07-06 20:05:56,952 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(30644) Message: Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/imagefactory/builders/FedoraBuilder.py", line 975, in push_image_upload
    self.vmware_push_image_upload(target_image_id, provider, credentials)
  File "/usr/lib/python2.7/site-packages/imagefactory/builders/FedoraBuilder.py", line 908, in vmware_push_image_upload
    guest_id='otherLinux64Guest', imagefilename=input_image)
  File "/usr/lib/python2.7/site-packages/imagefactory/VMWare.py", line 170, in import_vm
    lease_mo_ref = self.vim.invoke('ImportVApp', _this=resource_pool, spec = importspec, folder = dc.vmFolder)
  File "/usr/lib/python2.7/site-packages/psphere/vim25.py", line 54, in invoke
    result = self.vsoap.invoke(method, _this=_this, **kwargs)
  File "/usr/lib/python2.7/site-packages/psphere/soap.py", line 45, in invoke
    result = getattr(self.client.service, method)(**kwargs)
  File "/usr/lib/python2.7/site-packages/suds/client.py", line 542, in __call__
    return client.invoke(args, kwargs)
  File "/usr/lib/python2.7/site-packages/suds/client.py", line 595, in invoke
    soapenv = binding.get_message(self.method, args, kwargs)
  File "/usr/lib/python2.7/site-packages/suds/bindings/binding.py", line 120, in get_message
    content = self.bodycontent(method, args, kwargs)
  File "/usr/lib/python2.7/site-packages/suds/bindings/document.py", line 63, in bodycontent
    p = self.mkparam(method, pd, value)
  File "/usr/lib/python2.7/site-packages/suds/bindings/document.py", line 105, in mkparam
    return Binding.mkparam(self, method, pdef, object)
  File "/usr/lib/python2.7/site-packages/suds/bindings/binding.py", line 287, in mkparam
    return marshaller.process(content)
  File "/usr/lib/python2.7/site-packages/suds/mx/core.py", line 62, in process
    self.append(document, content)
  File "/usr/lib/python2.7/site-packages/suds/mx/core.py", line 75, in append
    self.appender.append(parent, content)
  File "/usr/lib/python2.7/site-packages/suds/mx/appender.py", line 102, in append
    appender.append(parent, content)
  File "/usr/lib/python2.7/site-packages/suds/mx/appender.py", line 243, in append
    Appender.append(self, child, cont)
  File "/usr/lib/python2.7/site-packages/suds/mx/appender.py", line 182, in append
    self.marshaller.append(parent, content)
  File "/usr/lib/python2.7/site-packages/suds/mx/core.py", line 74, in append
    if self.start(content):
  File "/usr/lib/python2.7/site-packages/suds/mx/literal.py", line 87, in start
    raise TypeNotFound(content.tag)
TypeNotFound: Type not found: 'resPoolEntity'
Comment 2 wes hayutin 2011-07-07 00:15:59 UTC 
I am going to try to rebuild a new image and then push
Comment 3 wes hayutin 2011-07-07 00:18:03 UTC 
Actually during the push I am seeing *NO* calls to deltacloud.. so I'm not convinced its a problem w/ the vmware server.


[root@dell-pe2950-01 ~]# /usr/bin/ruby /usr/bin/deltacloudd -i vsphere -r dell-pe2950-01.rhts.eng.bos.redhat.com -p 3006 -t 500 -e production
Starting Deltacloud API :: vsphere :: 10.16.120.136 :: http://dell-pe2950-01.rhts.eng.bos.redhat.com:3006/api

>> Thin web server (v1.2.5 codename This Is Not A Web Server)
>> Debugging ON
>> Maximum connections set to 1024
>> Listening on dell-pe2950-01.rhts.eng.bos.redhat.com:3006, CTRL+C to stop


It has to be some sort of setting or configuration on my conductor server.
Comment 4 wes hayutin 2011-07-07 01:16:12 UTC 
I noticed in the vmware setup page on the wiki.. there is a requirement for ...
"You should mark at least 1 Virtual Machine3 as a Template in order to be able to clone it"

Trying that on the vmware console.. omg this vmware setup sucks.. its soo slow
Comment 5 wes hayutin 2011-07-07 17:38:35 UTC 
ok.. I do not get this error when I run w/ 

{"westford_esx": {"api-url": "https://vsphere.virt.bos.redhat.com/sdk",
 "datastore": "datastore1", "network_name": "VM Network", "username":"Administrator", "password":"SNIP" } }


This must be vmware config... Ian has volunteered to help gather some requirements for how vmware should be configured.

closing this bug.. will open a doc bug.
Comment 6 wes hayutin 2011-07-07 17:39:33 UTC 
011-07-07 12:24:38,809 INFO root pid(11191) Message: Launched as daemon...
2011-07-07 12:24:38,953 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-07 12:24:38,954 INFO imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(11191) Message: image_factory has qmf/qpid address: redhat.com:imagefactory:5d7f70e3-9633-4eae-b716-75e3106e2c11:image_factory
2011-07-07 12:32:14,446 DEBUG imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(11191) Message: Method called: name = build_image 
 args = {'image': '', 'build': '', 'template': '<template>\n<name>tmpl1</name>\n<description>foo</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\n\n', 'targets': ['vmware']} 
 handle = <cqmf2.AgentEvent; proxy of <Swig Object of type 'qmf::AgentEvent *' at 0x21cecc0> > 
 addr = redhat.com:imagefactory:5d7f70e3-9633-4eae-b716-75e3106e2c11:image_factory 
 subtypes = {} 
 userId = anonymous
2011-07-07 12:32:14,447 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-07 12:32:14,448 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-07 12:32:14,467 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Setting metadata ({'object_type': 'image', 'uuid': '5e9a8be3-dada-4d5c-b9ef-e9f023b68c00'}) for http://localhost:9090/images/5e9a8be3-dada-4d5c-b9ef-e9f023b68c00
2011-07-07 12:32:14,553 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Setting metadata ({'image': '5e9a8be3-dada-4d5c-b9ef-e9f023b68c00', 'object_type': 'build', 'uuid': 'ed73308d-d026-4052-af9d-3dc936d29ba3'}) for http://localhost:9090/builds/ed73308d-d026-4052-af9d-3dc936d29ba3
2011-07-07 12:32:14,677 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-07 12:32:14,703 DEBUG oz.Guest.FedoraGuest pid(11191) Message: libvirt bridge name is virbr0, host_bridge_ip is 192.168.122.1
2011-07-07 12:32:14,703 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Name: tmpl1, UUID: f6117f12-ab09-4693-aa93-a54d0ea8012b
2011-07-07 12:32:14,703 DEBUG oz.Guest.FedoraGuest pid(11191) Message: MAC: 52:54:00:d6:e7:9a, distro: Fedora
2011-07-07 12:32:14,703 DEBUG oz.Guest.FedoraGuest pid(11191) Message: update: 14, arch: x86_64, diskimage: /var/tmp/tmpl1.dsk
2011-07-07 12:32:14,704 DEBUG oz.Guest.FedoraGuest pid(11191) Message: nicmodel: virtio, clockoffset: utc
2011-07-07 12:32:14,704 DEBUG oz.Guest.FedoraGuest pid(11191) Message: mousetype: ps2, disk_bus: virtio, disk_dev: vda
2011-07-07 12:32:14,704 DEBUG oz.Guest.FedoraGuest pid(11191) Message: icicletmp: /var/lib/oz/icicletmp/tmpl1, listen_port: 57322
2011-07-07 12:32:14,704 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Original ISO path: /var/lib/oz/isos/Fedora14x86_64-url.iso
2011-07-07 12:32:14,704 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Modified ISO cache: /var/lib/oz/isos/Fedora14x86_64-url-oz.iso
2011-07-07 12:32:14,704 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Output ISO path: /var/tmp/tmpl1-url-oz.iso
2011-07-07 12:32:14,705 DEBUG oz.Guest.FedoraGuest pid(11191) Message: ISO content path: /var/lib/oz/isocontent/tmpl1-url
2011-07-07 12:32:15,068 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Original URL http://download.fedoraproject.org/pub/fedora/linux/releases/14/Fedora/x86_64/os/ resolved to http://download.fedora.devel.redhat.com/pub/fedora/linux/releases/14/Fedora/x86_64/os/
2011-07-07 12:32:15,068 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: build_upload() called on FedoraBuilder...
2011-07-07 12:32:15,068 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: Building for target vmware with warehouse config http://localhost:9090/
2011-07-07 12:32:15,068 DEBUG imagefactory.BuildJob.BuildAdaptor pid(11191) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from NEW to BUILDING
2011-07-07 12:32:15,069 INFO oz.Guest.FedoraGuest pid(11191) Message: Cleaning up guest named tmpl1
2011-07-07 12:32:15,071 INFO oz.Guest.FedoraGuest pid(11191) Message: Generating install media
2011-07-07 12:32:15,072 INFO oz.Guest.FedoraGuest pid(11191) Message: Fetching the original media
2011-07-07 12:32:15,847 INFO oz.Guest.FedoraGuest pid(11191) Message: Fetching the original install media from ftp://gromit.redhat.com//pub/fedora/linux/releases/14/Fedora/x86_64/os//images/boot.iso
2011-07-07 12:32:16,364 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 0kB of 225280kB
2011-07-07 12:32:19,655 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 10241kB of 225280kB
2011-07-07 12:32:22,795 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 20481kB of 225280kB
2011-07-07 12:32:25,943 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 30720kB of 225280kB
2011-07-07 12:32:29,077 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 40962kB of 225280kB
2011-07-07 12:32:32,265 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 51200kB of 225280kB
2011-07-07 12:32:35,376 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 61441kB of 225280kB
2011-07-07 12:32:38,519 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 71680kB of 225280kB
2011-07-07 12:32:41,641 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 81920kB of 225280kB
2011-07-07 12:32:44,804 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 92161kB of 225280kB
2011-07-07 12:32:47,976 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 102400kB of 225280kB
2011-07-07 12:32:51,134 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 112640kB of 225280kB
2011-07-07 12:32:54,267 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 122880kB of 225280kB
2011-07-07 12:32:57,457 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 133120kB of 225280kB
2011-07-07 12:33:00,614 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 143360kB of 225280kB
2011-07-07 12:33:03,884 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 153601kB of 225280kB
2011-07-07 12:33:07,056 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 163840kB of 225280kB
2011-07-07 12:33:10,209 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 174080kB of 225280kB
2011-07-07 12:33:13,460 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 184320kB of 225280kB
2011-07-07 12:33:16,633 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 194560kB of 225280kB
2011-07-07 12:33:19,884 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 204800kB of 225280kB
2011-07-07 12:33:23,179 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 215040kB of 225280kB
2011-07-07 12:33:26,431 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 225280kB of 225280kB
2011-07-07 12:33:26,431 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 225280kB of 225280kB
2011-07-07 12:33:26,431 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 225280kB of 225280kB
2011-07-07 12:33:26,431 DEBUG oz.Guest.FedoraGuest pid(11191) Message: 225280kB of 225280kB
2011-07-07 12:33:26,454 INFO oz.Guest.FedoraGuest pid(11191) Message: Copying ISO contents for modification
2011-07-07 12:33:26,456 INFO oz.Guest.FedoraGuest pid(11191) Message: Setting up guestfs handle for tmpl1
2011-07-07 12:33:26,456 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Adding ISO image /var/lib/oz/isos/Fedora14x86_64-url.iso
2011-07-07 12:33:26,456 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Launching guestfs
2011-07-07 12:33:40,435 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Mounting ISO
2011-07-07 12:33:40,447 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Checking if there is enough space on the filesystem
2011-07-07 12:33:40,449 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Extracting ISO contents
2011-07-07 12:33:42,357 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Putting the kickstart in place
2011-07-07 12:33:42,358 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Modifying the boot options
2011-07-07 12:33:42,359 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Generating new ISO
2011-07-07 12:33:42,622 INFO oz.Guest.FedoraGuest pid(11191) Message: Cleaning up old ISO data
2011-07-07 12:33:42,672 DEBUG imagefactory.BuildJob.BuildAdaptor pid(11191) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 0 to 10
2011-07-07 12:33:42,673 INFO oz.Guest.FedoraGuest pid(11191) Message: Generating 10GB diskimage for tmpl1
2011-07-07 12:33:42,673 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: Doing base install via Oz
2011-07-07 12:33:42,673 INFO oz.Guest.FedoraGuest pid(11191) Message: Running install for tmpl1
2011-07-07 12:33:42,673 INFO oz.Guest.FedoraGuest pid(11191) Message: Generate XML for guest tmpl1 with bootdev cdrom
2011-07-07 12:33:42,674 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Generated XML:
<?xml version="1.0"?>
<domain type="kvm">
  <name>tmpl1</name>
  <memory>1048576</memory>
  <currentMemory>1048576</currentMemory>
  <uuid>f6117f12-ab09-4693-aa93-a54d0ea8012b</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:d6:e7:9a"/>
      <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-3a04b634-3d14-4c1f-8803-94db02ab2666.dsk"/>
    </disk>
    <disk type="file" device="cdrom">
      <source file="/var/tmp/tmpl1-url-oz.iso"/>
      <target dev="hdc"/>
    </disk>
  </devices>
</domain>

2011-07-07 12:33:43,140 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3600/3600
2011-07-07 12:33:53,168 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3590/3600
2011-07-07 12:34:03,200 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3580/3600
2011-07-07 12:34:13,240 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3570/3600
2011-07-07 12:34:23,272 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3560/3600
2011-07-07 12:34:33,304 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3550/3600
2011-07-07 12:34:43,335 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3540/3600
2011-07-07 12:34:53,366 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3530/3600
2011-07-07 12:35:03,396 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3520/3600
2011-07-07 12:35:13,427 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3510/3600
2011-07-07 12:35:23,458 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3500/3600
2011-07-07 12:35:33,490 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3490/3600
2011-07-07 12:35:43,519 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3480/3600
2011-07-07 12:35:53,550 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3470/3600
2011-07-07 12:36:03,580 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3460/3600
2011-07-07 12:36:13,610 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3450/3600
2011-07-07 12:36:23,642 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3440/3600
2011-07-07 12:36:33,672 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3430/3600
2011-07-07 12:36:43,775 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3420/3600
2011-07-07 12:36:53,808 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3410/3600
2011-07-07 12:37:03,838 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3400/3600
2011-07-07 12:37:13,867 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3390/3600
2011-07-07 12:37:23,938 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3380/3600
2011-07-07 12:37:33,965 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3370/3600
2011-07-07 12:37:43,994 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3360/3600
2011-07-07 12:37:54,023 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3350/3600
2011-07-07 12:38:04,058 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3340/3600
2011-07-07 12:38:14,088 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3330/3600
2011-07-07 12:38:24,118 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3320/3600
2011-07-07 12:38:34,145 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3310/3600
2011-07-07 12:38:44,174 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3300/3600
2011-07-07 12:38:54,204 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to finish installing, 3290/3600
2011-07-07 12:38:57,213 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Libvirt Domain Info Failed:
2011-07-07 12:38:57,213 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  code is 42
2011-07-07 12:38:57,213 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  domain is 10
2011-07-07 12:38:57,213 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  message is Domain not found: no domain with matching uuid 'f6117f12-ab09-4693-aa93-a54d0ea8012b'
2011-07-07 12:38:57,213 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  level is 2
2011-07-07 12:38:57,213 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  str1 is Domain not found: %s
2011-07-07 12:38:57,214 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  str2 is no domain with matching uuid 'f6117f12-ab09-4693-aa93-a54d0ea8012b'
2011-07-07 12:38:57,214 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  str3 is None
2011-07-07 12:38:57,214 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  int1 is -1
2011-07-07 12:38:57,214 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  int2 is -1
2011-07-07 12:38:57,214 INFO oz.Guest.FedoraGuest pid(11191) Message: Install of tmpl1 succeeded
2011-07-07 12:38:57,214 INFO oz.Guest.FedoraGuest pid(11191) Message: Generate XML for guest tmpl1 with bootdev hd
2011-07-07 12:38:57,215 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Generated XML:
<?xml version="1.0"?>
<domain type="kvm">
  <name>tmpl1</name>
  <memory>1048576</memory>
  <currentMemory>1048576</currentMemory>
  <uuid>f6117f12-ab09-4693-aa93-a54d0ea8012b</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:d6:e7:9a"/>
      <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-3a04b634-3d14-4c1f-8803-94db02ab2666.dsk"/>
    </disk>
  </devices>
</domain>

2011-07-07 12:38:57,215 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: Base install complete - Doing customization
2011-07-07 12:38:57,215 DEBUG imagefactory.BuildJob.BuildAdaptor pid(11191) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 10 to 30
2011-07-07 12:38:57,216 INFO oz.Guest.FedoraGuest pid(11191) Message: Customizing image
2011-07-07 12:38:57,216 INFO oz.Guest.FedoraGuest pid(11191) Message: No additional packages or files to install, skipping customization
2011-07-07 12:38:57,216 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: Customization complete
2011-07-07 12:38:57,217 DEBUG imagefactory.BuildJob.BuildAdaptor pid(11191) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 30 to 50
2011-07-07 12:38:57,217 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: Generating ICICLE
2011-07-07 12:38:57,217 INFO oz.Guest.FedoraGuest pid(11191) Message: Generating ICICLE
2011-07-07 12:38:57,217 INFO oz.Guest.FedoraGuest pid(11191) Message: Collection Setup
2011-07-07 12:38:57,219 INFO oz.Guest.FedoraGuest pid(11191) Message: Setting up guestfs handle for tmpl1
2011-07-07 12:38:57,219 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Adding disk image /var/tmp/base-image-3a04b634-3d14-4c1f-8803-94db02ab2666.dsk
2011-07-07 12:38:57,219 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Launching guestfs
2011-07-07 12:38:59,727 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Inspecting guest OS
2011-07-07 12:39:00,903 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Getting mountpoints
2011-07-07 12:39:00,904 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Root device: /dev/VolGroup00/LogVol00
2011-07-07 12:39:01,089 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Step 1: Uploading ssh keys
2011-07-07 12:39:01,097 INFO oz.Guest.FedoraGuest pid(11191) Message: Generating new openssh key
2011-07-07 12:39:01,097 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Step 2: setup sshd
2011-07-07 12:39:01,195 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Step 3: Open up the firewall
2011-07-07 12:39:01,201 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Step 4: Guest announcement
2011-07-07 12:39:01,226 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Step 5: Set SELinux to permissive mode
2011-07-07 12:39:01,238 INFO oz.Guest.FedoraGuest pid(11191) Message: Cleaning up guestfs handle for tmpl1
2011-07-07 12:39:01,238 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Syncing
2011-07-07 12:39:01,460 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Unmounting all
2011-07-07 12:39:01,499 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Killing guestfs subprocess
2011-07-07 12:39:02,036 INFO oz.Guest.FedoraGuest pid(11191) Message: Waiting for guest tmpl1 to boot
2011-07-07 12:39:02,054 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for guest tmpl1 to boot, 300/300
2011-07-07 12:39:12,065 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for guest tmpl1 to boot, 290/300
2011-07-07 12:39:22,075 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for guest tmpl1 to boot, 280/300
2011-07-07 12:39:32,085 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for guest tmpl1 to boot, 270/300
2011-07-07 12:39:42,095 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for guest tmpl1 to boot, 260/300
2011-07-07 12:39:52,100 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for guest tmpl1 to boot, 250/300
2011-07-07 12:40:02,105 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for guest tmpl1 to boot, 240/300
2011-07-07 12:40:03,857 DEBUG oz.Guest.FedoraGuest pid(11191) Message: IP address of guest is 192.168.122.80
2011-07-07 12:40:04,640 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Waiting for tmpl1 to shutdown, 60/60
2011-07-07 12:40:11,656 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Libvirt Domain Info Failed:
2011-07-07 12:40:11,657 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  code is 42
2011-07-07 12:40:11,657 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  domain is 10
2011-07-07 12:40:11,657 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  message is Domain not found: no domain with matching uuid 'f6117f12-ab09-4693-aa93-a54d0ea8012b'
2011-07-07 12:40:11,657 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  level is 2
2011-07-07 12:40:11,658 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  str1 is Domain not found: %s
2011-07-07 12:40:11,658 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  str2 is no domain with matching uuid 'f6117f12-ab09-4693-aa93-a54d0ea8012b'
2011-07-07 12:40:11,658 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  str3 is None
2011-07-07 12:40:11,658 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  int1 is -1
2011-07-07 12:40:11,658 DEBUG oz.Guest.FedoraGuest pid(11191) Message:  int2 is -1
2011-07-07 12:40:11,658 INFO oz.Guest.FedoraGuest pid(11191) Message: Collection Teardown
2011-07-07 12:40:11,660 INFO oz.Guest.FedoraGuest pid(11191) Message: Setting up guestfs handle for tmpl1
2011-07-07 12:40:11,660 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Adding disk image /var/tmp/base-image-3a04b634-3d14-4c1f-8803-94db02ab2666.dsk
2011-07-07 12:40:11,661 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Launching guestfs
2011-07-07 12:40:14,138 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Inspecting guest OS
2011-07-07 12:40:15,255 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Getting mountpoints
2011-07-07 12:40:15,256 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Root device: /dev/VolGroup00/LogVol00
2011-07-07 12:40:15,512 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Teardown step 1
2011-07-07 12:40:15,512 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Resetting authorized_keys
2011-07-07 12:40:15,551 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Teardown step 2
2011-07-07 12:40:15,551 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Resetting sshd_config
2011-07-07 12:40:15,574 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Resetting sshd service
2011-07-07 12:40:15,608 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Teardown step 3
2011-07-07 12:40:15,609 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Resetting iptables rules
2011-07-07 12:40:15,611 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Teardown step 4
2011-07-07 12:40:15,612 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Resetting announcement to host
2011-07-07 12:40:15,613 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Removing icicle-nc binary
2011-07-07 12:40:15,613 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Resetting crond service
2011-07-07 12:40:15,618 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Teardown step 5
2011-07-07 12:40:15,630 INFO oz.Guest.FedoraGuest pid(11191) Message: Cleaning up guestfs handle for tmpl1
2011-07-07 12:40:15,630 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Syncing
2011-07-07 12:40:15,756 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Unmounting all
2011-07-07 12:40:15,796 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Killing guestfs subprocess
2011-07-07 12:40:15,870 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: ICICLE generation complete
2011-07-07 12:40:15,870 INFO oz.Guest.FedoraGuest pid(11191) Message: Cleaning up after install
2011-07-07 12:40:15,870 DEBUG oz.Guest.FedoraGuest pid(11191) Message: Removing modified ISO
2011-07-07 12:40:15,915 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: Generated disk image (/var/tmp/base-image-3a04b634-3d14-4c1f-8803-94db02ab2666.dsk)
2011-07-07 12:40:15,915 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: Adding cloud-info to local image
2011-07-07 12:40:15,915 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: init guestfs
2011-07-07 12:40:15,916 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: add input image
2011-07-07 12:40:15,916 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: launch guestfs
2011-07-07 12:40:18,521 INFO imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: Creating cloud-info file indicating target (vmware)
2011-07-07 12:40:18,531 INFO imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: Updating rc.local with Audrey conditional
2011-07-07 12:40:19,041 INFO imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: Transforming image for use on VMWare
2011-07-07 12:40:19,041 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: Converting raw kvm image (/var/tmp/base-image-3a04b634-3d14-4c1f-8803-94db02ab2666.dsk) to vmware stream-optimized image (/var/tmp/vmware-image-3a04b634-3d14-4c1f-8803-94db02ab2666.vmdk)
2011-07-07 12:41:21,719 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: VMWare stream conversion complete
2011-07-07 12:41:21,719 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: Storing Fedora image at http://localhost:9090/...
2011-07-07 12:41:21,741 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(11191) 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-07 12:41:21,754 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Setting metadata ({'object_type': 'template', 'uuid': 'e4d1e954-b2a5-4093-870c-be921e1105ce'}) for http://localhost:9090/templates/e4d1e954-b2a5-4093-870c-be921e1105ce
2011-07-07 12:41:21,840 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Setting metadata ({'object_type': 'icicle', 'uuid': 'b3c4bf1c-f81c-4183-8c39-8e53446e453f'}) for http://localhost:9090/icicles/b3c4bf1c-f81c-4183-8c39-8e53446e453f
2011-07-07 12:41:25,345 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Setting metadata ({'icicle': 'b3c4bf1c-f81c-4183-8c39-8e53446e453f', 'uuid': '3a04b634-3d14-4c1f-8803-94db02ab2666', 'template': 'e4d1e954-b2a5-4093-870c-be921e1105ce', 'target_parameters': 'No target parameters for cloud type vmware', 'object_type': 'target_image', 'target': 'vmware', 'build': 'ed73308d-d026-4052-af9d-3dc936d29ba3'}) for http://localhost:9090/target_images/3a04b634-3d14-4c1f-8803-94db02ab2666
2011-07-07 12:41:25,593 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(11191) Message: Image warehouse storage complete
2011-07-07 12:41:25,593 DEBUG imagefactory.BuildJob.BuildAdaptor pid(11191) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 50 to 100
2011-07-07 12:41:25,594 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Getting metadata (['latest_unpushed']) from http://localhost:9090/images/5e9a8be3-dada-4d5c-b9ef-e9f023b68c00
2011-07-07 12:41:25,595 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Getting metadata (['latest_build']) from http://localhost:9090/images/5e9a8be3-dada-4d5c-b9ef-e9f023b68c00
2011-07-07 12:41:25,596 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Setting metadata ({'latest_unpushed': 'ed73308d-d026-4052-af9d-3dc936d29ba3'}) for http://localhost:9090/images/5e9a8be3-dada-4d5c-b9ef-e9f023b68c00
2011-07-07 12:41:25,598 DEBUG imagefactory.BuildJob.BuildAdaptor pid(11191) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from BUILDING to COMPLETED
2011-07-07 12:42:20,815 DEBUG imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(11191) Message: Method called: name = push_image 
 args = {'credentials': '<provider_accounts>\n<provider_account>\n<name>vmwareAccount</name>\n<provider>vmware</provider>\n<provider_type>vmware</provider_type>\n<provider_credentials>\n  <vmware_credentials>\n    <password>100yard-</password>\n    <username>Administrator</username>\n  </vmware_credentials>\n</provider_credentials>\n</provider_account>\n</provider_accounts>\n', 'image': '5e9a8be3-dada-4d5c-b9ef-e9f023b68c00', 'build': '', 'providers': ['vmware']} 
 handle = <cqmf2.AgentEvent; proxy of <Swig Object of type 'qmf::AgentEvent *' at 0x21cecc0> > 
 addr = redhat.com:imagefactory:5d7f70e3-9633-4eae-b716-75e3106e2c11:image_factory 
 subtypes = {} 
 userId = anonymous
2011-07-07 12:42:20,815 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Getting metadata (['latest_unpushed']) from http://localhost:9090/images/5e9a8be3-dada-4d5c-b9ef-e9f023b68c00
2011-07-07 12:42:20,827 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Querying (http://localhost:9090/target_images/_query) with expression ($build == "ed73308d-d026-4052-af9d-3dc936d29ba3" && $target == "condorcloud")
2011-07-07 12:42:20,843 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Getting metadata (['template']) from http://localhost:9090/target_images/None
2011-07-07 12:42:20,844 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(11191) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-07 12:42:20,844 ERROR imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(11191) Message: 'template' must be a UUID, URL, XML string or XML document path...
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/imagefactory/qmfagent/ImageFactoryAgent.py", line 74, in method
    result = getattr(target_obj, methodName)(**args)
  File "/usr/lib/python2.6/site-packages/imagefactory/qmfagent/ImageFactory.py", line 125, in push_image
    return BuildDispatcher().push_image_to_providers(image, build, providers, credentials, BuildAdaptor, self.agent)
  File "/usr/lib/python2.6/site-packages/imagefactory/BuildDispatcher.py", line 78, in push_image_to_providers
    job = job_cls(template, target, image_id, build_id, *args, **kwargs)
  File "/usr/lib/python2.6/site-packages/imagefactory/qmfagent/BuildAdaptor.py", line 76, in __init__
    super(BuildAdaptor, self).__init__(template, target, image_id, build_id)
  File "/usr/lib/python2.6/site-packages/imagefactory/BuildJob.py", line 42, in __init__
    self.template = template if isinstance(template, Template) else Template(template)
  File "/usr/lib/python2.6/site-packages/imagefactory/Template.py", line 83, in __init__
    raise ValueError("'template' must be a UUID, URL, XML string or XML document path...")
ValueError: 'template' must be a UUID, URL, XML string or XML document path...
2011-07-07 12:42:57,881 WARNING root pid(11191) Message: caught signal SIGTERM, stopping...
2011-07-07 12:43:02,636 INFO root pid(12292) Message: Launched as daemon...
2011-07-07 12:43:02,768 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(12292) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-07 12:43:02,768 INFO imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(12292) Message: image_factory has qmf/qpid address: redhat.com:imagefactory:30a19428-9383-479f-ab64-3c16141f8376:image_factory
2011-07-07 12:51:53,244 DEBUG imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(12292) Message: Method called: name = push_image 
 args = {'credentials': '<provider_accounts>\n<provider_account>\n<name>vmwareAccount</name>\n<provider>vmware</provider>\n<provider_type>vmware</provider_type>\n<provider_credentials>\n  <vmware_credentials>\n    <password>100yard-</password>\n    <username>Administrator</username>\n  </vmware_credentials>\n</provider_credentials>\n</provider_account>\n</provider_accounts>\n', 'image': '5e9a8be3-dada-4d5c-b9ef-e9f023b68c00', 'build': '', 'providers': ['westford_esx']} 
 handle = <cqmf2.AgentEvent; proxy of <Swig Object of type 'qmf::AgentEvent *' at 0x1824fc0> > 
 addr = redhat.com:imagefactory:30a19428-9383-479f-ab64-3c16141f8376:image_factory 
 subtypes = {} 
 userId = anonymous
2011-07-07 12:51:53,244 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(12292) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-07 12:51:53,245 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(12292) Message: Getting metadata (['latest_unpushed']) from http://localhost:9090/images/5e9a8be3-dada-4d5c-b9ef-e9f023b68c00
2011-07-07 12:51:53,247 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(12292) Message: Querying (http://localhost:9090/target_images/_query) with expression ($build == "ed73308d-d026-4052-af9d-3dc936d29ba3" && $target == "vmware")
2011-07-07 12:51:53,250 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(12292) Message: Getting metadata (['template']) from http://localhost:9090/target_images/3a04b634-3d14-4c1f-8803-94db02ab2666
2011-07-07 12:51:53,252 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(12292) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-07 12:51:53,283 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(12292) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-07 12:51:53,287 DEBUG imagefactory.BuildJob.BuildAdaptor pid(12292) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from NEW to PUSHING
2011-07-07 12:51:53,288 DEBUG imagefactory.BuildJob.BuildAdaptor pid(12292) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 0 to 0
2011-07-07 12:51:53,293 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(12292) Message: Image file /var/tmp/vmware-image-3a04b634-3d14-4c1f-8803-94db02ab2666.vmdk already present - skipping warehouse download
2011-07-07 12:53:59,994 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(12292) Message: Setting metadata ({'target_image': '3a04b634-3d14-4c1f-8803-94db02ab2666', 'uuid': '91942754-b7e9-489d-9601-1377e47bb66a', 'icicle': 'none', 'target_identifier': 'factory-image-91942754-b7e9-489d-9601-1377e47bb66a', 'object_type': 'provider_image', 'provider': 'westford_esx'}) for http://localhost:9090/provider_images/91942754-b7e9-489d-9601-1377e47bb66a
2011-07-07 12:54:00,250 DEBUG imagefactory.BuildJob.BuildAdaptor pid(12292) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 0 to 100
2011-07-07 12:54:00,251 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(12292) Message: Setting metadata ({'latest_build': 'ed73308d-d026-4052-af9d-3dc936d29ba3'}) for http://localhost:9090/images/5e9a8be3-dada-4d5c-b9ef-e9f023b68c00
2011-07-07 12:54:00,253 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(12292) Message: Setting metadata ({'latest_unpushed': None}) for http://localhost:9090/images/5e9a8be3-dada-4d5c-b9ef-e9f023b68c00
2011-07-07 12:54:00,300 DEBUG imagefactory.BuildJob.BuildAdaptor pid(12292) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from PUSHING to COMPLETED
Comment 7 wes hayutin 2011-07-11 00:32:53 UTC 
removing from tracker
Comment 8 wes hayutin 2011-12-08 13:57:47 UTC 
perm close