Bug 1364350

Summary: Unexpected error when clicked on service request
Product: Red Hat CloudForms Management Engine Reporter: Aziza Karol <akarol>
Component: AutomateAssignee: mkanoor
Status: CLOSED CURRENTRELEASE QA Contact: Jeff Teehan <jteehan>
Severity: high Docs Contact:
Priority: high    
Version: 5.6.0CC: akarol, dajohnso, hkataria, jhardy, jocarter, mkanoor, mpovolny, obarenbo, simaishi, tfitzger
Target Milestone: GAKeywords: TestOnly, ZStream
Target Release: 5.7.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: provisioning
Fixed In Version: 5.7.0.0 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1376513 (view as bug list) Environment:
Last Closed: 2017-01-11 20:16:10 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: Bug
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1376513    
Attachments:
Description Flags
err none

Description Aziza Karol 2016-08-05 07:31:27 UTC 
Description of problem:


Version-Release number of selected component (if applicable):
5.6.1.0.20160726144018_810a94f 

How reproducible:
100%

Steps to Reproduce:
1.Enforce the quota and provision a scvmm VM
2.Navigate to service->request and click on the request to get the detail page
3.

Actual results:
Method exited with rc=Unknown RC: [1] [miq_request/show]  displayed in UI. see attached screenshot

Note:
I tried clicking the service request provisioned  with other providers, request detail page gets displayed.

Expected results:


