Bug 1386108 - [RFE] Add the request ID (if there is one) to a log line along with Q-task_id
Summary: [RFE] Add the request ID (if there is one) to a log line along with Q-task_id
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: Automate
Version: 5.6.0
Hardware: Unspecified
OS: Unspecified
high
medium
Target Milestone: GA
: cfme-future
Assignee: John Hardy
QA Contact: Dmitry Misharov
URL:
Whiteboard: automate
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-10-18 07:58 UTC by Peter McGowan
Modified: 2020-04-08 13:45 UTC (History)
9 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-03-08 16:50:16 UTC
Category: ---
Cloudforms Team: ---
Target Upstream Version:


Attachments (Terms of Use)

Description Peter McGowan 2016-10-18 07:58:54 UTC
Description of problem:

Currently when printing a log line, the VMDBLogger class searches for a valid task_id field in the worker current message, and if one it exists the logger adds this to the log line, wrapped in the text "Q-task_id(...)".

Many users of CloudForms/ManageIQ are using enterprise class logging systems such as Splunk or ElasticSearch/Kibana to search for logs. It would be very useful to be able to search for all log lines that were related to the user issuing some kind of request, be it VM or service provisioning, or automation task for example. In such cases the request ID is returned to the user, but not the task ID. If we could add a Q-request_id field to the log line as follows, this would enable all tasks related to the single request to be monitored:

[----] I, [2016-08-26T12:21:55.640116 #20290:363990]  INFO -- : Q-task_id([automation_task_1000000004810]) Q-request_id([1000000003602]) Method exited with rc=MIQ_OK

I tried doing this by patching the 'call' method in VMDBLogger to recognise (via regex) the task type in the Q-task_d, and make a MiqRequestTask.where(:id => task_id).first lookup to get the request ID. This worked for 'production' rails environment (although not for 'development' because of the extra logging), but this is clearly not the right way to go about the problem.

I think a better way of doing this would be to add a new column called 'request_id' to the miq_queue table, and to modify any methods that call MiqQueue.put to make a request_id lookup at that time, and add this to the argument list, i.e.

MiqQueue.put(
      :class_name  => self.class.name,
      :instance_id => id,
      :method_name => "create_request_tasks",
      :zone        => options.fetch(:miq_zone, my_zone),
      :role        => my_role,
      :task_id     => "#{self.class.name.underscore}_#{id}",
      :request_id  => ...
      :msg_timeout => 3600,
      :deliver_on  => deliver_on
    )
  end

The logger could then simply retrieve this from the message and add to the log line in the same way that it does for the Q-task_id.

Comment 3 Tina Fitzgerald 2019-03-08 16:23:46 UTC
Hi Peter,

I know this ticket was opened a long time ago.

Are you satisfied with the current implementation of the request/task being displayed in the log? 

For example:
 [2019-02-26T00:17:08.922803 #32591:5ecf54]  INFO -- : Q-task_id([r5_service_template_provision_task_7]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Ending


If so, can we close this ticket?

Thanks,
Tina

Comment 4 Peter McGowan 2019-03-08 16:46:00 UTC
Sure you can close this, the solution is good.

Thanks,
Peter

Comment 5 Greg McCullough 2020-04-08 13:45:54 UTC
Code changes referenced above were made in PR https://github.com/ManageIQ/manageiq/pull/17013


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