more tweaks to logging fields

SpiffWorkflow/bpmn/specs/mixins/events/event_types.py

@@ -45,7 +45,6 @@ def catch(self, my_task, event):
         definition, at which point we can update our task's state.
         """
         self.event_definition.catch(my_task, event)
-        my_task.last_state_change = time.time()
         my_task._set_state(TaskState.WAITING)
 
     def _update_hook(self, my_task):

SpiffWorkflow/bpmn/util/subworkflow.py

@@ -39,11 +39,11 @@ def get_tasks_iterator(self, first_task=None, **kwargs):
 class BpmnSubWorkflow(BpmnBaseWorkflow):
 
     def __init__(self, spec, parent_task_id, top_workflow, **kwargs):
-        super().__init__(spec, **kwargs)
         self.parent_task_id = parent_task_id
         self.top_workflow = top_workflow
         self.correlations = {}
         self.depth = self._calculate_depth()
+        super().__init__(spec, **kwargs)
 
     @property
     def script_engine(self):

SpiffWorkflow/task.py

@@ -292,9 +292,13 @@ def _set_state(self, value):
         """Force set the state on a task"""
 
         if value != self.state:
+            elapsed = time.time() - self.last_state_change
             self.last_state_change = time.time()
             self._state = value
-            logger.info(f'State changed to {TaskState.get_name(value)}', extra=self.collect_log_extras())
+            logger.info(
+                f'State changed to {TaskState.get_name(value)}',
+                extra=self.collect_log_extras({'elapsed': elapsed})
+            )
         else:
             logger.debug(f'State set to {TaskState.get_name(value)}', extra=self.collect_log_extras())
 
@@ -382,15 +386,18 @@ def trigger(self, *args):
 
     def collect_log_extras(self, dct=None):
         """Return logging details for this task"""
-        extra = dct or {}
-        extra.update({
+        extra = {
             'workflow_spec': self.workflow.spec.name,
             'task_spec': self.task_spec.name,
             'task_id': self.id,
             'task_type': self.task_spec.__class__.__name__,
             'state': TaskState.get_name(self._state),
             'last_state_change': self.last_state_change,
-        })
+            'elapsed': 0,
+            'parent': None if self.parent is None else self.parent.id,
+        }
+        if dct is not None:
+            extra.update(dct)
         if logger.level < 20:
             extra.update({
                 'data': self.data if logger.level < 20 else None,

SpiffWorkflow/workflow.py

@@ -246,7 +246,7 @@ def reset_from_task_id(self, task_id, data=None):
             task_id: the id of the task to reset to
             data (dict): optionally replace the data (if None, data will be copied from the parent task)
 
-        Returns:
+        Returns:        extra.update(
             list(`Task`): tasks removed from the tree
         """
         task = self.get_task_from_id(task_id)
@@ -256,13 +256,13 @@ def reset_from_task_id(self, task_id, data=None):
     def collect_log_extras(self, dct=None):
         """Return logging details for this workflow"""
         extra = dct or {}
-        extra.update({'workflow_spec': self.spec.name})
+        extra.update({
+            'workflow_spec': self.spec.name,
+            'success': self.success,
+            'completed': self.completed,
+        })
         if logger.level < 20:
-            extra.update({
-                'finished': len([t for t in self.tasks.values() if t.has_state(TaskState.FINISHED_MASK)]),
-                'definite': len([t for t in self.tasks.values() if t.has_state(TaskState.DEFINITE_MASK)]),
-                'predicted': len([t for t in self.tasks.values() if t.has_state(TaskState.PREDICTED_MASK)]),
-            })
+            extra.update({'tasks': [t.id for t in Workflow.get_tasks(self)]})
         return extra
 
     def _predict(self, mask=TaskState.NOT_FINISHED_MASK):