Bug 696228

Summary: template builds stay in queued due to missing uuid in conductor
Product: [Retired] CloudForms Cloud Engine Reporter: wes hayutin <whayutin>
Component: aeolus-conductorAssignee: Jason Guiditta <jguiditt>
Status: CLOSED CURRENTRELEASE QA Contact: wes hayutin <whayutin>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 0.3.1CC: deltacloud-maint, maurizio.antillon
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
URL: na
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-12-08 13:49:16 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 684278    

Description wes hayutin 2011-04-13 15:52:50 UTC 
<jayg> weshay: what is happening is, since the events come back asynchronously, and the image build step happens SO fast, the return call is not yet done saving the new uuid in conductor, so statsu updates fail


[root@intel-d3c4702-01 ~]# rpm -qa | grep aeolus
aeolus-conductor-daemons-0.0.3-4.el6.x86_64
aeolus-configure-2.0.0-5.el6.noarch
aeolus-conductor-0.0.3-4.el6.x86_64
aeolus-conductor-doc-0.0.3-4.el6.x86_64
[root@intel-d3c4702-01 ~]# rpm -qa | grep connector
rubygem-image_factory_connector-0.0.1-2.el6_0.20110401225254git6800ed8.noarch
[root@intel-d3c4702-01 ~]# 


######### CONNECTOR LOGS,  not 100% sure if this demonstrates the issue #########


