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.
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.
This is trivial using the new logging infrastructure introduced in 4.1.3.
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
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
BZ<2>Jira Resync