Bug 1671563 - Different User is Being Shown as the Requester for a Lifecycle Provision in Automation Log
Summary: Different User is Being Shown as the Requester for a Lifecycle Provision in A...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: Automate
Version: 5.9.6
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: GA
: 5.11.0
Assignee: drew uhlmann
QA Contact: Ganesh Hubale
Red Hat CloudForms Documentation
URL:
Whiteboard:
: 1645628 (view as bug list)
Depends On:
Blocks: 1728706
TreeView+ depends on / blocked
 
Reported: 2019-01-31 22:33 UTC by myoder
Modified: 2019-12-13 15:09 UTC (History)
12 users (show)

Fixed In Version: 5.11.0.1
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1728706 (view as bug list)
Environment:
Last Closed: 2019-12-13 15:09:30 UTC
Category: Bug
Cloudforms Team: CFME Core
Target Upstream Version:


Attachments (Terms of Use)
web ui of request screen (25.71 KB, image/png)
2019-01-31 22:33 UTC, myoder
no flags Details
request id b user Jason after updating to 5.9.7.2 (28.56 KB, image/png)
2019-02-02 21:06 UTC, myoder
no flags Details

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 9 Keenan Brock 2019-03-04 16:24:08 UTC
*** Bug 1645628 has been marked as a duplicate of this bug. ***


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