Bug 1671563

Summary: Different User is Being Shown as the Requester for a Lifecycle Provision in Automation Log
Product: Red Hat CloudForms Management Engine Reporter: myoder
Component: AutomateAssignee: drew uhlmann <duhlmann>
Status: CLOSED CURRENTRELEASE QA Contact: Ganesh Hubale <ghubale>
Severity: high Docs Contact: Red Hat CloudForms Documentation <cloudforms-docs>
Priority: high    
Version: 5.9.6CC: dmetzger, duhlmann, ghubale, jocarter, mkanoor, mshriver, myoder, obarenbo, prutledg, rspagnol, simaishi, tfitzger
Target Milestone: GAKeywords: Reopened, TestOnly, ZStream
Target Release: 5.11.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: 5.11.0.1 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1728706 (view as bug list) Environment:
Last Closed: 2019-12-13 15:09:30 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: Bug
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: CFME Core Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1728706    
Attachments:
Description Flags
web ui of request screen
none
request id b user Jason after updating to 5.9.7.2 none

Description myoder 2019-01-31 22:33:03 UTC 
Created attachment 1525617 [details]
web ui of request screen

Description of problem:

I had a user request a default lifecycle provision, but a different user is being shown as the request in the automation.log.


Seems related to this bug:

    https://bugzilla.redhat.com/show_bug.cgi?id=1640631


This is the automation.log:

[----] I, [2019-01-31T17:10:45.223860 #5977:1125114]  INFO -- : In State=[ValidateRequest], invoking [on_entry] method=[validate_request]
[----] I, [2019-01-31T17:10:46.602876 #5977:1125114]  INFO -- : Updated namespace [infrastructure/vm/Provisioning/StateMachines/ProvisionRequestApproval/validate_request  Testing/infrastructure/vm/Provisioning/StateMachines]
[----] I, [2019-01-31T17:10:46.623537 #5977:1125114]  INFO -- : Invoking [inline] method [/Testing/Infrastructure/VM/Provisioning/StateMachines/ProvisionRequestApproval/validate_request] with inputs [{}]
[----] I, [2019-01-31T17:10:46.629080 #5977:1125114]  INFO -- : <AEMethod [/Testing/Infrastructure/VM/Provisioning/StateMachines/ProvisionRequestApproval/validate_request]> Starting 
[----] I, [2019-01-31T17:10:48.169315 #5977:11143b4]  INFO -- : <AEMethod validate_request> This is the user: usera
[----] I, [2019-01-31T17:10:48.172403 #5977:11143b4]  INFO -- : <AEMethod validate_request> Cheeto: usera
[----] I, [2019-01-31T17:10:48.173376 #5977:11143b4]  INFO -- : <AEMethod validate_request> Listing Root Object Attributes:
[----] I, [2019-01-31T17:10:48.190921 #5977:1345f70]  INFO -- : <AEMethod validate_request>     ae_next_state: 
[----] I, [2019-01-31T17:10:48.193058 #5977:1345f70]  INFO -- : <AEMethod validate_request>     ae_provider_category: infrastructure
[----] I, [2019-01-31T17:10:48.195143 #5977:1345f70]  INFO -- : <AEMethod validate_request>     ae_result: ok
[----] I, [2019-01-31T17:10:48.197115 #5977:1345f70]  INFO -- : <AEMethod validate_request>     ae_retry_server_affinity: false
[----] I, [2019-01-31T17:10:48.199108 #5977:1345f70]  INFO -- : <AEMethod validate_request>     ae_state: ValidateRequest
[----] I, [2019-01-31T17:10:48.201181 #5977:1345f70]  INFO -- : <AEMethod validate_request>     ae_state_max_retries: 100
[----] I, [2019-01-31T17:10:48.203284 #5977:1345f70]  INFO -- : <AEMethod validate_request>     ae_state_retries: 0
[----] I, [2019-01-31T17:10:48.205037 #5977:1345f70]  INFO -- : <AEMethod validate_request>     ae_state_started: 2019-01-31 22:10:45 UTC
[----] I, [2019-01-31T17:10:48.206799 #5977:1345f70]  INFO -- : <AEMethod validate_request>     ae_state_step: on_entry
[----] I, [2019-01-31T17:10:48.208555 #5977:1345f70]  INFO -- : <AEMethod validate_request>     ae_status_state: on_entry
[----] I, [2019-01-31T17:10:48.211490 #5977:1345f70]  INFO -- : <AEMethod validate_request>     event_stream: #<MiqAeMethodService::MiqAeServiceRequestEvent:0x0000000019020990>
[----] I, [2019-01-31T17:10:48.213224 #5977:1345f70]  INFO -- : <AEMethod validate_request>     event_stream_id: 1000000429835
[----] I, [2019-01-31T17:10:48.215569 #5977:1345f70]  INFO -- : <AEMethod validate_request>     event_type: request_created
[----] I, [2019-01-31T17:10:48.218102 #5977:1345f70]  INFO -- : <AEMethod validate_request>     miq_group: #<MiqAeMethodService::MiqAeServiceMiqGroup:0x0000000019005258>
[----] I, [2019-01-31T17:10:48.220778 #5977:1345f70]  INFO -- : <AEMethod validate_request>     miq_provision_request: #<MiqAeMethodService::MiqAeServiceMiqProvisionRequest:0x0000000019016dc8>
[----] I, [2019-01-31T17:10:48.222598 #5977:1345f70]  INFO -- : <AEMethod validate_request>     miq_provision_request_id: 1000000000564
[----] I, [2019-01-31T17:10:48.225142 #5977:1345f70]  INFO -- : <AEMethod validate_request>     miq_request: #<MiqAeMethodService::MiqAeServiceMiqProvisionRequest:0x0000000019011b20>
[----] I, [2019-01-31T17:10:48.226802 #5977:1345f70]  INFO -- : <AEMethod validate_request>     miq_request_id: 1000000000564
[----] I, [2019-01-31T17:10:48.229635 #5977:1345f70]  INFO -- : <AEMethod validate_request>     miq_server: #<MiqAeMethodService::MiqAeServiceMiqServer:0x0000000019008d40>
[----] I, [2019-01-31T17:10:48.231475 #5977:1345f70]  INFO -- : <AEMethod validate_request>     miq_server_id: 1000000000001
[----] I, [2019-01-31T17:10:48.233230 #5977:1345f70]  INFO -- : <AEMethod validate_request>     object_name: Event
[----] I, [2019-01-31T17:10:48.235152 #5977:1345f70]  INFO -- : <AEMethod validate_request>     state_machine: ProvisionRequestApproval
[----] I, [2019-01-31T17:10:48.237728 #5977:1345f70]  INFO -- : <AEMethod validate_request>     tenant: #<MiqAeMethodService::MiqAeServiceTenant:0x0000000019005708>
[----] I, [2019-01-31T17:10:48.240280 #5977:1345f70]  INFO -- : <AEMethod validate_request>     user: #<MiqAeMethodService::MiqAeServiceUser:0x0000000019005b90>
[----] I, [2019-01-31T17:10:48.241916 #5977:1345f70]  INFO -- : <AEMethod validate_request>     user_id: 1000000000009
[----] I, [2019-01-31T17:10:48.243696 #5977:1345f70]  INFO -- : <AEMethod validate_request>     vmdb_object_type: miq_provision_request
[----] I, [2019-01-31T17:10:48.245691 #5977:11143b4]  INFO -- : <AEMethod validate_request> ===========================================
[----] I, [2019-01-31T17:10:48.268408 #5977:11143b4]  INFO -- : <AEMethod validate_request> Auto-Approval Threshold(Model):<max_vms=1> detected
[----] W, [2019-01-31T17:10:48.285295 #5977:11143b4]  WARN -- : <AEMethod validate_request> Auto-Approval Threshold(Warning): Number of VMs requested:<4> exceeds:<1>
[----] I, [2019-01-31T17:10:48.350721 #5977:11143b4]  INFO -- : <AEMethod validate_request> Inspecting Messge:<Request was not auto-approved for the following reasons: (Requested VMs 4 limit is 1) >
[----] I, [2019-01-31T17:10:48.386127 #5977:1125114]  INFO -- : <AEMethod [/Testing/Infrastructure/VM/Provisioning/StateMachines/ProvisionRequestApproval/validate_request]> Ending


This is the id of my user named 'usera':

    vmdb_production=# select * from users;
    -[ RECORD 1 ]----+-------------------------------------------------------------
    id               | 1000000000009
    name             | usera


I am attaching a screenshot showing that the requester is displayed as 'Jason' with request id 1000000000564 from the Web UI.

This is what I used in my validate_request method:

    bud = $evm.root['user']
    $evm.log(:info, "This is the user: #{bud.userid}")
    $evm.log(:info, "Cheeto: #{bud.userid}")

    $evm.log("info", "Listing Root Object Attributes:")
    $evm.root.attributes.sort.each { |k, v| $evm.log("info", "\t#{k}: #{v}") }
    $evm.log("info", "===========================================")


Version-Release number of selected component (if applicable):
CFME 5.9.6.5

How reproducible:
not always

Steps to Reproduce:
1. Tested a series of service provisions and default lifecycle provisions with different users (Jay only did default, usera only did generic service provision)
2. Added logging to the validate_request method for both Service and Infrastructure namespaces
3. Viewed the automation.log

Actual results:
Sometimes the request user is correct, others it is not

Expected results:
Request user should be correct

Additional info:
I have this on reproducer 10.13.153.49 admin:smartvm
Comment 4 Tina Fitzgerald 2019-02-01 14:56:03 UTC 
Hi Yoder,

Can you test this on the latest 5.9 version?

Thanks,
Tina
Comment 5 myoder 2019-02-02 21:05:44 UTC 
Hey Tina,

Problem persists:

[----] I, [2019-02-02T12:43:08.916921 #13156:623108]  INFO -- : User [usera] with current group ID [1000000000022] n
ame [GroupA_User]
[----] I, [2019-02-02T12:43:09.097877 #13156:623108]  INFO -- : Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=1000000446199&MiqProvisionRequest%3A%3Amiq_provision_request=1000000000567&MiqRequest%3A%3Amiq_request=1000000000567&MiqServer%3A%3Amiq_server=1000000000001&User%3A%3Auser=1000000000009&event_stream_id=1000000446199&event_type=request_created&object_name=Event&vmdb_object_type=miq_provision_request]

<------------------ skipped lines ---------------------------->

[----] I, [2019-02-02T12:43:20.045741 #13156:6ad254]  INFO -- : <AEMethod validate_request> This is the user: usera


Version 5.9.7.2:

[----] I, [2019-02-02T12:38:27.224205 #12872:623108]  INFO -- : MiqServer: local=Y, master=Y, status= started, id=1000000000001, pid=12872, guid=642abc16-cb29-4714-a98a-a5aae2f2d32a, name=espero, zone=default, hostname=prueba2, ipaddress=10.13.153.49, version=5.9.7.2, build=20190109154935_c0d03d6, active roles=automate:database_owner:ems_inventory:ems_operations:event:notifier:scheduler:smartproxy:smartstate:user_interface:web_services:websocket


Uploading a screenshot showing the request id 1000000000567 by user Jason.

Cheers,
Comment 6 myoder 2019-02-02 21:06:58 UTC 
Created attachment 1526282 [details]
request id b user Jason after updating to 5.9.7.2
Comment 7 William Fitzgerald 2019-02-06 15:19:16 UTC 
I was able to reproduce this on the latest 5.9 and 5.10 downstream releases.

Reproducer: 5.10.0.33   10.8.198.128
            5.9.8.1     10.8.196.200


I updated the original validate_request method to make it clearer.
I created 2 copies, 1 for vm provisioning and 1 for service provisioning
I setup a vmuser for the vm provisioning and a svcuser for the service provision.

order one and then check results 
grep 'AEMethod validate_request' log/automation.log
Comment 8 drew uhlmann 2019-02-11 21:18:41 UTC 
https://github.com/ManageIQ/manageiq-automation_engine/pull/293
Comment 9 Keenan Brock 2019-03-04 16:24:08 UTC 
*** Bug 1645628 has been marked as a duplicate of this bug. ***