<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:
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.
moving to on_qa for review
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
\nrWXKgkWueOffs6f3eF3MpLoKS5b3BH7ijq0HJqgNPCVhDf+F4+JyM/h6BLbotyhYINmCf1SJpVXm
\nkp+ABo3y7KxIyx5xAUhoDQCbIed37hEE4GvGNNE9qkO3fxG4ejlyN4kSo2OQZtHeZqq7AgMBAAEC
\ngYByI9mXZoRPET++5/mB2IpRlT84Z8C1od/eOJkk63kNtfEVpfadoZhPuNHyzdM7TgH7cHHNybn7
\n+Jt6KXI/ar1QDIse7S+xU700AWJVaUt3FqlrglmGT018oGWqH1/3D9/4yVsdvxCKcKYuvre3j2gU
\nsi7uJPpWYqCLhs41EuIUiQJBAPcuRXEtVV5MJipuYljERZHfxT4Yh/b8agfr1dsrHvd4jly9rJnE
\nIwB3vn0mMS9Fs/f0rUc3RAZRSrsuwYravU8CQQCLl+YDqZOwVfZIkJO2ipWb1xgjVuikLDRTYAXr
\n0NqbDdeBozAdPNVvicrGpg61J0Un6r5zjnkMFfS6SpM4bFjVAkAuwbz3DLlCTitGCX1nBzGVx3t7
\nJI7LpLG17+GTRNPlwhND7ckxiQ2J8BzDda8GHyxM8ia4+vZOL6BwSgboajo3AkAsiTjkYDzzXGmn
\n+yB1c7+JqdVUqQyuHEBRfWhGNSsZnw/rl1HpchgybsbYG/DDURUaSCWdHo52EaczrElODhtFAkAU
\n95df+umPXSwSzFaSCVVaGm7QlH8yBx8nFHF+yeFPV5QmDWmj59Y9UM6vM4MHtUAdpEhIzzAoI/Et
\nlMA4EBbB
\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]#
release pending...
perm close