Best process instance 'verbose' logging strategy

[mmaker1234]

Hello Activiti developers,

We need to log as much as possible of a Process Instance execution. Until now I made changes to the Activiti Engine but it should not be as difficult, especially with the latest modification to the Listeners. Please advise what is the best approach to receive a result like this with as little modifications to the Activiti engine as possible:

…
end Activity id=1370772, name='Statistics Update Schedule Interval Timer' (definitionId=statisticsUpdateScheduleIntervalTimer) with properties: {default=null, name=Statistics Update Schedule Interval Timer, documentation=null, line=17, type=boundaryTimer}, Scope, Execution[id=1370772, ProcessInstance(id)=30101, ProcessDefinition(id)='UpdateStatistics:1:63', ActvityDefinition(id)='statisticsUpdateScheduleIntervalTimer'], definition_version: '$Revision: 1.2 $'

end Activity id=1370772, name='Manual Statistics Update' (definitionId=manualStatisticsUpdate) with properties: {default=null, name=Manual Statistics Update, documentation=null, line=16, timerDeclarations=[Timer [type=DURATION, expression='${updateInterval}', jobHandlerType=timer-transition, jobHandlerConfiguration=statisticsUpdateScheduleIntervalTimer, repeat=null, retries left = 3, exclusive=true]], type=userTask}, Scope, Execution[id=1370772, ProcessInstance(id)=30101, ProcessDefinition(id)='UpdateStatistics:1:63', ActvityDefinition(id)='manualStatisticsUpdate'], definition_version: '$Revision: 1.2 $'

start Activity id=30101, name='Update Statistics' (definitionId=updateStatistics) with properties: {default=null, name=Update Statistics, documentation=null, line=6, type=serviceTask}, Scope, Execution[id=30101, ProcessInstance(id)=30101, ProcessDefinition(id)='UpdateStatistics:1:63', ActvityDefinition(id)='updateStatistics'], definition_version: '$Revision: 1.2 $'

end Activity id=30101, name='Update Statistics' (definitionId=updateStatistics) with properties: {default=null, name=Update Statistics, documentation=null, line=6, type=serviceTask}, Scope, Execution[id=30101, ProcessInstance(id)=30101, ProcessDefinition(id)='UpdateStatistics:1:63', ActvityDefinition(id)='updateStatistics'], definition_version: '$Revision: 1.2 $'

start Activity id=1370803, name='Confirm Statistics Update Finished' (definitionId=confirmStatisticsUpdateFinished) with properties: {default=null, name=Confirm Statistics Update Finished, documentation=null, line=7, timerDeclarations=[Timer [type=DURATION, expression='PT1H', jobHandlerType=timer-transition, jobHandlerConfiguration=StatisticsUpdateTimedOutTimer, repeat=null, retries left = 3, exclusive=true]], type=receiveTask}, Scope, Execution[id=1370803, ProcessInstance(id)=30101, ProcessDefinition(id)='UpdateStatistics:1:63', ActvityDefinition(id)='confirmStatisticsUpdateFinished'], definition_version: '$Revision: 1.2 $'

end Activity id=1370803, name='Confirm Statistics Update Finished' (definitionId=confirmStatisticsUpdateFinished) with properties: {default=null, name=Confirm Statistics Update Finished, documentation=null, line=7, timerDeclarations=[Timer [type=DURATION, expression='PT1H', jobHandlerType=timer-transition, jobHandlerConfiguration=StatisticsUpdateTimedOutTimer, repeat=null, retries left = 3, exclusive=true]], type=receiveTask}, Scope, Execution[id=1370803, ProcessInstance(id)=30101, ProcessDefinition(id)='UpdateStatistics:1:63', ActvityDefinition(id)='confirmStatisticsUpdateFinished'], definition_version: '$Revision: 1.2 $'

start Activity id=30101, name='Is Statistics Collection Successful' (definitionId=isStatisticsCollectionSuccessfull) with properties: {default=null, name=Is Statistics Collection Successful, documentation=null, line=13, type=exclusiveGateway}, Scope, Execution[id=30101, ProcessInstance(id)=30101, ProcessDefinition(id)='UpdateStatistics:1:63', ActvityDefinition(id)='isStatisticsCollectionSuccessfull'], definition_version: '$Revision: 1.2 $'

Set value for variable named 'isStatisticsUpdateSuccessfull'

