diff --git a/docs/documentation/features.md b/docs/documentation/features.md index 7f77bcbbde..9b8e2fb099 100644 --- a/docs/documentation/features.md +++ b/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). + diff --git a/operator-framework-core/pom.xml b/operator-framework-core/pom.xml index ce8115829a..af0737bf29 100644 --- a/operator-framework-core/pom.xml +++ b/operator-framework-core/pom.xml @@ -62,6 +62,18 @@ org.slf4j slf4j-api + + org.apache.logging.log4j + log4j-slf4j-impl + test + + + org.apache.logging.log4j + log4j-core + ${log4j.version} + test-jar + test + org.junit.jupiter diff --git a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/DefaultEventHandler.java b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/DefaultEventHandler.java index 212cd378d7..9b5c10d877 100644 --- a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/DefaultEventHandler.java +++ b/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 latestCustomResource = - resourceCache.getCustomResource(customResourceUid); - - if (!controllerUnderExecution - && latestCustomResource.isPresent()) { - setUnderExecutionProcessing(customResourceUid); - final var retryInfo = retryInfo(customResourceUid); - ExecutionScope 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 latestCustomResource = + resourceCache.getCustomResource(customResourceUid); + latestCustomResource.ifPresent(MDCUtils::addCustomResourceInfo); + if (!controllerUnderExecution + && latestCustomResource.isPresent()) { + setUnderExecutionProcessing(customResourceUid); + final var retryInfo = retryInfo(customResourceUid); + ExecutionScope 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,6 +356,7 @@ public void run() { final var thread = Thread.currentThread(); final var name = thread.getName(); try { + MDCUtils.addCustomResourceInfo(executionScope.getCustomResource()); thread.setName("EventHandler-" + controllerName); PostExecutionControl postExecutionControl = eventDispatcher.handleExecution(executionScope); @@ -358,6 +364,7 @@ public void run() { } finally { // restore original name thread.setName(name); + MDCUtils.removeCustomResourceInfo(); } } diff --git a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/MDCUtils.java b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/MDCUtils.java new file mode 100644 index 0000000000..e68312c451 --- /dev/null +++ b/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); + } +} diff --git a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/internal/CustomResourceEventSource.java b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/internal/CustomResourceEventSource.java index a9a80c10f3..8845c599c6 100644 --- a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/internal/CustomResourceEventSource.java +++ b/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(); } } diff --git a/operator-framework-core/src/test/java/io/javaoperatorsdk/operator/TestUtils.java b/operator-framework-core/src/test/java/io/javaoperatorsdk/operator/TestUtils.java index 49dc35abdb..5e15fd59c8 100644 --- a/operator-framework-core/src/test/java/io/javaoperatorsdk/operator/TestUtils.java +++ b/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"); diff --git a/operator-framework-core/src/test/resources/log4j2.xml b/operator-framework-core/src/test/resources/log4j2.xml index f23cf772dd..68add1ab41 100644 --- a/operator-framework-core/src/test/resources/log4j2.xml +++ b/operator-framework-core/src/test/resources/log4j2.xml @@ -2,7 +2,7 @@ - +