Bug 1264827

Summary: Foreman logging missing unique identifier per request to correlate (API) logging
Product: Red Hat Satellite Reporter: Peter Vreman <peter.vreman>
Component: APIAssignee: satellite6-bugs <satellite6-bugs>
Status: CLOSED DUPLICATE QA Contact: Katello QA List <katello-qa-list>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 6.1.2CC: bbuckingham
Target Milestone: Unspecified   
Target Release: Unused   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-05-02 14:11:34 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1122832    

Description Peter Vreman 2015-09-21 10:18:38 UTC
Description of problem:
There is no unique identifier to correlate the logging per API request.
See the logging fragment below.
- There is a Content View Publish requested
- Followed shortly by a call to Tasks
- Then we see the Tasks "Completed" response
- Then we see the another "Completed" response, for which we _think_ it it related to the Publish response. But this might also be from an other concurrent request

2015-09-21 09:54:01 [I] Processing by Katello::Api::V2::ContentViewsController#publish as */*
2015-09-21 09:54:01 [I]   Parameters: {"per_page"=>9999, "api_version"=>"v2", "id"=>"38", "content_view"=>{}}
2015-09-21 09:54:01 [I] Authorized user hoici(hoici )
2015-09-21 09:54:01 [I] Processing by ForemanTasks::Api::TasksController#bulk_search as */*
2015-09-21 09:54:01 [I]   Parameters: {"per_page"=>9999, "searches"=>[{"type"=>"task", "task_id"=>"eba81e76-2642-4f42-937b-ab6b08c6c79b"}], "task"=>{}}
2015-09-21 09:54:01 [I] Authorized user hoici(hoici )
2015-09-21 09:54:02 [I] Completed 200 OK in 1499ms (Views: 1.9ms | ActiveRecord: 19.1ms)
2015-09-21 09:54:06 [I]   Rendered text template (0.0ms)
2015-09-21 09:54:06 [I] Completed 204 No Content in 25023ms (Views: 5.6ms | ActiveRecord: 35.7ms)

The more concurrent actions are handled by Sat6 the more the logging will be interwoven and harder to correlate which logging belongs together.



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


How reproducible:


Steps to Reproduce:
1. Start 20 Concurrent ContentView publish actions
2. Query the Tasks controller
3.

Actual results:
Unclear which logging belongs to which request

Expected results:
Unique identifier prefixing the logging, e.g. for the above example:

2015-09-21 09:54:01 [I][Req 12345] Processing by Katello::Api::V2::ContentViewsController#publish as */*
2015-09-21 09:54:01 [I][Req 12345]   Parameters: {"per_page"=>9999, "api_version"=>"v2", "id"=>"38", "content_view"=>{}}
2015-09-21 09:54:01 [I][Req 12345] Authorized user hoici(hoici )
2015-09-21 09:54:01 [I][Req 67890] Processing by ForemanTasks::Api::TasksController#bulk_search as */*
2015-09-21 09:54:01 [I][Req 67890]   Parameters: {"per_page"=>9999, "searches"=>[{"type"=>"task", "task_id"=>"eba81e76-2642-4f42-937b-ab6b08c6c79b"}], "task"=>{}}
2015-09-21 09:54:01 [I][Req 67890] Authorized user hoici(hoici )
2015-09-21 09:54:02 [I][Req 67890] Completed 200 OK in 1499ms (Views: 1.9ms | ActiveRecord: 19.1ms)
2015-09-21 09:54:06 [I][Req 12345]   Rendered text template (0.0ms)
2015-09-21 09:54:06 [I][Req 12345] Completed 204 No Content in 25023ms (Views: 5.6ms | ActiveRecord: 35.7ms)


Additional info:
See also BZ1264324 for Pulp logging, that is also missing a unqiue identifier to correlate the logging messages

Comment 2 Peter Vreman 2017-05-02 14:11:34 UTC

*** This bug has been marked as a duplicate of bug 1408420 ***