Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

split workflow & task logs, add state and update time to task logs #427

Merged
merged 4 commits into from
Jul 25, 2024
Merged
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Prev Previous commit
update docs
essweine committed Jul 23, 2024
commit c232b04602a866248d3009f1dc4a304d699162eb
60 changes: 33 additions & 27 deletions doc/bpmn/logging.rst
Original file line number Diff line number Diff line change
@@ -2,44 +2,50 @@ Logging
=======

Spiff provides several loggers:
- the :code:`spiff` logger, which emits messages when a workflow is initialized and when tasks change state
- the :code:`spiff.metrics` logger, which emits messages containing the elapsed duration of tasks

All log entries created during the course of running a workflow contain the following extra attributes:
- the :code:`spiff.workflow` logger, which emits messages when actions are taken on a workflow
- the :code:`spiff.task` logger, which emits messages when tasks change state

- :code:`workflow_spec`: the name of the current workflow spec
- :code:`task_spec`: the name of the task spec
- :code:`task_id`: the ID of the task)
- :code:`task_type`: the name of the task's spec's class
Records emitted at the :code:`INFO` level, with addtional attributes available for debugging if the level is lower.

If the log level is less than 20:
Log entries emitted by the :code:`spiff.workflow` logger contain the following extra atributes:

- :code:`data` the task data (this can be quite large and is only made available for debugging purposes)
- :code:`workflow_spec`: the name of the spec for this workflow
- :code:`completed`: whether the workflow has completed
- :code:`success`: the value of the :code:`success` attribute

If the log level is less than or equal to 10:
If the log level is less than 20, records include the following extra attribute:

- :code:`internal_data`: the task internal data (only available at DEBUG or below because it is not typically useful)
- :code:`tasks`: a list of the task ids in the workflow

The metrics logger additionally provides and only emits messages at the DEBUG level:
Log entries emitted by the :code:`spiff.task` logger contain the following extra attributes:

- :code:`elapsed`: the time it took the task to run after (ie, the duration of the :code:`task.run` method)
- :code:`workflow_spec`: the name of the spec for this workflow
- :code:`task_spec`: the name of the spec for this task
- :code:`task_id`: the ID of the task)
- :code:`task_type`: the name of the task's spec's class
- :code:`state`: the name of the tasks :code:`TaskState`
- :code:`last_state_chsnge`: the timestamp at which the state change was made
- :code:`elapsed`: the elapsed time since the previous state transition
- :code:`parent`: the id of the task's parent

In our command line UI (:app:`cli/subcommands.py`), we've added a few of these extra attributes to the log records:
If the log level is less than 20, records include the following extra attributes:

.. code-block:: python
- :code:`data` the task data
- :code:`internal_data`: the task internal data

Log entries containing task data and internal data can be quite large, so use with caution!

spiff_logger = logging.getLogger('spiff')
spiff_handler = logging.StreamHandler()
spiff_handler.setFormatter('%(asctime)s [%(name)s:%(levelname)s] (%(workflow_spec)s:%(task_spec)s) %(message)s')
spiff_logger.addHandler(spiff_handler)
In our command line UI (:app:`cli/subcommands.py`), we've added a few of these extra attributes to the log records:

metrics_logger = logging.getLogger('spiff.metrics')
metrics_handler = logging.StreamHandler()
metrics_handler.setFormatter('%(asctime)s [%(name)s:%(levelname)s] (%(workflow_spec)s:%(task_spec)s) %(elasped)s')
metrics_logger.addHandler(metrics_handler)
.. code-block:: python

In the configuration module :app:`spiff/file.py` that appears in many examples, we set the level of the :code:`spiff`
logger to :code:`INFO`, so that we'll see messages about task state changes, but we ignore the metrics log; however,
the configuration could easily be changed to include it (it can, however generate a high volume of very large records,
so consider yourself warned!).
task_logger = logging.getLogger('spiff.task')
task_handler = logging.StreamHandler()
task_handler.setFormatter(logging.Formatter('%(asctime)s [%(name)s:%(levelname)s] (%(workflow_spec)s:%(task_spec)s) %(message)s'))
task_logger.addHandler(task_handler)

wf_logger = logging.getLogger('spiff.workflow')
wf_handler = logging.StreamHandler()
wf_handler.setFormatter(logging.Formatter('%(asctime)s [%(name)s:%(levelname)s] (%(workflow_spec)s) %(message)s'))
wf_logger.addHandler(wf_handler)