feat(engine): Preserve External MDC Logging Properties

Description: The feature allows MDC Properties that are set externally by the User which have the same values as the Logging Context Parameter configured values (see ProcessEngineConfiguration) to be preserved and not cleared by the engine.

Notable points:
- External Properties are parked only in the case of outer commands
- The commit contains tests that cover the preservation of: 
    - Third party external properties
    - Logging context parameter properties
    - A mix of the two

Authored-by: petros.savvidis
Co-authored-by: danielkelemen
Related-to: camunda#2379

engine/src/main/java/org/camunda/bpm/engine/impl/context/Context.java

@@ -19,7 +19,6 @@
 import java.util.ArrayDeque;
 import java.util.Deque;
 import java.util.concurrent.Callable;
-
 import org.camunda.bpm.application.InvocationContext;
 import org.camunda.bpm.application.ProcessApplicationInterface;
 import org.camunda.bpm.application.ProcessApplicationReference;
@@ -83,10 +82,13 @@ public static void removeCommandInvocationContext() {
     if (stack.isEmpty()) {
       // do not clear when called from JobExecutor, will be cleared there after logging
       if (getJobExecutorContext() == null) {
+        // outer command remove flow
         currentContext.getProcessDataContext().clearMdc();
+        currentContext.getProcessDataContext().restoreExternalMDCProperties();
       }
     } else {
       // reset the MDC to the logging context of the outer command invocation
+      // inner command remove flow
       stack.peek().getProcessDataContext().updateMdcFromCurrentValues();
     }
   }

engine/src/main/java/org/camunda/bpm/engine/impl/interceptor/CommandContextInterceptor.java