end Activity id=30101, name='Is Statistics Collection Successful' (definitionId=isStatisticsCollectionSuccessfull) with properties: {default=null, name=Is Statistics Collection Successful, documentation=null, line=13, type=exclusiveGateway}, Scope, Execution[id=30101, ProcessInstance(id)=30101, ProcessDefinition(id)='UpdateStatistics:1:63', ActvityDefinition(id)='isStatisticsCollectionSuccessfull'], definition_version: '$Revision: 1.2 $'

start Activity id=30101, name='Set Update Interval' (definitionId=setUpdateInterval) with properties: {default=null, name=Set Update Interval, documentation=null, line=14, type=serviceTask}, Scope, Execution[id=30101, ProcessInstance(id)=30101, ProcessDefinition(id)='UpdateStatistics:1:63', ActvityDefinition(id)='setUpdateInterval'], definition_version: '$Revision: 1.2 $'

Set value for variable named 'updateInterval'

end Activity id=30101, name='Set Update Interval' (definitionId=setUpdateInterval) with properties: {default=null, name=Set Update Interval, documentation=null, line=14, type=serviceTask}, Scope, Execution[id=30101, ProcessInstance(id)=30101, ProcessDefinition(id)='UpdateStatistics:1:63', ActvityDefinition(id)='setUpdateInterval'], definition_version: '$Revision: 1.2 $'

start Activity id=1370812, name='Manual Statistics Update' (definitionId=manualStatisticsUpdate) with properties: {default=null, name=Manual Statistics Update, documentation=null, line=16, timerDeclarations=[Timer [type=DURATION, expression='${updateInterval}', jobHandlerType=timer-transition, jobHandlerConfiguration=statisticsUpdateScheduleIntervalTimer, repeat=null, retries left = 3, exclusive=true]], type=userTask}, Scope, Execution[id=1370812, ProcessInstance(id)=30101, ProcessDefinition(id)='UpdateStatistics:1:63', ActvityDefinition(id)='manualStatisticsUpdate'], definition_version: '$Revision: 1.2 $'
…‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Note also the creation, update, and removal of process instance variables (only the update is shown here).

I didn't catch the "life" (creation, ending) of the process instance jobs and human tasks, which are also of interest to us.

It would be best if the log displays the database IDs of the activities, jobs and human tasks (we set the history level to the maximum).

[jbarrez]

It would be best if the log displays the database IDs of the activities, jobs and human tasks (we set the history level to the maximum).

If that is the requirement, why not using a dedicated slf4j logger that logs to your system (db, queue, etc.)?
If you put the logging on debug you get *everything* including all sql that goes to the db.

[mmaker1234]

Hello Joram,

Actually we are trying to find some balance between offline debug and security. For this purpose we, as developers, would like to know what and when happened for each process instance with all the attributes needed for eventual (manual) intervention in the process instance execution (preferably the DB IDs of activities, jobs, tasks). On the opposite, we should not reveal in the logs the data (variable values) of the process instance. And the SQL queries are not interesting to us at all.

I think that the verbosity balance cold be best controlled at generation time as it is easier to build/collect the needed information than to cut-off the "garbage".

The problem is that I'm still not sure which is the best point to catch the events I need to log - if there is (and which is it) a single point for all and any event where I to have at least the following information:
- the process instance ID and the process definition ID;
- the involved process instance object (type) - activity, boundary event, signal, job, task, etc.;
- event - start, end, …;
- additional data that uniquely identifies the object - object instance ID, object definition ID;
- variable(s) change;
- additional data related to the object instance - exception message/stack, retries, etc.

I suppose one such point of "knowledge concentration" are the listeners already provided by Activiti and here the question is "How to best use them to get the above info?"

[frederikherema1]

Not all listeners you need are provided by activiti. What we do provide is the task-listeners and execution-listeners which you can add to any element by using a ParseHandler.

For the rest, you could use an additional interceptor in the activiti-command-context interceptors (take a look at org.activiti.engine.impl.interceptor.LogInterceptor and org.activiti.engine.impl.cfg.StandaloneProcessEngineConfiguration.createDefaultCommandInterceptors(boolean)). This interceptor allows you to intercept all commands and possibly unwrap them (using reflection) and log what's about to happen or has happened after executing it. It will cover 95% of everything you want to have logged.

[mmaker1234]

Hello Frederik,

