topic Re: Best process instance 'verbose' logging strategy in Alfresco Archive

Best process instance 'verbose' logging strategy

mmaker1234 — Fri, 08 Mar 2013 15:17:14 GMT

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

Re: Best process instance 'verbose' logging strategy

jbarrez — Mon, 11 Mar 2013 10:22:12 GMT

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.

Re: Best process instance 'verbose' logging strategy

mmaker1234 — Mon, 11 Mar 2013 11:58:19 GMT

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?"

Re: Best process instance 'verbose' logging strategy

frederikherema1 — Tue, 12 Mar 2013 08:05:23 GMT

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.

Re: Best process instance 'verbose' logging strategy

mmaker1234 — Mon, 18 Mar 2013 15:25:18 GMT

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?

Re: Best process instance 'verbose' logging strategy

jbarrez — Mon, 18 Mar 2013 16:00:20 GMT

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?

Re: Best process instance 'verbose' logging strategy

mmaker1234 — Mon, 18 Mar 2013 17:08:30 GMT

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

Re: Best process instance 'verbose' logging strategy

jbarrez — Fri, 22 Mar 2013 17:14:35 GMT

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…

Re: Best process instance 'verbose' logging strategy

mmaker1234 — Tue, 02 Apr 2013 12:47:13 GMT

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;
  }

Re: Best process instance 'verbose' logging strategy

shrey — Sun, 18 Oct 2015 12:14:52 GMT

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