@@ -88,9 +88,10 @@ public <T> T execute(Command<T> command) {
 
     // only create a new command context on the current command level (CAM-10002)
     boolean isNew = ProcessEngineContextImpl.consume();
-    boolean openNew = (context == null || isNew);
+    boolean isOuterCommand = (context == null);
+    boolean openNew = (isOuterCommand || isNew);
 
-    CommandInvocationContext commandInvocationContext = new CommandInvocationContext(command, processEngineConfiguration);
+    CommandInvocationContext commandInvocationContext = new CommandInvocationContext(command, processEngineConfiguration, isOuterCommand);
     Context.setCommandInvocationContext(commandInvocationContext);
 
     try {

engine/src/main/java/org/camunda/bpm/engine/impl/interceptor/CommandInvocationContext.java

@@ -45,13 +45,24 @@ public class CommandInvocationContext {
   protected Throwable throwable;
   protected Command< ? > command;
   protected boolean isExecuting = false;
-  protected List<AtomicOperationInvocation> queuedInvocations = new ArrayList<AtomicOperationInvocation>();
+  protected List<AtomicOperationInvocation> queuedInvocations = new ArrayList<>();
   protected BpmnStackTrace bpmnStackTrace = new BpmnStackTrace();
   protected ProcessDataContext processDataContext;
 
-  public CommandInvocationContext(Command<?> command, ProcessEngineConfigurationImpl configuration) {
+  /**
+   * All-args constructor.
+   *
+   * @param command        the associated command of this command invocation context.
+   * @param configuration  the process engine configuration
+   * @param isOuterCommand when true, the flag marks this command invocation context as outer and parks any MDC value
+   *                       associated with the Logging Context Parameters as external properties.
+   *                       when set to false, this command invocation context will be associated to an inner command,
+   *                       no external properties will be parked
+   */
+  public CommandInvocationContext(Command<?> command, ProcessEngineConfigurationImpl configuration, boolean isOuterCommand) {
     this.command = command;
-    this.processDataContext = new ProcessDataContext(configuration);
+    // only outer commands park external properties
+    this.processDataContext = new ProcessDataContext(configuration, false, isOuterCommand);
   }
 
   public Throwable getThrowable() {

engine/src/main/java/org/camunda/bpm/engine/impl/interceptor/ProcessDataContext.java

@@ -74,20 +74,37 @@ public class ProcessDataContext {
   protected Map<String, ProcessDataStack> mdcDataStacks = new HashMap<>();
   protected ProcessDataSections sections = new ProcessDataSections();
 
+  protected Map<String, String> externalProperties = new HashMap<>();
+
   public ProcessDataContext(ProcessEngineConfigurationImpl configuration) {
-    this(configuration, false);
+    this(configuration, false, false);
   }
 
   public ProcessDataContext(ProcessEngineConfigurationImpl configuration, boolean initFromCurrentMdc) {
+    this(configuration, initFromCurrentMdc, false);
+  }
+
+  /**
+   * All-args constructor.
+   *
+   * @param configuration          the process engine configuration to use to fetch Logging Context Parameters.
+   * @param initFromCurrentMdc     when true, this process data context will be populated from the current state of the MDC
+   * @param parkExternalProperties when true, the MDC tuples that are the same as the configured logging context parameters
+   *                               will be preserved separately in the process data context.
+   */
+  public ProcessDataContext(ProcessEngineConfigurationImpl configuration, boolean initFromCurrentMdc,
+                            boolean parkExternalProperties) {
     mdcPropertyActivityId = configuration.getLoggingContextActivityId();
 
     // always keep track of activity ids, because those are used to
     // populate the Job#getFailedActivityId field. This is independent
     // of the logging configuration
     activityIdStack = new ProcessDataStack(isNotBlank(mdcPropertyActivityId) ? mdcPropertyActivityId : null);
+
     if (isNotBlank(mdcPropertyActivityId)) {
       mdcDataStacks.put(mdcPropertyActivityId, activityIdStack);
     }
+
     mdcPropertyActivityName = initProperty(configuration::getLoggingContextActivityName);
     mdcPropertyApplicationName = initProperty(configuration::getLoggingContextApplicationName);
     mdcPropertyBusinessKey = initProperty(configuration::getLoggingContextBusinessKey);
@@ -97,6 +114,10 @@ public ProcessDataContext(ProcessEngineConfigurationImpl configuration, boolean
     mdcPropertyTenantId = initProperty(configuration::getLoggingContextTenantId);
     mdcPropertyEngineName = initProperty(configuration::getLoggingContextEngineName);
 
+    if (parkExternalProperties) {
+      parkExternalProperties(configuration);
+    }
+
     handleMdc = !mdcDataStacks.isEmpty();
 
     if (initFromCurrentMdc) {
@@ -111,6 +132,18 @@ public ProcessDataContext(ProcessEngineConfigurationImpl configuration, boolean
     }
   }
 
+  protected void parkExternalProperties(ProcessEngineConfigurationImpl configuration) {
+    parkExternalMDCProperty(configuration::getLoggingContextActivityId);
+    parkExternalMDCProperty(configuration::getLoggingContextActivityName);
+    parkExternalMDCProperty(configuration::getLoggingContextApplicationName);
+    parkExternalMDCProperty(configuration::getLoggingContextBusinessKey);
+    parkExternalMDCProperty(configuration::getLoggingContextProcessDefinitionId);
+    parkExternalMDCProperty(configuration::getLoggingContextProcessDefinitionKey);
+    parkExternalMDCProperty(configuration::getLoggingContextProcessInstanceId);
+    parkExternalMDCProperty(configuration::getLoggingContextTenantId);
+    parkExternalMDCProperty(configuration::getLoggingContextEngineName);
+  }
+
   protected String initProperty(final Supplier<String> configSupplier) {
     final String configValue = configSupplier.get();
     if (isNotBlank(configValue)) {
@@ -119,6 +152,15 @@ protected String initProperty(final Supplier<String> configSupplier) {
     return configValue;
   }
 
+  protected String parkExternalMDCProperty(final Supplier<String> configSupplier) {
+    final String configValue = configSupplier.get();
+
+    if (isNotBlank(configValue) && isNotBlank(MdcAccess.get(configValue))) {
+      externalProperties.put(configValue, MdcAccess.get(configValue));
+    }
+    return configValue;
+  }
+
   /**
    * Start a new section that keeps track of the pushed properties.
    *
@@ -193,6 +235,13 @@ public void clearMdc() {
     }
   }
 
+  /**
+   * Restores the external properties to the MDC. Meant to be called for ProcessDataContexts associated with outer commands.
+   */
+  public void restoreExternalMDCProperties() {
+    externalProperties.forEach(MdcAccess::put);
+  }
+
   /** Update the MDC with the current values of this logging context */
   public void updateMdcFromCurrentValues() {
     if (handleMdc) {

engine/src/test/java/org/camunda/bpm/engine/test/logging/ProcessDataLoggingContextTest.java

@@ -43,8 +43,10 @@
 import org.camunda.bpm.engine.test.util.ProvidedProcessEngineRule;
 import org.camunda.bpm.model.bpmn.Bpmn;
 import org.camunda.bpm.model.bpmn.BpmnModelInstance;
+import org.camunda.commons.logging.MdcAccess;
 import org.camunda.commons.testing.ProcessEngineLoggingRule;
 import org.camunda.commons.testing.WatchLogger;
+import org.jboss.logging.MDC;
 import org.junit.After;
 import org.junit.Before;
 import org.junit.ClassRule;
@@ -89,16 +91,20 @@ public class ProcessDataLoggingContextTest {
   private RuntimeService runtimeService;
   private TaskService taskService;
 
+  private TestMdcFacade testMDCFacade;
+
   @Before
   public void setupServices() {
     runtimeService = engineRule.getRuntimeService();
     taskService = engineRule.getTaskService();
     defaultEngineRegistered = false;
+    testMDCFacade = TestMdcFacade.empty();
   }
 
   @After
   public void resetClock() {
     ClockUtil.reset();
+    testMDCFacade.clear();
   }
 
   @After
@@ -164,6 +170,131 @@ public void shouldLogMdcPropertiesOnlyInActivityContext() {
     assertActivityLogsPresentWithoutMdc("ENGINE-130");
   }
 
+  @Test
+  @WatchLogger(loggerNames = {PVM_LOGGER, CMD_LOGGER}, level = "DEBUG")
+  public void shouldPreserveMDCExternalPropertiesAfterJobCompletion() {
+    // given
+
+    // a set of custom Logging Context parameters that populate the MDC prior to any process instance execution
+    testMDCFacade.withDefaultLoggingContextParameters(
+        "customActivityId",
+        "customActivityName",
+        "customApplicationName",
+        "customBusinessKey",
+        "customProcessDefinitionId",
+        "customProcessDefinitionKey",
+        "customProcessInstanceId",
+        "customTenantId",
+        "customEngineName"
+    );
+
+    // and a deployed process
+    manageDeployment(modelOneTaskProcess());
+
+    // when a process instance starts and completes
+    runtimeService.startProcessInstanceByKey(PROCESS, B_KEY);
+    taskService.complete(taskService.createTaskQuery().singleResult().getId());
+
+    // then the activity log events should use the process instance specific values (not their external property counterparts)
+    assertThat(loggingRule.getFilteredLog("ENGINE-200")).hasSize(13);
+
+    assertActivityLogsAtRange(0, 3, "start", "process:(.*):(.*)", "(\\d)+", "start", "testTenant", "businessKey1", "default");
+    assertActivityLogsAtRange(4, 7, "waitState", "process:(.*):(.*)", "(\\d)+", "waitState", "testTenant", "businessKey1", "default");
+    assertActivityLogsAtRange(8, 12, "end", "process:(.*):(.*)", "(\\d)+", "end", "testTenant", "businessKey1", "default");
+
+    // And the MDC External Properties are in the same state as prior to the commands execution
+    testMDCFacade.assertAllInsertedPropertiesAreInMdc();
+  }
+
+  @Test
+  @WatchLogger(loggerNames = {NestedLoggingDelegate.LOGGER_NAME}, level = "DEBUG")
+  public void shouldPreserveMDCExternalPropertiesInFlowsWithInnerCommands() {
+    // given
+
+    // a set of custom Logging Context parameters that populate the MDC prior to any process instance execution
+    testMDCFacade.withDefaultLoggingContextParameters(
+        "customActivityId",
+        "customActivityName",
+        "customApplicationName",
+        "customBusinessKey",
+        "customProcessDefinitionId",
+        "customProcessDefinitionKey",
+        "customProcessInstanceId",
+        "customTenantId",
+        "customEngineName"
+    );
+
+    manageDeployment(Bpmn.createExecutableProcess(PROCESS)
+        .startEvent("start")
+        .serviceTask("startProcess")
+        .camundaClass(NestedLoggingDelegate.class.getName())
+        .endEvent("end")
+        .done());
+
+    // when
+    ProcessInstance processInstance = runtimeService.startProcessInstanceByKey(PROCESS, B_KEY);
+
+    // then
+    List<ILoggingEvent> customLogs = loggingRule.getLog();
+
+    // Log events contain the execution specific MDC Properties
+    assertThat(customLogs).hasSize(2);
+
+    for (ILoggingEvent logEvent : customLogs) {
+      assertThat(logEvent.getMDCPropertyMap()).containsEntry("activityId", "startProcess");
+      assertThat(logEvent.getMDCPropertyMap()).containsEntry("businessKey", B_KEY);
+      assertThat(logEvent.getMDCPropertyMap()).containsEntry("processDefinitionId", processInstance.getProcessDefinitionId());
+      assertThat(logEvent.getMDCPropertyMap()).containsEntry("processInstanceId", processInstance.getId());
+      assertThat(logEvent.getMDCPropertyMap()).containsEntry("tenantId", processInstance.getTenantId());
+    }
+
+    // And the MDC External Properties are in the same state as prior to the commands execution
+    testMDCFacade.assertAllInsertedPropertiesAreInMdc();
+  }
+
+  @Test
+  @WatchLogger(loggerNames = {PVM_LOGGER, CMD_LOGGER}, level = "DEBUG")
+  public void shouldPreserveThirdPartyMDCProperties() {
+    // given
+
+    // Logging Context Properties
+    testMDCFacade.withDefaultLoggingContextParameters(
+        "customActivityId",
+        "customActivityName",
+        "customApplicationName",
+        "customBusinessKey",
+        "customProcessDefinitionId",
+        "customProcessDefinitionKey",
+        "customProcessInstanceId",
+        "customTenantId",
+        "customEngineName"
+    );
+
+    // And a custom property that does not belong to the logging context properties
+    testMDCFacade.withMDCProperty("thirdPartyProperty", "withAValue");
+
+    // and a deployed process
+    manageDeployment(modelOneTaskProcess());
+
+    // when a process instance starts and completes
+    runtimeService.startProcessInstanceByKey(PROCESS, B_KEY);
+    taskService.complete(taskService.createTaskQuery().singleResult().getId());
+
+    // then the activity log events should use the process instance specific values (not their external property counterparts)
+    assertThat(loggingRule.getFilteredLog("ENGINE-200")).hasSize(13);
+
+    assertActivityLogsAtRange(0, 3, "start", "process:(.*):(.*)", "(\\d)+", "start", "testTenant", "businessKey1", "default");
+    assertActivityLogsAtRange(4, 7, "waitState", "process:(.*):(.*)", "(\\d)+", "waitState", "testTenant", "businessKey1", "default");
+    assertActivityLogsAtRange(8, 12, "end", "process:(.*):(.*)", "(\\d)+", "end", "testTenant", "businessKey1", "default");
+
+    // and the MDC should contain both the logging context properties & the third party property prior to any command execution
+    Map<String, Object> mdcMap = MDC.getMap();
+
+    assertThat(mdcMap).hasSize(10);
+
+    testMDCFacade.assertAllInsertedPropertiesAreInMdc();
+  }
+
   @Test
   @WatchLogger(loggerNames = {PVM_LOGGER, CMD_LOGGER}, level = "DEBUG")
   public void shouldLogCustomMdcPropertiesOnlyInActivityContext() {
@@ -661,6 +792,37 @@ public void createDeployment(String processArchiveName, DeploymentBuilder deploy
     assertFailureLogInApplication(instance, "failingTask", application.getName());
   }
 
+  protected void assertActivityLogsAtRange(int start, int end, String activityId, String processDefinitionId,
+                                           String processInstanceId, String activityName, String tenantId, String businessKey,
+                                           String engineName) {
+    for (int i=start; i <= end; i++) {
+      assertActivityLogsAtIndex(i, activityId, processDefinitionId, processInstanceId, activityName, tenantId, businessKey, engineName);
+    }
+  }
+
+  protected void assertActivityLogsAtIndex(int index, String activityId, String processDefinitionIdRegex, String processInstanceIdRegex,
+                                    String activityName, String tenantId, String businessKey, String engineName) {
+    List<ILoggingEvent> logs = loggingRule.getFilteredLog("ENGINE-200");
+    ILoggingEvent logEvent = logs.get(index);
+
+    Map<String, String> mdcPropertyMap = logEvent.getMDCPropertyMap();
+
+    assertThat(mdcPropertyMap.get("processDefinitionId")).matches(processDefinitionIdRegex);
+    assertThat(mdcPropertyMap.get("processInstanceId")).matches(processInstanceIdRegex);
+
+    assertThat(mdcPropertyMap).containsEntry("activityId", activityId);
+    assertThat(mdcPropertyMap).containsEntry("activityName", activityName);
+    assertThat(mdcPropertyMap).containsEntry("tenantId", tenantId);
+    assertThat(mdcPropertyMap).containsEntry("businessKey", businessKey);
+    assertThat(mdcPropertyMap).containsEntry("engineName", engineName);
+  }
+
+  protected void clearMDCFromProperties(String... properties) {
+    for (String property : properties) {
+      MdcAccess.remove(property);
+    }
+  }
+
   protected void assertActivityLogsPresent(ProcessInstance instance, List<String> expectedActivities) {
     assertActivityLogs(instance, "ENGINE-200", expectedActivities, true, true, true, true, "default");
   }