[openstack-dev] [Mistral] Proposing to remove mistral.utils.wf_trace module

Lingxian Kong anlin.kong at gmail.com
Tue Jun 30 09:47:24 UTC 2015

Hi, guys,

After implementation of the blueprint[1], now we use olso.log module in
Mistral, just as the same with other projects. However, we still use
mistral.utils.wf_trace module to make some info insertion into log
messages(we want to log execution id or task id during workflow running),
which is a little bit ugly, considering it could be replaced using oslo.log
features itself.

​So, I ​submit the proposal here to bring more people to have an open
discussion, to make sure wo make consensus about that before I start to do
code work.

Below is the long version in rst format:

Problem Description
Currently, we have mistral.utils.wf_trace module to get execution-id and
task-id during mistral workflow execution, then insert them to the log, so
there are plenty of wf_trace.info invokings all around our code repo, which
is much more likely a hacking to log module funtionality, and it's not
consistent with most of the log behavior in code writing.

Proposed Change
Instead of adding an extra wf_trace module, we make use of the capability
provided by oslo.log. Take an example, we have code as below::

    wf_ex = task_ex.workflow_execution
    wf_trace.info(task_ex, "Task '%s' [%s -> %s]" % (task_ex.name,
task_ex.state, state))

then, you will see from the log with content below:

``2015-06-26 04:09:50.326 19492 mistral.engine.default_engine INFO Task
'my_task' [WAITING -> RUNNING]

the execution_id and task_i
d are automatically inserted in wf_trace module. With oslo.log, we could
change the log behavior::

    wf_ex = task_ex.workflow_execution
    LOG.info("Task '%s' [%s -> %s]" % (task_ex.name, task_ex.state, state),
resource={'type': 'workflow', 'id': wf_ex.id})

and don't forget config *logging_default_format_string* value in
*mistral.conf* to:

``%(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s [-]

so, the log content would be like this:

``2015-06-26 04:09:50.326 19492 mistral.engine.default_engine INFO
[workflow-c79b656f-f57f-4761-a270-138ee2417e54] Task 'my_task' [WAITING ->

As you could noticed, the task_id is lost, yes, actually, for the time
being, oslo.log don't provide the capability such as recording various
resources at the same time in one line, which I have send an email to
openstack-dev mailing list to ask what oslo team suggest for this issue.

However, IMO, we have enough information for the operators to debug, we
have execution-id, task name, etc, and most importnantly it's a more
general way for logging.

But, if you really don't tolerate this change, we have workaround here
before the oslo.log has a final solution(maybe that will never happen). We
change the code as below::

    wf_ex = task_ex.workflow_execution
    LOG.info("Task '%s'(%s) [%s -> %s]" % (task_ex.name, task_ex.id,
task_ex.state, state), resource={'type': 'workflow', 'id': wf_ex.id})

so, the log content would be like this:

``2015-06-26 04:09:50.326 19492 mistral.engine.default_engine INFO
[workflow-c79b656f-f57f-4761-a270-138ee2417e54] Task
'my_task'(a8935974-5468-de89-b785-138ee241qefd) [WAITING -> RUNNING]``

Finally, we get rid of the redundant wf_trace module from Mistral, which is
really important for an engineer with OCD :-)

No, it's just an improvement internally

Security Impact

Other End User Impact

Performance Impact
Absolutely no.

Other Deployer Impact

Developer Impact
Yes, it will change how the developers want to log something related to
executions or tasks.

Anyway, we could keep the wf_trace module as it is, but it's a very ugly


[1]: https://blueprints.launchpad.net/mistral/+spec/mistral-log-enhancement
Lingxian Kong
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openstack.org/pipermail/openstack-dev/attachments/20150630/a2f4a7c3/attachment.html>

More information about the OpenStack-dev mailing list