> Listening on 0.0.0.0:2003, CTRL+C to stop
>> Stopping ...
2011-04-13 08:55:20 warning Connection [51625 localhost:5672] closed
>> Thin web server (v1.2.5 codename This Is Not A Web Server)
>> Maximum connections set to 1024
>> Listening on 0.0.0.0:2003, CTRL+C to stop
D, [2011-04-13T08:38:13.593109 #19655] DEBUG -- : GOT AN AGENT:  redhat.com:imagefactory:aa8dfde4-9829-451d-ac28-307a84be0606 at Wed Apr 13 12:38:13 UTC 2011
D, [2011-04-13T08:38:13.870838 #19655] DEBUG -- : AGENT SCHEMA UPDATED:  imagefactory
>> Stopping ...
127.0.0.1 - - [13/Apr/2011 09:12:24] "POST /build HTTP/1.1" 200 108 4.8718
2011-04-13 09:47:53 warning Connection [51974 localhost:5672] closed
D, [2011-04-13T08:55:11.034457 #20755] DEBUG -- : GOT AN AGENT:  redhat.com:imagefactory:aa8dfde4-9829-451d-ac28-307a84be0606 at Wed Apr 13 12:55:11 UTC 2011
>> Thin web server (v1.2.5 codename This Is Not A Web Server)
>> Maximum connections set to 1024
>> Listening on 0.0.0.0:2003, CTRL+C to stop
D, [2011-04-13T09:12:19.973192 #20755] DEBUG -- : build method called with {"template"=>"http://localhost:9090/templates/96cc0e60-65cd-11e0-a8d0-001320f3f0c5", "target"=>"ec2"}
D, [2011-04-13T09:12:24.774041 #20755] DEBUG -- : GOT AN EVENT:  redhat.com:imagefactory:aa8dfde4-9829-451d-ac28-307a84be0606, percent_complete100eventPERCENTAGEaddr_object_namebuild_adaptor:image:fd4aada7-fa41-4202-bdb4-0913cb1ebfbe_agent_nameredhat.com:imagefactory:aa8dfde4-9829-451d-ac28-307a84be0606 at 1302700344756401899
D, [2011-04-13T09:12:24.804094 #20755] DEBUG -- : ====== Type of event: PERCENTAGE
D, [2011-04-13T09:12:24.842799 #20755] DEBUG -- : GOT AN EVENT:  redhat.com:imagefactory:aa8dfde4-9829-451d-ac28-307a84be0606, old_statusNEWeventSTATUSnew_statusCOMPLETEDaddr_object_namebuild_adaptor:image:fd4aada7-fa41-4202-bdb4-0913cb1ebfbe_agent_nameredhat.com:imagefactory:aa8dfde4-9829-451d-ac28-307a84be0606 at 1302700344757813636
D, [2011-04-13T09:12:24.883400 #20755] DEBUG -- : ====== Type of event: STATUS
D, [2011-04-13T09:12:24.886200 #20755] DEBUG -- : calling handle status in base handler
D, [2011-04-13T09:12:24.886633 #20755] DEBUG -- : Data: #<FactoryRestHandler::EventData:0x7f5c6eb18790 @obj="image", @value="completed", @event="STATUS", @uuid="fd4aada7-fa41-4202-bdb4-0913cb1ebfbe">
D, [2011-04-13T09:12:24.902114 #20755] DEBUG -- : Return code is: 404
D, [2011-04-13T09:12:24.902584 #20755] DEBUG -- : Return body is:
Comment 1 Jason Guiditta 2011-04-13 19:44:46 UTC 
Patch sent to list:

commit 5a3f568bd17fac26d7ea42a456b4b0c267823a13
Author: Jason Guiditta <jguiditt>
Date:   Wed Apr 13 15:40:49 2011 -0400

BZ #696228. Builds stay in queued.
    
https://bugzilla.redhat.com/show_bug.cgi?id=696228
    
This adds a temporary fix to cover the race condition seen
in testing when a status update comes back before the build
request from conductor has completed and update the uuid in
conductor db.
Comment 2 wes hayutin 2011-06-14 15:39:55 UTC 
moving to on_qa for review
Comment 3 wes hayutin 2011-06-23 21:44:25 UTC 
verified...




3cdd-4bb9-88ae-4a32f7d43678
2011-06-23 14:07:16,251 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(10681) Message: Stopping EC2 instance and deleting temp security group
2011-06-23 14:07:18,106 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(10681) Message: FedoraBuilder instance 139962918324048 pushed image with uuid 8809de31-c008-457b-8578-f743948eac2c to provider_image UUID (cfc800ce-3cdd-4bb9-88ae-4a32f7d43678) and set metadata: {'target_image': '8809de31-c008-457b-8578-f743948eac2c', 'target_identifier': 'ami-8c57afe5', 'icicle': 'cc6414fc-c8aa-4322-ab3d-ef76ae8bec2a', 'provider': 'ec2-us-east-1'}
2011-06-23 14:07:18,106 DEBUG imagefactory.BuildJob.BuildAdaptor pid(10681) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 0 to 100
2011-06-23 14:07:18,107 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(10681) Message: Setting metadata ({'latest_build': '6abfe669-4364-4bc5-9be5-d2ef04a003d0'}) for http://localhost:9090/images/e8b1cbb2-8e23-4bf6-867d-df79f83963b5
2011-06-23 14:07:18,148 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(10681) Message: Setting metadata ({'latest_unpushed': None}) for http://localhost:9090/images/e8b1cbb2-8e23-4bf6-867d-df79f83963b5
2011-06-23 14:07:18,189 DEBUG imagefactory.BuildJob.BuildAdaptor pid(10681) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from PUSHING to COMPLETED
2011-06-23 16:56:13,114 WARNING root pid(10681) Message: caught signal SIGTERM, stopping...
2011-06-23 16:57:05,500 INFO root pid(22672) Message: Launched as daemon...
2011-06-23 16:57:05,646 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-06-23 16:57:05,647 INFO imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(22672) Message: image_factory has qmf/qpid address: redhat.com:imagefactory:b1688e42-f6f5-42d4-aa19-fbb17eb92fbf:image_factory
2011-06-23 17:02:10,885 DEBUG imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(22672) Message: Method called: name = build_image 
 args = {'image': '', 'build': '', 'template': '<?xml version="1.0"?>\n<template>\n  <name>template01</name>\n  <description>template01 description </description>\n  <os>\n    <name>Fedora</name>\n    <arch>x86_64</arch>\n    <version>14</version>\n    <install type="url">\n      <url>http://download.fedoraproject.org/pub/fedora/linux/releases/14/Fedora/x86_64/os/</url>\n    </install>\n  </os>\n  <repositories>\n    <repository name="custom">\n      <url>http://repos.fedorapeople.org/repos/aeolus/demo/webapp/</url>\n      <signed>false</signed>\n    </repository>\n  </repositories>\n</template>\n', 'targets': ['ec2']} 
 handle = <cqmf2.AgentEvent; proxy of <Swig Object of type 'qmf::AgentEvent *' at 0x2e7e5d0> > 
 addr = redhat.com:imagefactory:b1688e42-f6f5-42d4-aa19-fbb17eb92fbf:image_factory 
 subtypes = {} 
 userId = anonymous
2011-06-23 17:02:10,892 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-06-23 17:02:10,893 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-06-23 17:02:10,907 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(22672) 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-06-23 17:02:10,910 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Setting metadata ({'object_type': 'image', 'uuid': '8d4da86e-2e74-4dcc-bada-359ebc8531c6'}) for http://localhost:9090/images/8d4da86e-2e74-4dcc-bada-359ebc8531c6
2011-06-23 17:02:10,993 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(22672) 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-06-23 17:02:10,995 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Setting metadata ({'image': '8d4da86e-2e74-4dcc-bada-359ebc8531c6', 'object_type': 'build', 'uuid': 'e8ddcbdd-5e32-4e55-8bbc-a113021c1a6f'}) for http://localhost:9090/builds/e8ddcbdd-5e32-4e55-8bbc-a113021c1a6f
2011-06-23 17:02:11,119 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-06-23 17:02:11,123 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Building Linux for non-upload cloud (ec2)
2011-06-23 17:02:11,126 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Storing placeholder object for non upload cloud image
2011-06-23 17:02:11,128 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(22672) 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-06-23 17:02:11,132 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Setting metadata ({'object_type': 'template', 'uuid': 'f710663c-eb70-4c31-97dd-bb6f47844335'}) for http://localhost:9090/templates/f710663c-eb70-4c31-97dd-bb6f47844335
2011-06-23 17:02:11,215 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(22672) 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-06-23 17:02:11,218 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Setting metadata ({'icicle': 'none', 'uuid': '57b8bffc-fa83-4d22-b22c-7e8a3cb01244', 'template': 'f710663c-eb70-4c31-97dd-bb6f47844335', 'target_parameters': None, 'object_type': 'target_image', 'target': 'ec2', 'build': 'e8ddcbdd-5e32-4e55-8bbc-a113021c1a6f'}) for http://localhost:9090/target_images/57b8bffc-fa83-4d22-b22c-7e8a3cb01244
2011-06-23 17:02:11,466 DEBUG imagefactory.BuildJob.BuildAdaptor pid(22672) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 0 to 100
2011-06-23 17:02:11,467 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Getting metadata (['latest_unpushed']) from http://localhost:9090/images/8d4da86e-2e74-4dcc-bada-359ebc8531c6
2011-06-23 17:02:11,468 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Getting metadata (['latest_build']) from http://localhost:9090/images/8d4da86e-2e74-4dcc-bada-359ebc8531c6
2011-06-23 17:02:11,469 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Setting metadata ({'latest_unpushed': 'e8ddcbdd-5e32-4e55-8bbc-a113021c1a6f'}) for http://localhost:9090/images/8d4da86e-2e74-4dcc-bada-359ebc8531c6
2011-06-23 17:02:11,471 DEBUG imagefactory.BuildJob.BuildAdaptor pid(22672) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from NEW to COMPLETED
2011-06-23 17:02:11,472 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Completed placeholder warehouse object for linux non-upload image...
2011-06-23 17:02:45,726 DEBUG imagefactory.qmfagent.ImageFactoryAgent.ImageFactoryAgent pid(22672) Message: Method called: name = push_image 
 args = {'credentials': '<provider_accounts>\n<provider_account>\n<name>wes-us-east-1</name>\n<provider>ec2-us-east-1</provider>\n<provider_type>ec2</provider_type>\n<provider_credentials>\n  <ec2_credentials>\n    <access_key>AKIAJ557U7P7OIHRV2EQ</access_key>\n    <account_number>6735-0069-5950</account_number>\n    <certificate>-----BEGIN CERTIFICATE-----\nMIICeDCCAeGgAwIBAgIGAIMhOJTUMA0GCSqGSIb3DQEBBQUAMFMxCzAJBgNVBAYT\nAlVTMRMwEQYDVQQKEwpBbWF6b24uY29tMQwwCgYDVQQLEwNBV1MxITAfBgNVBAMT\nGEFXUyBMaW1pdGVkLUFzc3VyYW5jZSBDQTAeFw0xMDA0MTkxNDU2MDRaFw0xMTA0\nMTkxNDU2MDRaMFMxCzAJBgNVBAYTAlVTMRMwEQYDVQQKEwpBbWF6b24uY29tMRcw\nFQYDVQQLEw5BV1MtRGV2ZWxvcGVyczEWMBQGA1UEAxMNMTNxb2pvMnhpa3AxMzCB\nnzANBgkqhkiG9w0BAQEFAAOBjQAwgYkCgYEAhsjKFoUJvEiZLdqALUAyFdDoeBKt\nZcqCRa5459+zp/d4XcykugpLlvcEfuKOrQcmqA08JWEN/4Xj4nIz+HoEtui3KFgg\n2YJ/VImlVeaSn4AGjfLsrEjLHnEBSGgNAJsh53fuEQTga8Y00T2qQ7d/Ebh6OXI3\niRKjY5Bm0d5mqrsCAwEAAaNXMFUwDgYDVR0PAQH/BAQDAgWgMBYGA1UdJQEB/wQM\nMAoGCCsGAQUFBwMCMAwGA1UdEwEB/wQCMAAwHQYDVR0OBBYEFDML4N2PsXn7nurg\n5bXHxMkFVQbLMA0GCSqGSIb3DQEBBQUAA4GBAIUGLc0R3HnEDXlXQMiLfQygqXEv\ndouihRgqCO+LOWb3tJbpk49TkhSFcjO0TJnKMb+XzuAdfswwgXSmwbbvrcDT/OdD\njHbCrLTCBBXIgShKZTrTYOAII5sokU4wg5QS0w9cEWcxceUWRaP8ELdai+ubrlif\noCeB2dgQxL18+uK5\n-----END CERTIFICATE-----\n</certificate>\n    <key>-----BEGIN PRIVATE KEY-----\nMIICdQIBADANBgkqhkiG9w0BAQEFAASCAl8wggJbAgEAAoGBAIbIyhaFCbxImS3agC1AMhXQ6HgS&#xD;\nrWXKgkWueOffs6f3eF3MpLoKS5b3BH7ijq0HJqgNPCVhDf+F4+JyM/h6BLbotyhYINmCf1SJpVXm&#xD;\nkp+ABo3y7KxIyx5xAUhoDQCbIed37hEE4GvGNNE9qkO3fxG4ejlyN4kSo2OQZtHeZqq7AgMBAAEC&#xD;\ngYByI9mXZoRPET++5/mB2IpRlT84Z8C1od/eOJkk63kNtfEVpfadoZhPuNHyzdM7TgH7cHHNybn7&#xD;\n+Jt6KXI/ar1QDIse7S+xU700AWJVaUt3FqlrglmGT018oGWqH1/3D9/4yVsdvxCKcKYuvre3j2gU&#xD;\nsi7uJPpWYqCLhs41EuIUiQJBAPcuRXEtVV5MJipuYljERZHfxT4Yh/b8agfr1dsrHvd4jly9rJnE&#xD;\nIwB3vn0mMS9Fs/f0rUc3RAZRSrsuwYravU8CQQCLl+YDqZOwVfZIkJO2ipWb1xgjVuikLDRTYAXr&#xD;\n0NqbDdeBozAdPNVvicrGpg61J0Un6r5zjnkMFfS6SpM4bFjVAkAuwbz3DLlCTitGCX1nBzGVx3t7&#xD;\nJI7LpLG17+GTRNPlwhND7ckxiQ2J8BzDda8GHyxM8ia4+vZOL6BwSgboajo3AkAsiTjkYDzzXGmn&#xD;\n+yB1c7+JqdVUqQyuHEBRfWhGNSsZnw/rl1HpchgybsbYG/DDURUaSCWdHo52EaczrElODhtFAkAU&#xD;\n95df+umPXSwSzFaSCVVaGm7QlH8yBx8nFHF+yeFPV5QmDWmj59Y9UM6vM4MHtUAdpEhIzzAoI/Et&#xD;\nlMA4EBbB&#xD;\n-----END PRIVATE KEY-----\n</key>\n    <secret_access_key>7COhvBzxrz2agtOPgk3bZM7W3ej9QI/j6WvYiHdg</secret_access_key>\n  </ec2_credentials>\n</provider_credentials>\n</provider_account>\n</provider_accounts>\n', 'image': '8d4da86e-2e74-4dcc-bada-359ebc8531c6', 'build': '', 'providers': ['ec2-us-east-1']} 
 handle = <cqmf2.AgentEvent; proxy of <Swig Object of type 'qmf::AgentEvent *' at 0x2e7e5d0> > 
 addr = redhat.com:imagefactory:b1688e42-f6f5-42d4-aa19-fbb17eb92fbf:image_factory 
 subtypes = {} 
 userId = anonymous
2011-06-23 17:02:45,726 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Getting metadata (['latest_unpushed']) from http://localhost:9090/images/8d4da86e-2e74-4dcc-bada-359ebc8531c6
2011-06-23 17:02:45,728 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Querying (http://localhost:9090/target_images/_query) with expression ($build == "e8ddcbdd-5e32-4e55-8bbc-a113021c1a6f" && $target == "ec2")
2011-06-23 17:02:45,731 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Getting metadata (['template']) from http://localhost:9090/target_images/57b8bffc-fa83-4d22-b22c-7e8a3cb01244
2011-06-23 17:02:45,732 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-06-23 17:02:45,735 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Created Image Warehouse instance http://localhost:9090 - buckets(target_images, templates, icicles, provider_images)
2011-06-23 17:02:45,743 DEBUG oz.Guest.FedoraRemoteGuest pid(22672) Message: Name: template01, UUID: 5501ce12-cf71-4911-8396-1fc7d037dee6
2011-06-23 17:02:45,744 DEBUG oz.Guest.FedoraRemoteGuest pid(22672) Message: MAC: 52:54:00:29:77:6b, distro: Fedora
2011-06-23 17:02:45,744 DEBUG oz.Guest.FedoraRemoteGuest pid(22672) Message: update: 14, arch: x86_64, diskimage: /var/tmp/template01.dsk
2011-06-23 17:02:45,744 DEBUG oz.Guest.FedoraRemoteGuest pid(22672) Message: nicmodel: virtio, clockoffset: utc
2011-06-23 17:02:45,744 DEBUG oz.Guest.FedoraRemoteGuest pid(22672) Message: mousetype: ps2, disk_bus: virtio, disk_dev: vda
2011-06-23 17:02:45,744 DEBUG oz.Guest.FedoraRemoteGuest pid(22672) Message: icicletmp: /var/lib/oz/icicletmp/template01, listen_port: 17810
2011-06-23 17:02:45,744 DEBUG oz.Guest.FedoraRemoteGuest pid(22672) Message: Original ISO path: /var/lib/oz/isos/Fedora14x86_64-url.iso
2011-06-23 17:02:45,744 DEBUG oz.Guest.FedoraRemoteGuest pid(22672) Message: Modified ISO cache: /var/lib/oz/isos/Fedora14x86_64-url-oz.iso
2011-06-23 17:02:45,745 DEBUG oz.Guest.FedoraRemoteGuest pid(22672) Message: Output ISO path: /var/tmp/template01-url-oz.iso
2011-06-23 17:02:45,745 DEBUG oz.Guest.FedoraRemoteGuest pid(22672) Message: ISO content path: /var/lib/oz/isocontent/template01-url
2011-06-23 17:02:48,463 DEBUG oz.Guest.FedoraRemoteGuest pid(22672) 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-06-23 17:02:48,463 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Being asked to push for provider ec2-us-east-1
2011-06-23 17:02:48,463 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: distro: Fedora - update: 14 - arch: x86_64
2011-06-23 17:02:48,465 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: acting as EC2 user: 6735-0069-5950
2011-06-23 17:02:48,466 DEBUG imagefactory.BuildJob.BuildAdaptor pid(22672) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from NEW to PUSHING
2011-06-23 17:02:48,466 DEBUG imagefactory.BuildJob.BuildAdaptor pid(22672) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 0 to 0
2011-06-23 17:02:48,467 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Starting ami ami-d6b946bf with instance_type m1.large
2011-06-23 17:02:48,789 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Creating temporary security group (imagefactory-41d97db0-ce8f-4698-819e-13a7fc3fb770)
2011-06-23 17:02:49,926 WARNING boto pid(22672) Message: Error converting code (pending) to int
2011-06-23 17:02:59,937 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Waiting for EC2 instance to start: 0/300
2011-06-23 17:03:10,050 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Waiting for EC2 instance to start: 10/300
2011-06-23 17:03:20,145 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Waiting for EC2 instance to start: 20/300
2011-06-23 17:03:30,240 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Waiting for EC2 instance to start: 30/300
2011-06-23 17:03:30,576 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Waiting up to 300 seconds for ssh to become available on ec2-50-16-102-48.compute-1.amazonaws.com
2011-06-23 17:03:30,576 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Waiting for EC2 ssh access: 0/300
2011-06-23 17:03:45,703 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Waiting for EC2 ssh access: 10/300
2011-06-23 17:03:59,427 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Waiting for EC2 ssh access: 20/300
2011-06-23 17:04:00,287 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Waiting 20 seconds for remaining boot tasks
2011-06-23 17:04:20,308 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Removing utility package and repo
2011-06-23 17:04:23,340 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Removal complete
2011-06-23 17:04:23,341 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Customizing guest: ec2-50-16-102-48.compute-1.amazonaws.com
2011-06-23 17:04:23,342 DEBUG oz.Guest.FedoraRemoteGuest pid(22672) Message: Installing additional repository files
2011-06-23 17:04:24,930 DEBUG oz.Guest.FedoraRemoteGuest pid(22672) Message: Installing custom packages
2011-06-23 17:04:24,930 INFO oz.Guest.FedoraRemoteGuest pid(22672) Message: Uploading custom files
2011-06-23 17:04:24,930 DEBUG oz.Guest.FedoraRemoteGuest pid(22672) Message: Syncing
2011-06-23 17:04:25,680 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Customization step complete
2011-06-23 17:04:25,680 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Generating ICICLE from customized guest
2011-06-23 17:04:27,031 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: ICICLE generation complete
2011-06-23 17:04:27,031 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Re-de-activate firstboot just in case it has been revived during customize
2011-06-23 17:04:27,756 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: De-activation complete
2011-06-23 17:04:27,756 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Uploading cert material
2011-06-23 17:04:32,658 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Cert upload complete
2011-06-23 17:04:32,658 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Executing bundle vol command: euca-bundle-vol -c /tmp/tmpTxbj_F -k /tmp/tmp5D2dr4 -u 6735-0069-5950 -e /mnt,/tmp,/root/.ssh --arch x86_64 -d /mnt/bundles --kernel aki-427d952b -p 41d97db0-ce8f-4698-819e-13a7fc3fb770 -s 10240 --ec2cert /tmp/cert-ec2.pem --fstab /etc/fstab -v /
2011-06-23 17:08:43,921 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Bundle output: Filesystem label=/
OS type: Linux
Block size=4096 (log=2)
Fragment size=4096 (log=2)
Stride=0 blocks, Stripe width=0 blocks
655360 inodes, 2621440 blocks
131072 blocks (5.00%) reserved for the super user
First data block=0
Maximum filesystem blocks=2684354560
80 block groups
32768 blocks per group, 32768 fragments per group
8192 inodes per group
Superblock backups stored on blocks: 
	32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632

Writing inode tables: done                            
Creating journal (32768 blocks): done
Writing superblocks and filesystem accounting information: done

This filesystem will be automatically checked every 30 mounts or
180 days, whichever comes first.  Use tune2fs -c or -i to override.
Unable to read ramdisk id
Unable to read product codes
Unable to read product codes
['blkid', '-sFS_TYPE', '-ovalue', '/tmp/tmpn3Q0dw/dev']
['blkid', '-sUUID', '-ovalue', '/tmp/tmpn3Q0dw/dev']
['blkid', '-sLABEL', '-ovalue', '/tmp/tmpn3Q0dw/dev']
Warning: rsync reports files partially copied:
('', 'rsync: rsync_xal_clear: lremovexattr("etc/ld.so.conf.d/.libc6-xen.conf.pU8PSp","security.selinux") failed: Permission denied (13)\nrsync: rsync_xal_clear: lremovexattr("etc/sysconfig/.cloud-info.BnSZgC","security.selinux") failed: Permission denied (13)\nrsync: rsync_xal_clear: lremovexattr("var/cache/ldconfig/.aux-cache.IjN1Lu","security.selinux") failed: Permission denied (13)\nrsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1042) [sender=3.0.7]\n')
Checking image
Encrypting image
Splitting image...
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.00
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.01
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.02
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.03
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.04
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.05
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.06
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.07
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.08
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.09
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.10
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.11
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.12
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.13
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.14
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.15
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.16
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.17
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.18
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.19
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.20
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.21
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.22
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.23
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.24
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.25
Part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.26
Generating manifest /mnt/bundles/41d97db0-ce8f-4698-819e-13a7fc3fb770.manifest.xml

2011-06-23 17:08:48,436 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Executing upload bundle command: euca-upload-bundle -b imagefactory-ec2-us-east-1-6735-0069-5950 -m /mnt/bundles/41d97db0-ce8f-4698-819e-13a7fc3fb770.manifest.xml --ec2cert /tmp/cert-ec2.pem -a "AKIAJ557U7P7OIHRV2EQ" -s "7COhvBzxrz2agtOPgk3bZM7W3ej9QI/j6WvYiHdg" -U http://s3.amazonaws.com/
2011-06-23 17:09:12,080 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Upload output: Checking bucket: imagefactory-ec2-us-east-1-6735-0069-5950
Uploading manifest file
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.00
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.01
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.02
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.03
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.04
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.05
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.06
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.07
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.08
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.09
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.10
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.11
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.12
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.13
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.14
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.15
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.16
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.17
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.18
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.19
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.20
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.21
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.22
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.23
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.24
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.25
Uploading part: 41d97db0-ce8f-4698-819e-13a7fc3fb770.part.26
Uploaded image as imagefactory-ec2-us-east-1-6735-0069-5950/41d97db0-ce8f-4698-819e-13a7fc3fb770.manifest.xml

2011-06-23 17:09:12,080 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Executing register command: euca-register -U http://ec2.us-east-1.amazonaws.com/ -A "AKIAJ557U7P7OIHRV2EQ" -S "7COhvBzxrz2agtOPgk3bZM7W3ej9QI/j6WvYiHdg" imagefactory-ec2-us-east-1-6735-0069-5950/41d97db0-ce8f-4698-819e-13a7fc3fb770.manifest.xml
2011-06-23 17:09:13,690 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Register output: IMAGE	ami-264bb34f

2011-06-23 17:09:13,692 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Extracted AMI ID: ami-264bb34f 
2011-06-23 17:09:13,695 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(22672) 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-06-23 17:09:13,698 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Setting metadata ({'object_type': 'icicle', 'uuid': '1a50212d-5cbb-4765-a037-c674ed12c307'}) for http://localhost:9090/icicles/1a50212d-5cbb-4765-a037-c674ed12c307
2011-06-23 17:09:13,780 INFO imagefactory.ImageWarehouse.ImageWarehouse pid(22672) 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-06-23 17:09:13,783 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Setting metadata ({'target_image': '57b8bffc-fa83-4d22-b22c-7e8a3cb01244', 'uuid': '41d97db0-ce8f-4698-819e-13a7fc3fb770', 'icicle': '1a50212d-5cbb-4765-a037-c674ed12c307', 'target_identifier': 'ami-264bb34f', 'object_type': 'provider_image', 'provider': 'ec2-us-east-1'}) for http://localhost:9090/provider_images/41d97db0-ce8f-4698-819e-13a7fc3fb770
2011-06-23 17:09:14,029 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: Stopping EC2 instance and deleting temp security group
2011-06-23 17:09:18,577 DEBUG imagefactory.builders.BaseBuilder.FedoraBuilder pid(22672) Message: FedoraBuilder instance 48758672 pushed image with uuid 57b8bffc-fa83-4d22-b22c-7e8a3cb01244 to provider_image UUID (41d97db0-ce8f-4698-819e-13a7fc3fb770) and set metadata: {'target_image': '57b8bffc-fa83-4d22-b22c-7e8a3cb01244', 'target_identifier': 'ami-264bb34f', 'icicle': '1a50212d-5cbb-4765-a037-c674ed12c307', 'provider': 'ec2-us-east-1'}
2011-06-23 17:09:18,578 DEBUG imagefactory.BuildJob.BuildAdaptor pid(22672) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed percent complete from 0 to 100
2011-06-23 17:09:18,579 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Setting metadata ({'latest_build': 'e8ddcbdd-5e32-4e55-8bbc-a113021c1a6f'}) for http://localhost:9090/images/8d4da86e-2e74-4dcc-bada-359ebc8531c6
2011-06-23 17:09:18,581 DEBUG imagefactory.ImageWarehouse.ImageWarehouse pid(22672) Message: Setting metadata ({'latest_unpushed': None}) for http://localhost:9090/images/8d4da86e-2e74-4dcc-bada-359ebc8531c6
2011-06-23 17:09:18,622 DEBUG imagefactory.BuildJob.BuildAdaptor pid(22672) Message: Raising event with agent handler (<ImageFactoryAgent(Thread-1, initial)>), changed status from PUSHING to COMPLETED


[root@ibm-x3950m2-01 noarch]# rpm -qa | grep aeolus
aeolus-conductor-0.3.0-0.el6.20110623205403git551632a.noarch
aeolus-configure-2.0.1-0.el6.20110622123902gitdf4ae05.noarch
aeolus-conductor-doc-0.3.0-0.el6.20110623205403git551632a.noarch
aeolus-all-0.3.0-0.el6.20110623205403git551632a.noarch
rubygem-aeolus-cli-0.0.1-1.el6.20110623205403git551632a.noarch
aeolus-conductor-daemons-0.3.0-0.el6.20110623205403git551632a.noarch
aeolus-conductor-devel-0.3.0-0.el6.20110623205403git551632a.noarch
[root@ibm-x3950m2-01 noarch]#
Comment 4 wes hayutin 2011-08-01 19:54:54 UTC 
release pending...
Comment 5 wes hayutin 2011-08-01 19:56:45 UTC 
release pending...
Comment 7 wes hayutin 2011-12-08 13:49:16 UTC 
perm close