Bug 1298292 - create_provision_request drb method missing error
create_provision_request drb method missing error
Status: CLOSED INSUFFICIENT_DATA
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: Automate (Show other bugs)
5.5.0
Unspecified Unspecified
medium Severity medium
: GA
: 5.6.0
Assigned To: Tina Fitzgerald
Dave Johnson
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2016-01-13 11:31 EST by Josh Carter
Modified: 2016-03-09 14:57 EST (History)
7 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-03-09 14:57:00 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
Screen shot service with 2 VMs when one was requested (59.19 KB, image/png)
2016-01-18 22:26 EST, Rich
no flags Details
User Account from LDAP creating service request (26.35 KB, image/png)
2016-01-18 22:28 EST, Rich
no flags Details

  None (edit)
Comment 4 Greg McCullough 2016-01-13 14:07:40 EST
Tina - Please work with Billy to recreate this issue.
Comment 5 Tina Fitzgerald 2016-01-15 13:45:58 EST
Hi Josh,

The reason for the error appears to be an invalid user, user_name=qo386420 passed as an argument to the create_provision_request method.

The automation.log error is very misleading. The evm.log shows the real error: 
MIQ(MiqProvisionVirtWorkflow.from_ws_ver_1_x) <Couldn't find User with [WHERE "users"."region" = ? AND "users"."userid" = ?]>

The create_provision_request method should have reported the invalid user. 
While we're working on a fix to the method, could you ask the customer to check if the user: qo386420 is valid?

Thanks,
Tina

