Bug 1425596

Summary: [RFE] Provide a way to correlate each 'run and protect' thread to its task
Product: Red Hat Enterprise Virtualization Manager Reporter: Marina Kalinin <mkalinin>
Component: vdsmAssignee: Nir Soffer <nsoffer>
Status: CLOSED ERRATA QA Contact: Lucie Leistnerova <lleistne>
Severity: high Docs Contact:
Priority: high    
Version: 4.1.0CC: lsurette, lsvaty, mgoldboi, mperina, nsoffer, srevivo, tnisan, ycui, ykaul
Target Milestone: ovirt-4.2.0Keywords: FutureFeature, ZStream
Target Release: 4.2.0Flags: lsvaty: testing_plan_complete-
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: No Doc Update
Doc Text:
undefined
Story Points: ---
Clone Of:
: 1461295 (view as bug list) Environment:
Last Closed: 2018-05-15 17:50:23 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Infra RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1425219, 1461295    

Description Marina Kalinin 2017-02-21 20:49:02 UTC
Today, there is no way to correlate directly (without guessing and hoping it is your lucky day) from 'run and protect' thread to the task opened to fulfill the request. Unless you go to engine.log and try correlating the command from there.
If engine.log is missing or system has high traffic of events going on and the threads in the pool are being reused frequently, the likelihood of correlating the thread to its task successfully decreases. 

Example of current behavior:
~~~
INFO  (jsonrpc/6) [dispatcher] Run and protect: create_lease(lease={u'sd_id': u'd4ad5a78-1d75-457b-8caf-400d2d7917a6', u'lease_id': u'7eb2c25b-1bc8-4016-a9a5-73c6a69d2fa2'})

INFO  (tasks/2) [storage.ThreadPool.WorkerThread] START task a6a2107d-63b0-42b3-ac60-4ebbb1d1e3a9 (cmd=<bound method Task.commit of <storage.task.Task instance at 0x31afa70>>, args=None)

INFO  (tasks/2) [storage.xlease] Adding lease '7eb2c25b-1bc8-4016-a9a5-73c6a69d2fa2' in lockspace u'd4ad5a78-1d75-457b-8caf-400d2d7917a6' (xlease:548)
~~~

Expected behavior:
Add a correlation ID to be present in both thread and task. This sounds like the best option to me.

Or somehow add the task information in run and protect message or the other way around. But the problem with other way around is that jsonrpc threads seem to be reused from a pool of threads and they do not really have a unique identifier as the task does.

Comment 2 Nir Soffer 2017-03-23 23:05:37 UTC
All storage verbs run in a task, and the task id is available via vars.task.id.
We just need to add the task id in the logger creating the "Run and protect"
messages.

Can be something like:

INFO  (jsonrpc/6) [dispatcher] Run and protect: create_lease(lease={u'sd_id': u'd4ad5a78-1d75-457b-8caf-400d2d7917a6', u'lease_id': u'7eb2c25b-1bc8-4016-a9a5-73c6a69d2fa2'}) (task=a6a2107d-63b0-42b3-ac60-4ebbb1d1e3a9)
...
INFO  (tasks/2) [storage.ThreadPool.WorkerThread] START task a6a2107d-63b0-42b3-ac60-4ebbb1d1e3a9 (cmd=<bound method Task.commit of <storage.task.Task instance at 0x31afa70>>, args=None)
...
INFO  (jsonrpc/6) [dispatcher] Run and protect: create_lease, Return response: None)
(task=a6a2107d-63b0-42b3-ac60-4ebbb1d1e3a9)

Adding correction id can be nice, but we don't have it now in vdsm, it was dropped
when we moved to jsonrpc.

Comment 3 Nir Soffer 2017-05-28 16:58:40 UTC
This is trivial using the new logging infrastructure introduced in 4.1.3.

Comment 7 Lucie Leistnerova 2017-11-06 09:33:07 UTC
Every vdsm.api START/FINISH call has its task_id. This format replaced the 'Run and protect' prefix.
So the start/finish of asynchronous action can be correlate to 'START task' action.

verified in vdsm-4.20.6-1.el7ev.x86_64

Comment 12 errata-xmlrpc 2018-05-15 17:50:23 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.

https://access.redhat.com/errata/RHEA-2018:1489

Comment 13 Franta Kust 2019-05-16 13:04:50 UTC
BZ<2>Jira Resync