Bug 1412186 - [RFE] Track what user executed remote job in the production.log
Summary: [RFE] Track what user executed remote job in the production.log
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Remote Execution
Version: 6.2.4
Hardware: x86_64
OS: Linux
medium vote
Target Milestone: Unspecified
Assignee: Ivan Necas
QA Contact: Marek Hulan
Depends On:
TreeView+ depends on / blocked
Reported: 2017-01-11 13:33 UTC by Michal Dekan
Modified: 2021-06-10 11:49 UTC (History)
10 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Last Closed: 2018-02-21 12:37:44 UTC
Target Upstream Version:

Attachments (Terms of Use)

System ID Private Priority Status Summary Last Updated
Foreman Issue Tracker 18949 0 Normal Closed Include information about current user when loggin 2020-06-05 14:15:08 UTC
Red Hat Product Errata RHSA-2018:0336 0 normal SHIPPED_LIVE Important: Satellite 6.3 security, bug fix, and enhancement update 2018-02-21 22:43:42 UTC

Description Michal Dekan 2017-01-11 13:33:41 UTC
Description of problem:

Customer is running Satellite 6.2 and would like to enable remote execution. However, customer wants to audit remote execution activity and needs to see this in a logfile somewhere. They need to see:

- Who ran a remote execution job
- What action they ran
- Where they ran it - which target hosts

/var/log/foreman/production.log shows what was ran and where it was run but it doesn't show who ran the job.

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

Satellite 6.2.x

How reproducible:  100%

Steps to Reproduce:

Execute any remote job and see the details being logged in to the production.log

Actual results:

Example from my test satellite instance shows the what and where but not the user (Run Uptime on test1.example.com)

2016-11-22 17:45:48 [app] [I]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"5fRSfJOibo8zREKH9Lfuft7Em2j53za777mxlCHrdbU=", "job_invocation"=>{"job_category"=>"Commands", "providers"=>{"SSH"=>{"job_template_id"=>"94", "job_templates"=>{"94"=>{"input_values"=>"[FILTERED]", "effective_user"=>""}, "125"=>{"input_values"=>"[FILTERED]", "effective_user"=>""}}}}, "description"=>"Run uptime", "description_override"=>"Run %{command}", "description_format"=>"Run %{command}", "concurrency_level"=>"", "time_span"=>""}, "targeting"=>{"bookmark_id"=>"", "search_query"=>"name = test1.example.com", "targeting_type"=>"static_query"}, "triggering"=>{"mode"=>"immediate", "start_at_raw"=>"2016-11-22 17:45", "start_before_raw"=>"", "input_type"=>"daily", "cronline"=>"", "days"=>"", "days_of_week"=>{"1"=>"0", "2"=>"0", "3"=>"0", "4"=>"0", "5"=>"0", "6"=>"0", "7"=>"0"}, "time"=>{"time(1i)"=>"2016", "time(2i)"=>"11", "time(3i)"=>"22", "time(4i)"=>"17", "time(5i)"=>"45"}, "max_iteration"=>"", "end_time_limited"=>"false", "end_time"=>{"end_time(3i)"=>"22", "end_time(2i)"=>"11", "end_time(1i)"=>"2016", "end_time(4i)"=>"17", "end_time(5i)"=>"45"}}, "commit"=>"Submit"}

Expected results:

Username which triggered remote execution job should be logged in to production.log