I did the following:
1. In the configuration file added    <property name="postBpmnParseHandlers">
      <list>
        <bean class="org.activiti.engine.parse.ActivityInstanceLoggersRegistrator" />
      </list>
    </property>2. Implemented ActivityInstanceLoggersRegistrator:public class ActivityInstanceLoggersRegistrator extends AbstractBpmnParseHandler<Activity> {

  private static final ActivityInstanceLogger ACTIVITI_INSTANCE_LOGGER = new ActivityInstanceLogger();
 
  protected void executeParse(BpmnParse bpmnParse, Activity element) {
    bpmnParse.getCurrentScope().addExecutionListener( org.activiti.engine.impl.pvm.PvmEvent.EVENTNAME_START, ACTIVITI_INSTANCE_LOGGER );
   
//    ActivityImpl activity = bpmnParse.getCurrentScope().findActivity(element.getId());
    ActivityImpl activity = bpmnParse.getCurrentActivity();
    activity.addExecutionListener(org.activiti.engine.impl.pvm.PvmEvent.EVENTNAME_START, ACTIVITI_INSTANCE_LOGGER, 0);
    activity.addExecutionListener(org.activiti.engine.impl.pvm.PvmEvent.EVENTNAME_END, ACTIVITI_INSTANCE_LOGGER);
    LoggerFactory.getLogger(ActivityInstanceLogger.class).info( "Registered execution listeners for activity '" + activity.getId() 
                                                                + "': (size=" + activity.getExecutionListeners().size() + ") "
                                                                + activity.getExecutionListeners() );
  }
}
3. Implemented ActivityInstanceLogger:  private static final Logger LOG = LoggerFactory.getLogger(ActivityInstanceLogger.class);

  @Override
  public void notify(DelegateExecution execution) throws Exception {
    LOG.info( execution.getEventName() + " " + formatInfo( execution ) );
  }
  …
Now the notify(…) method of the ActivityInstanceLogger class seems to be never called (debug doesn't stops there).

What I did wrong?

[jbarrez]

That could looks pretty similar to what I did in the AbstractBpmnParseHandler.

Do you see the logging produced by the parse handler?

If so, can you just throw together these files and put them somewhere online such that I can check them?

[mmaker1234]

Hello Joram,

Unfortunately I see no log traces from this implementation. As I doubt the configuration of SLF4J is not correct I tried to debug - just to see that my code is reached.

To shed more light to the environment I have to note that this code is working in a WebLogic domain, although I do not expect this fact to be related to the problem.

Preparing this answer I tried to "catch" the call to ActivityInstanceLoggersRegistrator.executeParse(…) but it was not called (the debugger didn't stop there). Probably the configuration is not correct …

Here is the sources package: https://docs.google.com/file/d/0B0LoSQX-9OwXTVVDcENWMml4cjQ/edit?usp=sharing

All .java files are located in the Activiti Engine (probably a habit from changing the previous versions) - modules/activiti-engine/src/main/java/org/activiti/engine/parse

The only trace from the Activiti after the engine is started is the following:INFO | 2013-03-18 18:25:52.931 (1363623952931) | ExecuteThread: '12' for queue: 'default' | org.activiti.engine.impl.bpmn.deployer.BpmnDeployer | deploy
Processing resource MyProcess.MyProcess.png

INFO | 2013-03-18 18:25:52.931 (1363623952931) | ExecuteThread: '12' for queue: 'default' | org.activiti.engine.impl.bpmn.deployer.BpmnDeployer | deploy
Processing resource MyProcess.bpmn

[jbarrez]

Okay i see what the issue probably is. The parse handlers don't work with inheritance.

Can you override the public Set<Class< ? extends BaseElement>> getHandledTypes() {
method and provide a set of classes you are interested in (but really like USerTask.class, StartEvent.class, etc.).

I remember vaguely there was a reason not to use inheritance there as it cause some unforseen issuee…

[mmaker1234]

Hello Joram,

Overriding the getHandledTypes() method did (most of) the work 

I had to override TimerDeclarationImpl.toString() in the following manner, though:  public String toString() {
    String result;
   
    result = "Timer [type=" + type
              + ", expression='" + description.getExpressionText() + "'"
              + ", jobHandlerType=" + jobHandlerType
              + ", jobHandlerConfiguration=" + jobHandlerConfiguration
              + ", repeat=" + repeat
              + ", retries left = " + retries
              + ", exclusive=" + exclusive
              + ", isInterrupting=" + isInterruptingTimer
              + "]";
   
    return result;
  }


[shrey]

This thread is very Informative. I have been trying almost the same things.
Thanks mmaker1234, Joram, Frederik.