evm.log.....
[----] I, [2016-01-12T10:15:55.209285 #2993:58e8014] INFO -- : Q-task_id([service_template_provision_task_1000000000052]) <AutomationEngine> <AEMethod vmware_build_vmprovision_request> Build: 1 - Building provision request with the following arguments: ["1.1", "name=CF-Centos6-stdfs|guid=c6a93884-a8ca-11e5-b617-005056834234", "vm_name=tttttt|number_of_vms=1|provision_type=vmware|cores_per_socket=1|vm_memory=512|retirement=172800|retirement_warn=86400", "user_name=qo386420|owner_first_name=Rich|owner_last_name=Caldwell|owner_email=Rich.Caldwell@sprint.com", "environment=test|role=app|flex_monitor=false|flavor=xsmall", "service_name=Test_as_Admin_User|dialog_service_name=Test_as_Admin_User|service_description=logged in as caldwell|dialog_service_description=logged in as caldwell|template=c6a93884-a8ca-11e5-b617-005056834234|flavor=xsmall|add_disk1=10|group_id=1000000000023|group_name=IT-RND-|service_id=1000000000016|service_guid=bcdb8446-b947-11e5-be76-005056831180|environment=test|role=app|flex_monitor=false", nil, nil]

[----] W, [2016-01-12T10:15:55.211550 #2993:58e8014] WARN -- : Q-task_id([service_template_provision_task_1000000000052]) MIQ(MiqProvisionVirtWorkflow.from_ws_ver_1_x) Web-service provisioning starting with interface version <1.1> by requester <admin>

[----] E, [2016-01-12T10:15:55.212923 #2993:58e8014] ERROR -- : Q-task_id([service_template_provision_task_1000000000052]) MIQ(MiqProvisionVirtWorkflow.from_ws_ver_1_x) <Couldn't find User with [WHERE "users"."region" = ? AND "users"."userid" = ?]>

[----] E, [2016-01-12T10:15:55.214517 #2993:926a418] ERROR -- : Q-task_id([service_template_provision_task_1000000000052]) <AutomationEngine> <AEMethod vmware_build_vmprovision_request> [ActiveRecord]

/opt/rh/rh-ruby22/root/usr/share/ruby/drb/drb.rb:1149:in `method_missing’

<code: request = $evm.execute('create_provision_request', *args)>:384:in `build_provision_request’
Comment 8 Tina Fitzgerald 2016-01-18 13:58:35 EST
Your logs indicate that the user_name sent to provisioning is 'qo386420' for both test99 and test100 service provision requests as shown below(look for user_name):

[----] I, [2016-01-18T08:53:46.752891 #16652:177b428] INFO -- : Q-task_id([service_template_provision_task_1000000000145]) <AutomationEngine> <AEMethod vmware_build_vmprovision_request> Build: 1 - Building provision request with the following arguments: ["1.1", "name=CF-Centos6-stdfs|guid=c6a93884-a8ca-11e5-b617-005056834234", "number_of_vms=1|provision_type=vmware|vm_name=changeme|vlan=VM Network|cores_per_socket=1|vm_memory=4096|retirement=7776000|retirement_warn=604800", "user_name=qo386420|owner_first_name=Rich|owner_last_name=Caldwell|owner_email=Rich.Caldwell@sprint.com", "environment=prod|role=app|flavor=medium", "service_name=test99|dialog_service_name=test99|service_description=test99|dialog_service_description=test99|network=ent-dhcp|dialog_network=ent-dhcp|template=c6a93884-a8ca-11e5-b617-005056834234|flavor=medium|group_id=1000000000023|group_name=IT-RND-|service_id=1000000000045|service_guid=40641a3a-bdf3-11e5-b04e-005056834234|environment=prod|role=app", nil, nil]

----] I, [2016-01-18T09:01:08.363580 #16649:5dd5cac] INFO -- : Q-task_id([service_template_provision_task_1000000000148]) <AutomationEngine> <AEMethod vmware_build_vmprovision_request> Build: 1 - Building provision request with the following arguments: ["1.1", "name=CF-Centos6-stdfs|guid=c6a93884-a8ca-11e5-b617-005056834234", "number_of_vms=1|provision_type=vmware|vm_name=changeme|vlan=VM Network|cores_per_socket=1|vm_memory=4096|retirement=7776000|retirement_warn=604800", "user_name=qo386420|owner_first_name=Rich|owner_last_name=Caldwell|owner_email=Rich.Caldwell@sprint.com", "environment=prod|role=app|flavor=medium", "service_name=test100|dialog_service_name=test100|service_description=test100|dialog_service_description=test100|network=ent-dhcp|dialog_network=ent-dhcp|template=c6a93884-a8ca-11e5-b617-005056834234|flavor=medium|group_id=1000000000023|group_name=IT-RND-|service_id=1000000000046|service_guid=453c9dce-bdf4-11e5-b04e-005056834234|environment=prod|role=app", nil, nil]


Could you do the following in a test environment:

Using the Automate Explorer:
1. Navigate to the /CloudformsPOC/Service/Provisioning/Statemachines/Methods class
2. Edit the vmware_build_provision_request method.

Note - We need to make a very simple change to the get_requester method code.
I've listed my code since I'm not sure if your method differs.

My line 138 reads:
    matching_options_hash[:user_name]        = /^[^@]*/.match(@user.userid).to_s

We need to make a copy of that line, and comment it out.
Then modify the copied line to read:
    matching_options_hash[:user_name]        = @user.userid

The changed code should look like this:
    #matching_options_hash[:user_name]        = /^[^@]*/.match(@user.userid).to_s
    matching_options_hash[:user_name]        = @user.userid

3. Save the method.
4. Provision Service.
  

my copy of get_requester code inside vmware_build_provision_request automate method for reference:

  # get requester and tenant information and allow a userid for provisioning on behalf of
  def get_requester(build, matching_options_hash, matching_tags_hash)
    log(:info, "Processing get_requester...", true)
    @user   = $evm.vmdb('user').find_by_id(matching_options_hash[:evm_owner_id]) || $evm.vmdb('user').find_by_userid(matching_options_hash[:userid])
    @user ||= $evm.vmdb('user').find_by_id($evm.root['user_id'])
    matching_options_hash[:user_name]        = /^[^@]*/.match(@user.userid).to_s
    matching_options_hash[:owner_first_name] = @user.first_name ? @user.first_name : 'Cloud'
    matching_options_hash[:owner_last_name]  = @user.last_name ? @user.last_name : 'Admin'
    matching_options_hash[:owner_email]      = @user.email ? @user.email : $evm.object['to_email_address']
    log(:info, "Build: #{build} - User: #{@user.userid} id: #{@user.id} email: #{@user.email}")
    # Stuff the current group information
    matching_options_hash[:group_id] = @user.current_group.id
    matching_options_hash[:group_name] = @user.current_group.description
    log(:info, "Build: #{build} - Group: #{@user.current_group.description} id: #{@user.current_group.id}")
    log(:info, "Processing get_requester...Complete", true)
  end


Thanks,
Tina
Comment 9 Tina Fitzgerald 2016-01-18 15:06:34 EST
One additional request:

Could you navigate to Configure/Configuration/Access Control/Users and provide a screen shot of the user in question.

Thanks,
Tina
Comment 10 Rich 2016-01-18 22:23:48 EST
My code is slightly different than yours, but I have made the requisite changes and that resolves this issue.  I successfully provisioned a service using both short (qo386420) and long name login (qo386420@ad.sprint.com).  However, regardless of how or who I log in as, when I provision this service I ask for 1 VM, but I get two VMs created with different naming conventions.  For example, I told the name to be "testlongname". I got 2 VMs created in this service named "testlongname" and "test_0043".  "testlongname" has correct number of CPUs and Memory, "test_0043" has wrong number of both. Not sure why the test_0043 VM is being created.

def get_requester(build, merged_options_hash, merged_tags_hash)    ##Line 136 in my code starts here
  log_and_update_message(:info, "Processing get_requester...", true)
  @user = $evm.vmdb('user').find_by_id(merged_options_hash[:evm_owner_id]) ||
    $evm.vmdb('user').find_by_userid(merged_options_hash[:userid]) ||
    $evm.root['user']
  ###merged_options_hash[:user_name]        = /^[^@]*/.match(@user.userid).to_s
  merged_options_hash[:user_name]        = @user.userid
  merged_options_hash[:owner_first_name] = @user.first_name ? @user.first_name : 'Cloud'
  merged_options_hash[:owner_last_name]  = @user.last_name ? @user.last_name : 'Admin'
  merged_options_hash[:owner_email]      = @user.email ? @user.email : $evm.object['to_email_address']
  log_and_update_message(:info, "Build: #{build} - User: #{@user.userid} id: #{@user.id} email: #{@user.email}")

  # Stuff the current group information
  merged_options_hash[:group_id] = @user.current_group.id
  merged_options_hash[:group_name] = @user.current_group.description
  log_and_update_message(:info, "Build: #{build} - Group: #{merged_options_hash[:group_name]} " \
                         "id: #{merged_options_hash[:group_id]}")
  log_and_update_message(:info, "Processing get_requester...Complete", true)
end    ### Line 154 is this line
Comment 11 Rich 2016-01-18 22:26 EST
Created attachment 1116026 [details]
Screen shot service with 2 VMs when one was requested
Comment 12 Rich 2016-01-18 22:28 EST
Created attachment 1116027 [details]
User Account from LDAP creating service request

This is the user account that I was logged in as when the service was failing. It's an Active Directory user account.
Comment 14 Tina Fitzgerald 2016-01-20 17:40:06 EST
It appears as though there are multiple things going on here.

1. An invalid user causes create_provision_request automate call to break and log the following error:
[----] E, [2016-01-12T10:15:55.212923 #2993:58e8014] ERROR -- : Q-task_id([service_template_provision_task_1000000000052]) MIQ(MiqProvisionVirtWorkflow.from_ws_ver_1_x) <Couldn't find User with [WHERE "users"."region" = ? AND "users"."userid" = ?]>
We will make a fix for this.

2. The /CloudformsPOC/Service/Provisioning/Statemachines/Methods/vmware_build_provision_request method needed the following change to pass the correct userid: 
###merged_options_hash[:user_name]        = /^[^@]*/.match(@user.userid).to_s
merged_options_hash[:user_name]        = @user.userid

3. Two VMs are being provisioned from a service where only a single VM is expected. Waiting for additional information on the service anatomy, a screen shot showing the service and its resources.
Comment 15 Tina Fitzgerald 2016-01-21 11:21:02 EST
Rich sent me the service screen shots last night and I'll look at the logs.

Can we open a separate ticket for this issue?

Note You need to log in before you can comment on or make changes to this bug.