Bug 719635

Summary:	unable to build a template after rebooting aeolus
Product:	[Retired] CloudForms Cloud Engine	Reporter:	wes hayutin <whayutin>
Component:	iwhd	Assignee:	Chris Lalancette <clalance>
Status:	CLOSED CURRENTRELEASE	QA Contact:	wes hayutin <whayutin>
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	0.3.1	CC:	akarol, dajohnso, deltacloud-maint, ssachdev
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:53:25 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-07 14:23:47 UTC

Description of problem:

recreate:
1. install/configure/ aeolus
2. setup your provider etc.. in my case using vmware
3. build and push template.. fine..

reboot the aeolus server..
some services may or may not come up correctly...
see https://bugzilla.redhat.com/show_bug.cgi?id=719590

fix the services by hand to the best of your ability :)

4. attempt to build a template

ERROR...
    response_headers, response = self._http_request(url, 'PUT')
  File "/usr/lib/python2.7/site-packages/imagefactory/ImageWarehouse.py", line 75, in _http_request
    raise WarehouseError("Problem encountered trying to reach image warehouse. Please check that iwhd is running and reachable.\nException text: %s" % (e, ))
WarehouseError: "Problem encountered trying to reach image warehouse. Please check that iwhd is running and reachable.\nException text: 'NoneType' object has no attribute 'makefile'"


However the iwhd process is indeed running

[root@dell-pe2950-01 ~]# /etc/init.d/iwhd status
iwhd (pid  15350) is running...
[root@dell-pe2950-01 ~]# ps -ef | grep iwhd
root     15350     1  0 08:39 pts/0    00:00:00 iwhd -c /etc/iwhd/conf.js -d localhost 27017
root     16921 16122  0 10:22 pts/2    00:00:00 grep --color=auto iwhd
[root@dell-pe2950-01 ~]# cat /etc/iwhd/conf.js 
[
  {
    "name": "primary",
    "type": "fs",
    "path": "/var/lib/iwhd"
  }
]

[root@dell-pe2950-01 ~]# cat /var/log/iwhd.log 
0 replication servers defined
iwhd: convert-provider: ITER key: name
iwhd: convert-provider: ITER key: type
iwhd: convert-provider: ITER key: path
[root@dell-pe2950-01 ~]# 


====================== FULL TRACE =======================
[root@dell-pe2950-01 ~]# tail -f /var/log/imagefactory.log
2011-07-07 09:55:08,306 DEBUG imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(2248) Message: Method called: name = build_image 
 args = {'image': '', 'build': '', 'template': '<template>\n<name>tmpl4</name>\n<description>foo-bar</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 0x195bb10> > 
 addr = redhat.com:imagefactory:957935a3-c1e3-42f9-923b-738b9bfdb3f2:image_factory 
 subtypes = {} 
 userId = anonymous
2011-07-07 09:55:08,308 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(2248) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-07 09:55:08,309 ERROR imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(2248) Message: "Problem encountered trying to reach image warehouse. Please check that iwhd is running and reachable.\nException text: 'NoneType' object has no attribute 'makefile'"
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/imagefactory/qmfagent/ImageFactoryAgent.py", line 74, in method
    result = getattr(target_obj, methodName)(**args)
  File "/usr/lib/python2.7/site-packages/imagefactory/qmfagent/ImageFactory.py", line 122, in build_image
    return BuildDispatcher().build_image_for_targets(image, build, template, targets, BuildAdaptor, self.agent)
  File "/usr/lib/python2.7/site-packages/imagefactory/BuildDispatcher.py", line 51, in build_image_for_targets
    image_id = self._ensure_image_with_template(image_id, template)
  File "/usr/lib/python2.7/site-packages/imagefactory/BuildDispatcher.py", line 96, in _ensure_image_with_template
    return self._ensure_image(image_id, image_desc)
  File "/usr/lib/python2.7/site-packages/imagefactory/BuildDispatcher.py", line 102, in _ensure_image
    return self.warehouse.store_image(None, image_desc)
  File "/usr/lib/python2.7/site-packages/imagefactory/ImageWarehouse.py", line 171, in store_image
    object_url = self.__url_for_id_of_type(image_id, object_type="image")
  File "/usr/lib/python2.7/site-packages/imagefactory/ImageWarehouse.py", line 100, in __url_for_id_of_type
    self.create_bucket_at_url("%s/%s" % (self.url, bucket))
  File "/usr/lib/python2.7/site-packages/imagefactory/ImageWarehouse.py", line 87, in create_bucket_at_url
    response_headers, response = self._http_request(url, 'PUT')
  File "/usr/lib/python2.7/site-packages/imagefactory/ImageWarehouse.py", line 75, in _http_request
    raise WarehouseError("Problem encountered trying to reach image warehouse. Please check that iwhd is running and reachable.\nException text: %s" % (e, ))
WarehouseError: "Problem encountered trying to reach image warehouse. Please check that iwhd is running and reachable.\nException text: 'NoneType' object has no attribute 'makefile'"

Comment 1 wes hayutin 2011-07-07 17:28:02 UTC

ad-1, initial)>), changed status from PUSHING to COMPLETED
2011-07-07 12:59:56,813 WARNING root pid(12292) Message: caught signal SIGTERM, stopping...
2011-07-07 13:13:54,564 INFO root pid(2948) Message: Launched as daemon...
2011-07-07 13:13:54,715 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(2948) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-07 13:13:54,715 INFO imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(2948) Message: image_factory has qmf/qpid address: redhat.com:imagefactory:099542f0-01a9-497d-9d96-4be3f3fd12d0:image_factory

