feat: contextual information about processing for loging using MDC

docs/documentation/features.md

@@ -33,6 +33,23 @@ permalink: /docs/features
 
 ## Monitoring with Micrometer
 
+## Contextual Info for Logging with MDC
+
+Logging is enhanced with additional contextual information using [MDC](http://www.slf4j.org/manual.html#mdc). 
+This following attributes are available in most parts of reconciliation logic and during the execution of the controller:
+
+| MDC Key      | Value added from Custom Resource |
+| :---        |    :---   | 
+| `resource.apiVersion`   | `.apiVersion` |
+| `resource.kind`   | `.kind` |
+| `resource.name`      | `.metadata.name` | 
+| `resource.namespace`   | `.metadata.namespace` |
+| `resource.resourceVersion`   | `.metadata.resourceVersion` |
+| `resource.generation`   | `.metadata.generation` |
+| `resource.uid`   | `.metadata.uid` |
+
+For more information about MDC see this [link](https://www.baeldung.com/mdc-in-log4j-2-logback).
+
 
 
 

operator-framework-core/pom.xml

@@ -62,6 +62,18 @@
       <groupId>org.slf4j</groupId>
       <artifactId>slf4j-api</artifactId>
     </dependency>
+    <dependency>
+      <groupId>org.apache.logging.log4j</groupId>
+      <artifactId>log4j-slf4j-impl</artifactId>
+      <scope>test</scope>
+    </dependency>
+    <dependency>
+      <groupId>org.apache.logging.log4j</groupId>
+      <artifactId>log4j-core</artifactId>
+      <version>${log4j.version}</version>
+      <type>test-jar</type>
+      <scope>test</scope>
+    </dependency>
 
     <dependency>
       <groupId>org.junit.jupiter</groupId>

operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/DefaultEventHandler.java

@@ -103,6 +103,7 @@ public void handleEvent(Event event) {
         return;
       }
       final var resourceID = event.getRelatedCustomResourceID();
+      MDCUtils.addCustomResourceIDInfo(resourceID);
       metrics.receivedEvent(event);
 
       handleEventMarking(event);
@@ -111,40 +112,44 @@ public void handleEvent(Event event) {
       } else {
         cleanupForDeletedEvent(resourceID);
       }
-
     } finally {
       lock.unlock();
+      MDCUtils.removeCustomResourceIDInfo();
     }
   }
 
   private void submitReconciliationExecution(CustomResourceID customResourceUid) {
-    boolean controllerUnderExecution = isControllerUnderExecution(customResourceUid);
-    Optional<R> latestCustomResource =
-        resourceCache.getCustomResource(customResourceUid);
-
-    if (!controllerUnderExecution
-        && latestCustomResource.isPresent()) {
-      setUnderExecutionProcessing(customResourceUid);
-      final var retryInfo = retryInfo(customResourceUid);
-      ExecutionScope<R> executionScope =
-          new ExecutionScope<>(
-              latestCustomResource.get(),
-              retryInfo);
-      eventMarker.unMarkEventReceived(customResourceUid);
-      metrics.reconcileCustomResource(customResourceUid, retryInfo);
-      log.debug("Executing events for custom resource. Scope: {}", executionScope);
-      executor.execute(new ControllerExecution(executionScope));
-    } else {
-      log.debug(
-          "Skipping executing controller for resource id: {}."
-              + " Controller in execution: {}. Latest CustomResource present: {}",
-          customResourceUid,
-          controllerUnderExecution,
-          latestCustomResource.isPresent());
-      if (latestCustomResource.isEmpty()) {
-        log.warn("no custom resource found in cache for CustomResourceID: {}",
-            customResourceUid);
+    try {
+      boolean controllerUnderExecution = isControllerUnderExecution(customResourceUid);
+      Optional<R> latestCustomResource =
+          resourceCache.getCustomResource(customResourceUid);
+      latestCustomResource.ifPresent(MDCUtils::addCustomResourceInfo);
+      if (!controllerUnderExecution
+          && latestCustomResource.isPresent()) {
+        setUnderExecutionProcessing(customResourceUid);
+        final var retryInfo = retryInfo(customResourceUid);
+        ExecutionScope<R> executionScope =
+            new ExecutionScope<>(
+                latestCustomResource.get(),
+                retryInfo);
+        eventMarker.unMarkEventReceived(customResourceUid);
+        metrics.reconcileCustomResource(customResourceUid, retryInfo);
+        log.debug("Executing events for custom resource. Scope: {}", executionScope);
+        executor.execute(new ControllerExecution(executionScope));
+      } else {
+        log.debug(
+            "Skipping executing controller for resource id: {}."
+                + " Controller in execution: {}. Latest CustomResource present: {}",
+            customResourceUid,
+            controllerUnderExecution,
+            latestCustomResource.isPresent());
+        if (latestCustomResource.isEmpty()) {
+          log.warn("no custom resource found in cache for CustomResourceID: {}",
+              customResourceUid);
+        }
       }
+    } finally {
+      MDCUtils.removeCustomResourceInfo();
     }
   }
 
@@ -351,13 +356,15 @@ public void run() {
       final var thread = Thread.currentThread();
       final var name = thread.getName();
       try {
+        MDCUtils.addCustomResourceInfo(executionScope.getCustomResource());
         thread.setName("EventHandler-" + controllerName);
         PostExecutionControl<R> postExecutionControl =
             eventDispatcher.handleExecution(executionScope);
         eventProcessingFinished(executionScope, postExecutionControl);
       } finally {
         // restore original name
         thread.setName(name);
+        MDCUtils.removeCustomResourceInfo();
       }
     }
 

operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/MDCUtils.java

@@ -0,0 +1,47 @@
+package io.javaoperatorsdk.operator.processing;
+
+import org.slf4j.MDC;
+
+import io.fabric8.kubernetes.client.CustomResource;
+import io.javaoperatorsdk.operator.processing.event.CustomResourceID;
+
+public class MDCUtils {
+
+  private static final String NAME = "resource.name";
+  private static final String NAMESPACE = "resource.namespace";
+  private static final String API_VERSION = "resource.apiVersion";
+  private static final String KIND = "resource.kind";
+  private static final String RESOURCE_VERSION = "resource.resourceVersion";
+  private static final String GENERATION = "resource.generation";
+  private static final String UID = "resource.uid";
+
+  public static void addCustomResourceIDInfo(CustomResourceID customResourceID) {
+    MDC.put(NAME, customResourceID.getName());
+    MDC.put(NAMESPACE, customResourceID.getNamespace().orElse("no namespace"));
+  }
+
+  public static void removeCustomResourceIDInfo() {
+    MDC.remove(NAME);
+    MDC.remove(NAMESPACE);
+  }
+
+  public static void addCustomResourceInfo(CustomResource<?, ?> customResource) {
+    MDC.put(API_VERSION, customResource.getApiVersion());
+    MDC.put(KIND, customResource.getKind());
+    MDC.put(NAME, customResource.getMetadata().getName());
+    MDC.put(NAMESPACE, customResource.getMetadata().getNamespace());
+    MDC.put(RESOURCE_VERSION, customResource.getMetadata().getResourceVersion());
+    MDC.put(GENERATION, customResource.getMetadata().getGeneration().toString());
+    MDC.put(UID, customResource.getMetadata().getUid());
+  }
+
+  public static void removeCustomResourceInfo() {
+    MDC.remove(API_VERSION);
+    MDC.remove(KIND);
+    MDC.remove(NAME);
+    MDC.remove(NAMESPACE);
+    MDC.remove(RESOURCE_VERSION);
+    MDC.remove(GENERATION);
+    MDC.remove(UID);
+  }
+}

operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/internal/CustomResourceEventSource.java

@@ -15,6 +15,7 @@
 import io.javaoperatorsdk.operator.api.config.Cloner;
 import io.javaoperatorsdk.operator.api.config.ControllerConfiguration;
 import io.javaoperatorsdk.operator.processing.ConfiguredController;
+import io.javaoperatorsdk.operator.processing.MDCUtils;
 import io.javaoperatorsdk.operator.processing.ResourceCache;
 import io.javaoperatorsdk.operator.processing.event.AbstractEventSource;
 import io.javaoperatorsdk.operator.processing.event.CustomResourceID;
@@ -116,17 +117,21 @@ public void stop() {
   }
 
   public void eventReceived(ResourceAction action, T customResource, T oldResource) {
-    log.debug(
-        "Event received for resource: {}", getName(customResource));
-
-    if (filter.acceptChange(controller.getConfiguration(), oldResource, customResource)) {
-      eventHandler.handleEvent(
-          new CustomResourceEvent(action, CustomResourceID.fromResource(customResource)));
-    } else {
+    try {
       log.debug(
-          "Skipping event handling resource {} with version: {}",
-          getUID(customResource),
-          getVersion(customResource));
+          "Event received for resource: {}", getName(customResource));
+      MDCUtils.addCustomResourceInfo(customResource);
+      if (filter.acceptChange(controller.getConfiguration(), oldResource, customResource)) {
+        eventHandler.handleEvent(
+            new CustomResourceEvent(action, CustomResourceID.fromResource(customResource)));
+      } else {
+        log.debug(
+            "Skipping event handling resource {} with version: {}",
+            getUID(customResource),
+            getVersion(customResource));
+      }
+    } finally {
+      MDCUtils.removeCustomResourceInfo();
     }
   }
 

operator-framework-core/src/test/java/io/javaoperatorsdk/operator/TestUtils.java

@@ -37,7 +37,6 @@ public static TestCustomResource testCustomResource(CustomResourceID id) {
             .withNamespace(id.getNamespace().orElse(null))
             .build());
     resource.getMetadata().setAnnotations(new HashMap<>());
-    resource.setKind("CustomService");
     resource.setSpec(new TestCustomResourceSpec());
     resource.getSpec().setConfigMapName("test-config-map");
     resource.getSpec().setKey("test-key");

operator-framework-core/src/test/resources/log4j2.xml

@@ -2,7 +2,7 @@
 <Configuration status="WARN">
   <Appenders>
     <Console name="Console" target="SYSTEM_OUT">
-      <PatternLayout pattern="%d %threadId %-30c{1.} [%-5level] %msg%n%throwable"/>
+      <PatternLayout pattern="%d %threadId %-30c{1.} [%-5level] resource.name=%X{resource.name} %msg%n%throwable "/>
     </Console>
   </Appenders>
   <Loggers>