There is an API call which can be used to retrieve info about remote execution job. It contains user_id field:

]#  curl -H 'Content-Type: application/json' -k -u admin:xxx https://$(hostname -f)/api/v2/job_invocations/50 | json_reformat
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   675    0   675    0     0   1204      0 --:--:-- --:--:-- --:--:--  1205
    "id": 50,
    "description": "Run ping google.com",
    "job_category": "Commands",
    "targeting_id": 50,
    "status": 1,
    "start_at": "2017-01-06 13:40:32 UTC",
    "status_label": "failed",
    "dynflow_task": {
        "id": "04efbb0f-9ff9-463c-8c29-7efc24f7b1a3",
        "state": "stopped"
    "succeeded": 0,
    "failed": 1,
    "pending": 0,
    "total": 1,
    "targeting": {
        "bookmark_id": null,
        "search_query": "name = mdekan-test2.sysmgmt.lan",
        "targeting_type": "static_query",
        "user_id": 3,
        "hosts": [
                "name": "mdekan-test2.sysmgmt.lan",
                "id": 169
    "template_invocations": [
            "template_id": 96,
            "template_name": "Run Command - SSH Default",
            "template_invocation_input_values": [
                    "template_input_name": "command",
                    "template_input_id": 7,
                    "value": "ping google.com"
To get username for user_id 3 and check Login field:

# hammer user info --id 3
Id:                   3
Login:                admin
Name:                 Admin User
Email:                root
Admin:                yes
Authorized by:        Internal
Locale:               en
Last login:           2017/01/11 08:31:08
Default organization: Default Organization
Default location:     Default Location
User groups:          
    Default Location
    Default Organization
Created at:           2016/02/25 17:52:12
Updated at:           2017/01/11 08:31:08

Or API call

# curl -H 'Content-Type: application/json' -k -u admin:xxx https://$(hostname -f)/api/v2/users/3 | json_reformat

We could use either 
# hammer user info --id X
# curl -H 'Content-Type: application/json' -k -u admin:xxx https://$(hostname -f)/api/v2/users/X | json_reformat

to add login field into parameters for the remote execution job to have the information which user was used to execute the remote job:

2016-11-22 17:45:48 [app] [I]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"5fRSfJOibo8zREKH9Lfuft7Em2j53za777mxlCHrdbU=", "job_invocation"=>{"job_category"=>"Commands", "providers"=>{"SSH"=>{"job_template_id"=>"94", "job_templates"=>{"94"=>{"input_values"=>"[FILTERED]", "effective_user"=>""}, "125"=>{"input_values"=>"[FILTERED]", "effective_user"=>""}}}}, "description"=>"Run uptime", "description_override"=>"Run %{command}", "description_format"=>"Run %{command}", "concurrency_level"=>"", "time_span"=>""}, "targeting"=>{"bookmark_id"=>"", "search_query"=>"name = test1.example.com", "targeting_type"=>"static_query"}, "triggering"=>{"mode"=>"immediate", "start_at_raw"=>"2016-11-22 17:45", "start_before_raw"=>"", "input_type"=>"daily", "cronline"=>"", "days"=>"", "days_of_week"=>{"1"=>"0", "2"=>"0", "3"=>"0", "4"=>"0", "5"=>"0", "6"=>"0", "7"=>"0"}, "time"=>{"time(1i)"=>"2016", "time(2i)"=>"11", "time(3i)"=>"22", "time(4i)"=>"17", "time(5i)"=>"45"}, "max_iteration"=>"", "end_time_limited"=>"false", "end_time"=>{"end_time(3i)"=>"22", "end_time(2i)"=>"11", "end_time(1i)"=>"2016", "end_time(4i)"=>"17", "end_time(5i)"=>"45"}}, "commit"=>"Submit", "login" => "admin"}

Comment 1 Ivan Necas 2017-03-17 13:30:06 UTC
Created redmine issue http://projects.theforeman.org/issues/18949 from this bug

Comment 2 Ivan Necas 2017-03-17 13:39:12 UTC
I've proposed a change to include info about the user performing the actions inside the production.log, that would apply for all logged messages, not only for remote execution. I'm waiting for feedback of other core contributors.

Comment 3 Satellite Program 2017-03-17 14:11:21 UTC
Upstream bug assigned to inecas

Comment 4 Satellite Program 2017-03-17 14:11:25 UTC
Upstream bug assigned to inecas

Comment 5 Ivan Necas 2017-03-17 14:16:40 UTC
There is one issue with the proposed solution: the info about the user get logged, but unfortunately, we don't have this information at the time the parameters are being logged, which leads to this kind of logs:

2017-03-17T15:13:50 23eeb21c  [app] [I] Started GET "/" for at 2017-03-17 15:13:50 +0100
2017-03-17T15:13:50 23eeb21c  [app] [I] Processing by DashboardController#index as HTML
2017-03-17T15:13:50 23eeb21c [user:skoroadmin] [app] [I]   Rendered dashboard/index.html.erb within layouts/application (88.7ms)
2017-03-17T15:13:50 23eeb21c [user:skoroadmin] [app] [I]   Rendered common/_searchbar.html.erb (5.2ms)
2017-03-17T15:13:50 23eeb21c [user:skoroadmin] [app] [I]   Rendered layouts/_application_content.html.erb (6.3ms)
2017-03-17T15:13:51 23eeb21c [user:skoroadmin] [app] [I]   Rendered home/_user_dropdown.html.erb (5.6ms)
2017-03-17T15:13:51 23eeb21c [user:skoroadmin] [app] [I]   Rendered home/_organization_dropdown.html.erb (4.7ms)
2017-03-17T15:13:51 23eeb21c [user:skoroadmin] [app] [I]   Rendered home/_location_dropdown.html.erb (5.2ms)
2017-03-17T15:13:51 23eeb21c [user:skoroadmin] [app] [I]   Rendered home/_org_switcher.html.erb (11.1ms)
2017-03-17T15:13:51 23eeb21c [user:skoroadmin] [app] [I]   Rendered home/_submenu.html.erb (3.1ms)
2017-03-17T15:13:51 23eeb21c [user:skoroadmin] [app] [I]   Rendered home/_submenu.html.erb (3.4ms)
2017-03-17T15:13:51 23eeb21c [user:skoroadmin] [app] [I]   Rendered home/_submenu.html.erb (2.0ms)
2017-03-17T15:13:51 23eeb21c [user:skoroadmin] [app] [I]   Rendered home/_submenu.html.erb (1.3ms)
2017-03-17T15:13:51 23eeb21c [user:skoroadmin] [app] [I]   Rendered home/_submenu.html.erb (3.0ms)
2017-03-17T15:13:51 23eeb21c [user:skoroadmin] [app] [I]   Rendered home/_topbar.html.erb (135.9ms)
2017-03-17T15:13:51 23eeb21c [user:skoroadmin] [app] [I]   Rendered layouts/base.html.erb (768.2ms)
2017-03-17T15:13:51 23eeb21c  [app] [I] Completed 200 OK in 987ms (Views: 874.0ms | ActiveRecord: 16.0ms)
2017-03-17T15:13:53 23eeb21c  [app] [D]
2017-03-17T15:13:53 23eeb21c  [app] [D]

Notice the processing has not the '[user:skoroadmin]' prefix, and the same would apply for params.

Comment 6 Ivan Necas 2017-03-17 14:30:56 UTC
Would this format of log be sufficient?

2016-11-22 17:45:48 23eeb21c [app] [I]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"5fRSfJOibo8zREKH9Lfuft7Em2j53za777mxlCHrdbU=", "job_invocation"=>{"job_category"=>"Commands", "providers"=>{"SSH"=>{"job_template_id"=>"94", "job_templates"=>{"94"=>{"input_values"=>"[FILTERED]", "effective_user"=>""}, "125"=>{"input_values"=>"[FILTERED]", "effective_user"=>""}}}}, "description"=>"Run uptime", "description_override"=>"Run %{command}", "description_format"=>"Run %{command}", "concurrency_level"=>"", "time_span"=>""}, "targeting"=>{"bookmark_id"=>"", "search_query"=>"name = test1.example.com", "targeting_type"=>"static_query"}, "triggering"=>{"mode"=>"immediate", "start_at_raw"=>"2016-11-22 17:45", "start_before_raw"=>"", "input_type"=>"daily", "cronline"=>"", "days"=>"", "days_of_week"=>{"1"=>"0", "2"=>"0", "3"=>"0", "4"=>"0", "5"=>"0", "6"=>"0", "7"=>"0"}, "time"=>{"time(1i)"=>"2016", "time(2i)"=>"11", "time(3i)"=>"22", "time(4i)"=>"17", "time(5i)"=>"45"}, "max_iteration"=>"", "end_time_limited"=>"false", "end_time"=>{"end_time(3i)"=>"22", "end_time(2i)"=>"11", "end_time(1i)"=>"2016", "end_time(4i)"=>"17", "end_time(5i)"=>"45"}}, "commit"=>"Submit", "login" => "admin"}

2017-03-17T15:13:50 23eeb21c [app] [I] Current user: skoroadmin (regular user)

It doesn't seem to be feasible to get this information on one line, but the info can be grouped together by the session id (23eeb21c)

Comment 7 Satellite Program 2017-03-21 20:10:54 UTC
Moving this bug to POST for triage into Satellite 6 since the upstream issue http://projects.theforeman.org/issues/18949 has been resolved.

Comment 8 Ivan Necas 2017-03-24 08:47:19 UTC
Got the answer off this channel. As I understand correctly, having the user at the same line as Parameters are mentioned would be better, but the framework we are using and the lifecycle of handling a request doesn't allow us to do this short term (long term, there should be more work spend on better auditing facilities that would support this case better). The change to add info about current user into logging got merged upstream

Comment 14 errata-xmlrpc 2018-02-21 12:37:44 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.


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