Integrating MDC Logging into all Logging Messages

[miniscem]

Hello, 

I would like to use a custom mdc logging pattern and with my own custom key and values to all messages logged within and outside the activiti engine without adding each custom property to the LogMDC context in every delegate or action listener.

I've implemented the solution suggested here:  https://community.alfresco.com/message/766907-mdc-logging-from-methods-called-with-spring-expression..., which will only log messages in mdc format within the command context. My implementation sets the adds the custom MDC logging (key, value) pairs within a class that implements ProcessEngineConfigurationConfigurer and calls the setcommandContextFactory() on the SpringProcessEngineConfiguration objects passed to processEngineConfigurationInitialized(). Is this the best place to set the command context? Second, are there any other places within the activiti engine startup lifecycle where I can set the MDC logging configuration so as to log with MDC context in all logging messages (up until this point I've been focusing on command contexts only)?

I've also read and successfully implemented the changes to log4j mentioned here: Activiti User Guide  

Any help would be greatly appreciated. 

[jearles]

Mark,
I'm not super familiar with MDC logging in general, but I'm looking into the details a bit more to see if we can get this going.

-JEarles

‌

[miniscem]

Thank you Jonathan. While I have been able to configure a custom command context to perform MDC logging, the command context appears only to be executing in custom java delegates. I received the same results when calling setCommandContext() on a ProcessEngineConfigurationImpl object from within a class implementing ProcessEngineConfigurator - this class was configured using the ServiceLoader approach noted in the Activiti documentation. 

[jearles]

Is this the best place to set the command context?

This does seem like the most logical location to place this; while there aren't really any requirements for the placement of this configuration, it just makes sense to place all of your ProcessEngine initializations in the same place.

Relating to your more recent comment, the ServiceLoader method is just a more modular approach - from my understanding, there shouldn't be any difference in how Activiti sees the implementation at runtime.

Are there any other places within the activiti engine startup lifecycle where I can set the MDC logging configuration so as to log with MDC context in all logging messages?

I may be misunderstanding the implementation details of MDC, but it seems like - so long as the context parameters are set for the running thread, and the log4j conversion pattern is established, then all log4j messages should follow the modified pattern. You're saying that only the custom java delegates utilize the conversion pattern?

-JEarles

[miniscem]

This gets to the core of the question: what is the 'correct' (or recommended) way to configure the process engine with our custom MDC logging properties?

My logging pattern is always followed (defined in log4j.properties) but the custom properties in my logging pattern need to be configured so they can be injected in the log files. Here is my pattern:

log4j.appender.File.layout.ConversionPattern=%d{ISO8601} %-5p [%c] %X{mdcAuthenticatedUser}/%X{mdcProcessDefinitionID}/%X{mdcProcessInstanceID} %m%n

The "//" part of the pattern always appear in the logs - so I know the MDC is pattern is working, but the values for variables: mdcAuthenticatedUser, mdcProcessDefinitionID, mdcProcessInstanceID do not (note: the first is a custom property being assigned in application logic, and the latter two are being assigned through Activiti's LogMDC class). 

As of now, I'm trying to make these custom properties appear in every logging message by setting them up in a custom class that implements CommandContextFactory and then calling setCommandContext() on a ProcessEngineConfigurationImpl object from within a class implementing ProcessEngineConfigurator. However, not all messaged logged are appearing with my custom properties. 

What other strategies can I use to ensure that as many logging messages as possible contain values for my custom logging properties: mdcAuthenticatedUser, mdcProcessDefinitionID, mdcProcessInstanceID?

[jearles]

Just out of curiosity, have you debugged the LogMDC class to check that those MDC parameters are indeed being set with values? I'm mostly just wanting to make sure that all of the components are actually being loaded and utilized - if they are, then we can cross that off the potential problem list.

Another quick verification, the built in MDC parameters (processDefinitionId, processInstanceId & processBusinessKey) all work, is that correct? Or are those not showing up consistently either?

[miniscem]

The LogMDC class appears to be working correctly when it is called in when creating a command context. Activiti only references it from within 3 different classes: CommandContext, TimerCatchIntermediateJobHandler, AtomicOperationActivitiyExecute. Additionally, within these three classes, the LogMDC class is only used from within exception handler code - so it's evident that mapped diagnostic contexts are not used heavily from within the Activiti codebase. 

While this may be fine default activiti behavior, we have a requirement to call LogMDC.putMDCExecution() within our own code -- I *think* this can be accomplished by adding some configuration to the activiti process engine but I'm not 100% positive. As mentioned above, I am attempting to add this configuration by setting a custom command context at process engine configuration time. Within the command context, the LogMDC.putMDCExecution() will be called within the CustomCommandContext's performOperation() call. 

[lwoznicki]

performOperation method was removed in activiti 6. Any idea to put use pudMDCExecution in activiti engine?