Additional info:
evm.log
og_name_prefix]> Starting 
[----] E, [2016-08-05T03:24:43.991550 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: The following error occurred during inline method preamble evaluation:
[----] E, [2016-08-05T03:24:43.991819 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR:   DRb::DRbConnError: druby://127.0.0.1:40243 - #<Errno::ECONNREFUSED: Connection refused - connect(2) for "127.0.0.1" port 40243>
[----] E, [2016-08-05T03:24:43.991920 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR:   /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:744:in `rescue in block in open'
[----] E, [2016-08-05T03:24:43.991998 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:738:in `block in open'
[----] E, [2016-08-05T03:24:43.992088 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:737:in `each'
[----] E, [2016-08-05T03:24:43.992163 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:737:in `open'
[----] E, [2016-08-05T03:24:43.992231 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1248:in `initialize'
[----] E, [2016-08-05T03:24:43.992308 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1228:in `new'
[----] E, [2016-08-05T03:24:43.992381 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1228:in `open'
[----] E, [2016-08-05T03:24:43.992467 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1141:in `block in method_missing'
[----] E, [2016-08-05T03:24:43.992562 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1160:in `with_friend'
[----] E, [2016-08-05T03:24:43.992649 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1140:in `method_missing'
[----] E, [2016-08-05T03:24:43.992746 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: -:31:in `<main>'
[----] E, [2016-08-05T03:24:43.992850 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:744:in `rescue in block in open': druby://127.0.0.1:40243 - #<Errno::ECONNREFUSED: Connection refused - connect(2) for "127.0.0.1" port 40243> (DRb::DRbConnError)
[----] E, [2016-08-05T03:24:43.992942 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:738:in `block in open'
[----] E, [2016-08-05T03:24:43.993028 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:737:in `each'
[----] E, [2016-08-05T03:24:43.993121 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:737:in `open'
[----] E, [2016-08-05T03:24:43.993203 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1248:in `initialize'
[----] E, [2016-08-05T03:24:43.993283 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1228:in `new'
[----] E, [2016-08-05T03:24:43.993364 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1228:in `open'
[----] E, [2016-08-05T03:24:43.993475 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1141:in `block in method_missing'
[----] E, [2016-08-05T03:24:43.993573 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1160:in `with_friend'
[----] E, [2016-08-05T03:24:43.993655 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1140:in `method_missing'
[----] E, [2016-08-05T03:24:43.993788 #3030:1149960] ERROR -- : <AutomationEngine> Method STDERR: 	from -:31:in `<main>'
[----] I, [2016-08-05T03:24:44.055854 #3030:15140cc]  INFO -- : <AutomationEngine> <AEMethod [/ManageIQ/System/Process/parse_provider_category]> Ending
[----] E, [2016-08-05T03:24:44.056593 #3030:15140cc] ERROR -- : <AutomationEngine> Aborting instantiation (unknown method return code) because [Method exited with rc=Unknown RC: [1]]
[----] I, [2016-08-05T03:24:44.142651 #2776:fa3994]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-08-05 07:24:44 UTC]...
[----] I, [2016-08-05T03:24:44.192214 #2776:fa3994]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-08-05 07:24:44 UTC]...Complete
[----] I, [2016-08-05T03:24:44.203202 #2776:fa3994]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] E, [2016-08-05T03:24:44.273316 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: The following error occurred during inline method preamble evaluation:
[----] E, [2016-08-05T03:24:44.273643 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR:   DRb::DRbConnError: druby://127.0.0.1:45593 - #<Errno::ECONNREFUSED: Connection refused - connect(2) for "127.0.0.1" port 45593>
[----] E, [2016-08-05T03:24:44.273817 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR:   /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:744:in `rescue in block in open'
[----] E, [2016-08-05T03:24:44.273950 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:738:in `block in open'
[----] E, [2016-08-05T03:24:44.274055 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:737:in `each'
[----] E, [2016-08-05T03:24:44.274149 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:737:in `open'
[----] E, [2016-08-05T03:24:44.274247 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1248:in `initialize'
[----] E, [2016-08-05T03:24:44.274350 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1228:in `new'
[----] E, [2016-08-05T03:24:44.274456 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1228:in `open'
[----] E, [2016-08-05T03:24:44.274587 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1141:in `block in method_missing'
[----] E, [2016-08-05T03:24:44.274684 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1160:in `with_friend'
[----] E, [2016-08-05T03:24:44.274821 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1140:in `method_missing'
[----] E, [2016-08-05T03:24:44.274925 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: -:31:in `<main>'
[----] E, [2016-08-05T03:24:44.275019 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:744:in `rescue in block in open': druby://127.0.0.1:45593 - #<Errno::ECONNREFUSED: Connection refused - connect(2) for "127.0.0.1" port 45593> (DRb::DRbConnError)
[----] E, [2016-08-05T03:24:44.275116 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:738:in `block in open'
[----] E, [2016-08-05T03:24:44.275228 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:737:in `each'
[----] E, [2016-08-05T03:24:44.275328 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:737:in `open'
[----] E, [2016-08-05T03:24:44.275423 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1248:in `initialize'
[----] E, [2016-08-05T03:24:44.275527 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1228:in `new'
[----] E, [2016-08-05T03:24:44.275632 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1228:in `open'
[----] E, [2016-08-05T03:24:44.275759 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1141:in `block in method_missing'
[----] E, [2016-08-05T03:24:44.275879 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1160:in `with_friend'
[----] E, [2016-08-05T03:24:44.275979 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: 	from /opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1140:in `method_missing'
[----] E, [2016-08-05T03:24:44.276070 #3030:933a5f0] ERROR -- : <AutomationEngine> Method STDERR: 	from -:31:in `<main>'
[----] I, [2016-08-05T03:24:44.324522 #3030:1516160]  INFO -- : <AutomationEngine> <AEMethod [/ManageIQ/Infrastructure/VM/Provisioning/Profile/vm_dialog_name_prefix]> Ending
[----] E, [2016-08-05T03:24:44.324940 #3030:1516160] ERROR -- : <AutomationEngine> Aborting instantiation (unknown method return code) because [Method exited with rc=Unknown RC: [1]]
[----] E, [2016-08-05T03:24:44.325227 #3030:1516160] ERROR -- : <AutomationEngine> Aborting instantiation (unknown method return code) because [Method exited with rc=Unknown RC: [1]]
[----] E, [2016-08-05T03:24:44.325520 #3030:1516160] ERROR -- : <AutomationEngine> Aborting instantiation (unknown method return code) because [Method exited with rc=Unknown RC: [1]]
Comment 2 Aziza Karol 2016-08-05 07:32:01 UTC 
Created attachment 1187790 [details]
err
Comment 3 mkanoor 2016-08-11 14:21:09 UTC 
Hi Aziza,
Can you provide the evm.log and automation.log?
Thanks,
Madhu
Comment 4 Dave Johnson 2016-08-12 15:52:40 UTC 
Removed scvmm from the summary as we believe this is the case with all provisioning requests.  Aziza, can you see if that is true with some other provider provision requests please.
Comment 6 Aziza Karol 2016-08-12 16:33:09 UTC 
Dave,

This error occurs when you double click on all provider's provisioning request.

Thanks,
~Aziza
Comment 7 mkanoor 2016-08-12 17:45:23 UTC 
This error is happening because when you double click it is sending back to back Automate Requests which are stomping on the DRb variables. We had put a mutex around the MiqAeEngine.deliver call now it seems like we would either have to put a mutex around MiqAeEngine.resolve_automation_object or make DRb thread safe.

This all started in 5.6 with Rails 5, PUMA web server serves up multiple concurrent requests.

We have fixed a similar issue with dynamic dialogs.
https://bugzilla.redhat.com/show_bug.cgi?id=1354054
Comment 10 mkanoor 2016-09-21 20:29:04 UTC 
This has been fixed in 5.7 via PR's
https://github.com/ManageIQ/manageiq/pull/10135
https://github.com/ManageIQ/manageiq/pull/10004
Comment 11 Jeff Teehan 2016-09-22 18:43:25 UTC 
I doubled clicked on everything, included a newly provisioned scvmm vm.  Working as required using 5.7.0.2.20160921112913_c5ff117 on 10.16.6.191

Moving to verified.