| Summary: | Invalid EC2 zone error message not indicative of the problem. | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [Retired] CloudForms Cloud Engine | Reporter: | Joe Vlcek <jvlcek> | ||||
| Component: | aeolus-conductor | Assignee: | Michal Fojtik <mfojtik> | ||||
| Status: | CLOSED ERRATA | QA Contact: | wes hayutin <whayutin> | ||||
| Severity: | medium | Docs Contact: | |||||
| Priority: | unspecified | ||||||
| Version: | 1.0.0 | CC: | akarol, dajohnso, deltacloud-maint, dgao, jprovazn, rlandy, ssachdev | ||||
| Target Milestone: | rc | ||||||
| Target Release: | --- | ||||||
| Hardware: | Unspecified | ||||||
| OS: | Unspecified | ||||||
| Whiteboard: | |||||||
| Fixed In Version: | r1227194 | Doc Type: | Bug Fix | ||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | Environment: | ||||||
| Last Closed: | 2012-05-15 22:14:24 UTC | Type: | --- | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Attachments: |
|
||||||
The is related to error handling in conductor-core. In short, message "malformed format string - %A" is generated by deltacloud-core when deltacloud-core is running in production mode -> assigning this bug to Michal. This is probably because @error.message in view /usr/share/deltacloud-core/views/errors/502.xml.haml is not set. Can I get a full deltacloud-core log please?
I want to know the origin of this error message. Is this 'malformed format string - %A' coming from EC2 and passed in 'message'? Deltacloud should pass:
"Invalid availability zone: [us-east-1a]" in message.
The message in 502.xml.haml should be always set:
%message< #{cdata @error.message}
+ according to chunk Joe sent it's error '500' not '502' ;) I wasn't able to reproduce same situation as Joe's "unavailable realm", but I'm getting same error when running dbomatic - 500 and 502 views are very similar.
(shouldn't be problem to raise the error from deltacloudd code)
content of response is:
"<error status='500' url='/api/instances/i-b14f0ed2'>\n <kind>backend_error</kind>\n <backend driver='ec2'>\n <code>500</code>\n </backend>\n <message><![CDATA[malformed format string - %A]]></message>\n</error>\n"
deltacloudd output:
Processing /api/instances/i-b14f0ed2 (for 127.0.0.1 at Wed Dec 07 16:39:04 +0100 2011) [GET] [EC2]
/usr/bin/deltacloudd[18993]: Parameters: {}
/usr/bin/deltacloudd[18993]: Provider: us-east-1
/usr/bin/deltacloudd[18993]: Authentication: Basic
/usr/bin/deltacloudd[18993]: Server: thin 1.2.11 codename Bat-Shit Crazy
/usr/bin/deltacloudd[18993]: Accept: application/xml
/usr/bin/deltacloudd[18993]: /usr/lib/ruby/gems/1.8/gems/aws-2.5.5/lib/ses/../awsbase/utils.rb:105: warning: already initialized constant HEX
/usr/bin/deltacloudd[18993]: /usr/lib/ruby/gems/1.8/gems/aws-2.5.5/lib/ses/../awsbase/utils.rb:107: warning: already initialized constant TO_REMEMBER
/usr/bin/deltacloudd[18993]: /usr/lib/ruby/gems/1.8/gems/aws-2.5.5/lib/ses/../awsbase/utils.rb:108: warning: already initialized constant ASCII
/usr/bin/deltacloudd[18993]: /usr/lib/ruby/gems/1.8/gems/aws-2.5.5/lib/ses/../awsbase/errors.rb:128: warning: already initialized constant DEFAULT_CLOSE_ON_4XX_PROBABILITY
/usr/bin/deltacloudd[18993]: /usr/lib/ruby/gems/1.8/gems/aws-2.5.5/lib/ses/../awsbase/parsers.rb:47: warning: already initialized constant DEFAULT_XML_LIBRARY
/usr/bin/deltacloudd[18993]: /usr/lib/ruby/gems/1.8/gems/aws-2.5.5/lib/ses/../awsbase/awsbase.rb:66: warning: already initialized constant AMAZON_PROBLEMS
/usr/bin/deltacloudd[18993]: /usr/lib/ruby/gems/1.8/gems/aws-2.5.5/lib/ses/../awsbase/awsbase.rb:86: warning: already initialized constant DEFAULT_SIGNATURE_VERSION
I, [2011-12-07T16:39:04.848256 #18993] INFO -- : New Aws::Ec2 using per_thread-connection mode
I, [2011-12-07T16:39:04.861323 #18993] INFO -- : Opening new HTTPS connection to ec2.us-east-1.amazonaws.com:443
/usr/bin/deltacloudd[18993]:
Processing /api/instances/inst72 (for 127.0.0.1 at Wed Dec 07 16:39:04 +0100 2011) [GET] [Mock]
/usr/bin/deltacloudd[18993]: Parameters: {}
/usr/bin/deltacloudd[18993]: Provider:
/usr/bin/deltacloudd[18993]: Authentication: Basic
/usr/bin/deltacloudd[18993]: Server: thin 1.2.11 codename Bat-Shit Crazy
/usr/bin/deltacloudd[18993]: Accept: application/xml
/usr/bin/deltacloudd[18993]:
Completed in 0.000388 | 0.000000 | 404 | application/xml | http://localhost:3002/api/instances/inst72
/usr/bin/deltacloudd[18993]: 127.0.0.1 - - [07/Dec/2011 16:39:05] "GET /api/instances/inst72 HTTP/1.1" 404 98 0.3474
W, [2011-12-07T16:39:05.590851 #18993] WARN -- : ##### Aws::Ec2 returned an error: 400 Bad Request
<?xml version="1.0" encoding="UTF-8"?>
<Response><Errors><Error><Code>InvalidInstanceID.NotFound</Code><Message>The instance ID 'i-b14f0ed2' does not exist</Message></Error></Errors><RequestID>79b6a333-ca2f-45dc-8c2d-68fe0983106e</RequestID></Response> #####
W, [2011-12-07T16:39:05.590955 #18993] WARN -- : ##### Aws::Ec2 request: ec2.us-east-1.amazonaws.com:443/?AWSAccessKeyId=AKIAJDNGKF2QAIF5HCSQ&Action=DescribeInstances&InstanceId.1=i-b14f0ed2&SignatureMethod=HmacSHA256&SignatureVersion=2&Timestamp=2011-12-07T15%3A39%3A04.000Z&Version=2010-08-31&Signature=kmGD9tiT5Z7x6h39Lzt5V4Amc5M8nyqejmbOZBA6ZlU%3D ####
/usr/bin/deltacloudd[18993]:
Completed in 0.000000 | 0.000000 | 500 | application/xml | http://localhost:3002/api/instances/i-b14f0ed2
/usr/bin/deltacloudd[18993]: 127.0.0.1 - - [07/Dec/2011 16:39:05] "GET /api/instances/i-b14f0ed2 HTTP/1.1" 500 212 0.8908
spent some time now with this:
problem can be reproduced when you try to get any not existing ec2 instance, example from conductor rails console:
> ProviderAccount.first.connect.instance('i-b14f0ed2')
problem is caused by syslog logging in DC - syslog inteprets "%" in a message as sprintf substitution symbol, so then "malformed format string - %A". This fix worked for me:
diff --git a/server/lib/sinatra/rack_syslog.rb b/server/lib/sinatra/rack_syslog.rb
index f515afb..f7c3d53 100644
--- a/server/lib/sinatra/rack_syslog.rb
+++ b/server/lib/sinatra/rack_syslog.rb
@@ -13,11 +13,11 @@ class SyslogFile < File
end
def info(msg)
- @log.info(msg)
+ @log.info("%s", msg)
end
def err(msg)
- @log.err(msg)
+ @log.err("%s", msg)
end
alias :warning :err
Michal: can you please get the patch for this into DC?
here is also some nice info: http://labs.animoto.com/2008/08/20/ruby-syslog-considered-harmful-or-at-least-undocumented/ Unstaged changes after reset: M server/lib/sinatra/rack_syslog.rb M server/lib/sinatra/rack_syslog.rb Committed r1227194 M server/lib/sinatra/rack_syslog.rb r1227194 = bd5de1d3991dd97fd5e771b76f90001f78268618 (refs/remotes/trunk) No changes between current HEAD and refs/remotes/trunk Resetting to the latest refs/remotes/trunk adding to ce-sprint removing ce-sprint-next tracker Verified that Conductor now displays the correct message when an EC2 zone is unavailable/invalid:
Warnings
Failed to launch following component blueprints:
Errors
500 : Unhandled exception or status code (us-east-one-hello temporarily unavailable: (getaddrinfo: Name or service not known))
This is the same error returned by Deltacloud.
rpm -qa |grep deltacloud
rpm -qa |grep aeolus
deltacloud-core-vsphere-0.5.0-5.el6.noarch
deltacloud-core-ec2-0.5.0-5.el6.noarch
deltacloud-core-rhevm-0.5.0-5.el6.noarch
deltacloud-core-0.5.0-5.el6.noarch
rubygem-deltacloud-client-0.5.0-2.el6.noarch
[root@hp-dl360g5-02 workspace]# \rpm -qa |grep aeolus
aeolus-all-0.8.0-35.el6.noarch
aeolus-conductor-0.8.0-35.el6.noarch
aeolus-configure-2.5.0-15.el6.noarch
aeolus-conductor-doc-0.8.0-35.el6.noarch
rubygem-aeolus-image-0.3.0-9.el6.noarch
aeolus-conductor-daemons-0.8.0-35.el6.noarch
rubygem-aeolus-cli-0.3.0-10.el6.noarch
(See attached screenshot)
Created attachment 566136 [details]
error with unavailable ec2 Zone
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. http://rhn.redhat.com/errata/RHEA-2012-0583.html |
Description of problem: The error message displayed in Conductor when an EC2 zone is unavailable is cryptic and not indicative of the problem. - Using Conductor to launch a deployment with an unavailable zone specified in the Realm results in the following message being displayed in Conductor: Failed to launch following assemblies: JoeAssembly: malformed format string - %A The deltacloud log: /var/log/deltacloud-core/mock.log contains the below text indicating the problem is the zone is not available. I, [2011-10-05T09:31:35.422013 #30572] INFO -- : Opening new HTTPS connection to ec2.us-east-1.amazonaws.com:443 W, [2011-10-05T09:31:35.947688 #30572] WARN -- : ##### Aws::Ec2 returned an error: 400 Bad Request <?xml version="1.0" encoding="UTF-8"?> <Response><Errors><Error><Code>InvalidParameterValue</Code><Message>Invalid availability zone: [us-east-1a]</Mess/usr/bin/deltacloudd[30572]: 127.0.0.1 - - [05/Oct/2011 09:31:35] "POST /api/instances HTTP/1.1" 500 201 0.5324 The error message displayed in Conductor should implicate the unavailable zone. Version-Release number of selected component (if applicable): How reproducible: - Using Conductor to launch a deployment with an unavailable zone specified in the Realm results in the following message being displayed in Conductor: Steps to Reproduce: 1. In Conductor Configure a Realm w/and unavailable EC2 zone 2. Launch a deployment using the Realm with the unavailable zone. Actual results: Error message is: Failed to launch following assemblies: JoeAssembly: malformed format string - %A Expected results: An error message similar to: Failed to launch following assemblies: JoeAssembly: Invalid availability zone: [us-east-1a] Additional info: