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
Hi Yoder, Can you test this on the latest 5.9 version? Thanks, Tina
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,
Created attachment 1526282 [details] request id b user Jason after updating to 5.9.7.2
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
https://github.com/ManageIQ/manageiq-automation_engine/pull/293
*** Bug 1645628 has been marked as a duplicate of this bug. ***