REBOOT HERE::::::  SNIP!!!!  REBOOOT


2011-07-07 13:26:39,993 DEBUG imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(2948) Message: Method called: name = build_image 
 args = {'image': '', 'build': '', 'template': '<template>\n<name>tmpl2</name>\n<description>foo-bar</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 0x2805e70> > 
 addr = redhat.com:imagefactory:099542f0-01a9-497d-9d96-4be3f3fd12d0:image_factory 
 subtypes = {} 
 userId = anonymous
2011-07-07 13:26:39,995 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(2948) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-07 13:26:39,995 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(2948) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-07 13:26:40,015 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(2948) 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 13:26:40,058 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(2948) Message: Setting metadata ({'object_type': 'image', 'uuid': 'ed4ea99d-81d6-4f98-9843-184ed924af89'}) for http://localhost:9090/images/ed4ea99d-81d6-4f98-9843-184ed924af89
2011-07-07 13:26:40,102 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(2948) 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 13:26:40,108 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(2948) Message: Setting metadata ({'image': 'ed4ea99d-81d6-4f98-9843-184ed924af89', 'object_type': 'build', 'uuid': '911555ff-b1e3-4102-88a7-7e8ef36be19a'}) for http://localhost:9090/builds/911555ff-b1e3-4102-88a7-7e8ef36be19a
2011-07-07 13:26:40,232 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(2948) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-07-07 13:26:40,273 DEBUG oz.Guest.FedoraGuest pid(2948) Message: libvirt bridge name is virbr0, host_bridge_ip is 192.168.122.1
2011-07-07 13:26:40,273 DEBUG oz.Guest.FedoraGuest pid(2948) Message: Name: tmpl2, UUID: c6f8310d-7433-46f8-8dc2-aa28dd6b2a9e
2011-07-07 13:26:40,273 DEBUG oz.Guest.FedoraGuest pid(2948) Message: MAC: 52:54:00:dc:42:e0, distro: Fedora
2011-07-07 13:26:40,274 DEBUG oz.Guest.FedoraGuest pid(2948) Message: update: 14, arch: x86_64, diskimage: /var/tmp/tmpl2.dsk
2011-07-07 13:26:40,274 DEBUG oz.Guest.FedoraGuest pid(2948) Message: nicmodel: virtio, clockoffset: utc
2011-07-07 13:26:40,274 DEBUG oz.Guest.FedoraGuest pid(2948) Message: mousetype: ps2, disk_bus: virtio, disk_dev: vda
2011-07-07 13:26:40,274 DEBUG oz.Guest.FedoraGuest pid(2948) Message: icicletmp: /var/lib/oz/icicletmp/tmpl2, listen_port: 35189
2011-07-07 13:26:40,274 DEBUG oz.Guest.FedoraGuest pid(2948) Message: Original ISO path: /var/lib/oz/isos/Fedora14x86_64-url.iso
2011-07-07 13:26:40,274 DEBUG oz.Guest.FedoraGuest pid(2948) Message: Modified ISO cache: /var/lib/oz/isos/Fedora14x86_64-url-oz.iso
2011-07-07 13:26:40,275 DEBUG oz.Guest.FedoraGuest pid(2948) Message: Output ISO path: /var/tmp/tmpl2-url-oz.iso
2011-07-07 13:26:40,275 DEBUG oz.Guest.FedoraGuest pid(2948) Message: ISO content path: /var/lib/oz/isocontent/tmpl2-url
2011-07-07 13:26:40,941 DEBUG oz.Guest.FedoraGuest pid(2948) 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 13:26:40,941 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(2948) Message: build_upload() called on FedoraBuilder...
2011-07-07 13:26:40,942 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(2948) Message: Building for target vmware with warehouse config http://localhost:9090/
2011-07-07 13:26:40,942 DEBUG imagefactory.BuildJob.BuildAdaptor pid(2948) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from NEW to BUILDING
2011-07-07 13:26:40,942 INFO oz.Guest.FedoraGuest pid(2948) Message: Cleaning up guest named tmpl2
2011-07-07 13:26:40,949 INFO oz.Guest.FedoraGuest pid(2948) Message: Generating install media
2011-07-07 13:26:40,965 INFO oz.Guest.FedoraGuest pid(2948) Message: Fetching the original media
2011-07-07 13:26:42,329 INFO oz.Guest.FedoraGuest pid(2948) Message: Original install media available, using cached version
2011-07-07 13:26:42,329 INFO oz.Guest.FedoraGuest pid(2948) Message: Copying ISO contents for modification
2011-07-07 13:26:42,344 INFO oz.Guest.FedoraGuest pid(2948) Message: Setting up guestfs handle for tmpl2
2011-07-07 13:26:42,344 DEBUG oz.Guest.FedoraGuest pid(2948) Message: Adding ISO image /var/lib/oz/isos/Fedora14x86_64-url.iso
2011-07-07 13:26:42,351 DEBUG oz.Guest.FedoraGuest pid(2948) Message: Launching guestfs
2011-07-07 13:26:45,187 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(2948) Message: Exception caught in ImageFactory
2011-07-07 13:26:45,272 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(2948) Message: Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/imagefactory/builders/FedoraBuilder.py", line 157, in build_upload
    self.guest.generate_install_media(force_download=False)
  File "/usr/lib/python2.6/site-packages/oz/RedHat.py", line 384, in generate_install_media
    return self.iso_generate_install_media(fetchurl, force_download)
  File "/usr/lib/python2.6/site-packages/oz/Guest.py", line 1063, in iso_generate_install_media
    self.copy_iso()
  File "/usr/lib/python2.6/site-packages/oz/Guest.py", line 847, in copy_iso
    gfs.launch()
  File "/usr/lib/python2.6/site-packages/guestfs.py", line 151, in launch
    return libguestfsmod.launch (self._o)
RuntimeError: child process died unexpectedly

2011-07-07 13:26:45,273 DEBUG imagefactory.BuildJob.BuildAdaptor pid(2948) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from BUILDING to FAILED
2011-07-07 13:26:45,274 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(2948) Message: Exception caught in ImageFactory
2011-07-07 13:26:45,274 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(2948) Message: Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/imagefactory/builders/FedoraBuilder.py", line 125, in build_image
    self.build_upload(build_id)
  File "/usr/lib/python2.6/site-packages/imagefactory/builders/FedoraBuilder.py", line 157, in build_upload
    self.guest.generate_install_media(force_download=False)
  File "/usr/lib/python2.6/site-packages/oz/RedHat.py", line 384, in generate_install_media
    return self.iso_generate_install_media(fetchurl, force_download)
  File "/usr/lib/python2.6/site-packages/oz/Guest.py", line 1063, in iso_generate_install_media
    self.copy_iso()
  File "/usr/lib/python2.6/site-packages/oz/Guest.py", line 847, in copy_iso
    gfs.launch()
  File "/usr/lib/python2.6/site-packages/guestfs.py", line 151, in launch
    return libguestfsmod.launch (self._o)
RuntimeError: child process died unexpectedly

2011-07-07 13:26:45,274 DEBUG imagefactory.BuildJob.BuildAdaptor pid(2948) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from FAILED to FAILED

Comment 2 wes hayutin 2011-07-07 17:31:40 UTC

looks like this last issue is OZ related..

Comment 3 wes hayutin 2011-07-07 17:53:25 UTC

the error turned out to be between the keyboard and my chair.

Comment 4 wes hayutin 2011-07-11 00:32:58 UTC

removing from tracker

Comment 5 wes hayutin 2011-12-08 14:13:21 UTC

perm close