improve: logging for resource filter cache (#3167)

Signed-off-by: Attila Mészáros <a_meszaros@apple.com>
Co-authored-by: Chris Laprun <metacosm@gmail.com>

Author: csviri

docs/content/en/docs/documentation/observability.md

@@ -33,6 +33,28 @@ parts of reconciliation logic and during the execution of the controller:
 
 For more information about MDC see this [link](https://www.baeldung.com/mdc-in-log4j-2-logback).
 
+### MDC entries during event handling
+
+Although, usually users might not require it in their day-to-day workflow, it is worth mentioning that 
+there are additional MDC entries managed for event handling. Typically, you might be interested in it
+in your `SecondaryToPrimaryMapper` related logs.
+For `InformerEventSource` and `ControllerEventSource` the following information is present:
+
+| MDC Key                                        | Value from Resource from the Event               |
+|:-----------------------------------------------|:-------------------------------------------------|
+| `eventsource.event.resource.name`              | `.metadata.name`                                 |
+| `eventsource.event.resource.uid`               | `.metadata.uid`                                  |
+| `eventsource.event.resource.namespace`         | `.metadata.namespace`                            |
+| `eventsource.event.resource.kind`              | resource kind                                    |
+| `eventsource.event.resource.resourceVersion`   | `.metadata.resourceVersion`                      |
+| `eventsource.event.action`                     | action name (e.g. `ADDED`, `UPDATED`, `DELETED`) |
+| `eventsource.name`                             | name of the event source                         |
+
+### Disabling MDC support
+
+MDC support is enabled by default. If you want to disable it, you can set the `JAVA_OPERATOR_SDK_USE_MDC` environment
+variable to `false` when you start your operator.
+
 ## Metrics
 
 JOSDK provides built-in support for metrics reporting on what is happening with your reconcilers in the form of

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

@@ -20,6 +20,7 @@
 import io.fabric8.kubernetes.api.model.HasMetadata;
 import io.javaoperatorsdk.operator.api.config.Utils;
 import io.javaoperatorsdk.operator.processing.event.ResourceID;
+import io.javaoperatorsdk.operator.processing.event.source.ResourceAction;
 
 public class MDCUtils {
 
@@ -34,6 +35,72 @@ public class MDCUtils {
   private static final boolean enabled =
       Utils.getBooleanFromSystemPropsOrDefault(Utils.USE_MDC_ENV_KEY, true);
 
+  private static final String EVENT_RESOURCE_NAME = "eventsource.event.resource.name";
+  private static final String EVENT_RESOURCE_UID = "eventsource.event.resource.uid";
+  private static final String EVENT_RESOURCE_NAMESPACE = "eventsource.event.resource.namespace";
+  private static final String EVENT_RESOURCE_KIND = "eventsource.event.resource.kind";
+  private static final String EVENT_RESOURCE_VERSION = "eventsource.event.resource.resourceVersion";
+  private static final String EVENT_ACTION = "eventsource.event.action";
+  private static final String EVENT_SOURCE_NAME = "eventsource.name";
+
+  public static void addInformerEventInfo(
+      HasMetadata resource, ResourceAction action, String eventSourceName) {
+    if (enabled) {
+      MDC.put(EVENT_RESOURCE_NAME, resource.getMetadata().getName());
+      MDC.put(EVENT_RESOURCE_NAMESPACE, resource.getMetadata().getNamespace());
+      MDC.put(EVENT_RESOURCE_KIND, HasMetadata.getKind(resource.getClass()));
+      MDC.put(EVENT_RESOURCE_VERSION, resource.getMetadata().getResourceVersion());
+      MDC.put(EVENT_RESOURCE_UID, resource.getMetadata().getUid());
+      MDC.put(EVENT_ACTION, action == null ? null : action.name());
+      MDC.put(EVENT_SOURCE_NAME, eventSourceName);
+    }
+  }
+
+  public static void removeInformerEventInfo() {
+    if (enabled) {
+      MDC.remove(EVENT_RESOURCE_NAME);
+      MDC.remove(EVENT_RESOURCE_NAMESPACE);
+      MDC.remove(EVENT_RESOURCE_KIND);
+      MDC.remove(EVENT_RESOURCE_VERSION);
+      MDC.remove(EVENT_RESOURCE_UID);
+      MDC.remove(EVENT_ACTION);
+      MDC.remove(EVENT_SOURCE_NAME);
+    }
+  }
+
+  public static void withMDCForEvent(
+      HasMetadata resource, Runnable runnable, String eventSourceName) {
+    withMDCForEvent(resource, null, runnable, eventSourceName);
+  }
+
+  public static void withMDCForEvent(
+      HasMetadata resource, ResourceAction action, Runnable runnable, String eventSourceName) {
+    try {
+      MDCUtils.addInformerEventInfo(resource, action, eventSourceName);
+      runnable.run();
+    } finally {
+      MDCUtils.removeInformerEventInfo();
+    }
+  }
+
+  public static void withMDCForResourceID(ResourceID resourceID, Runnable runnable) {
+    try {
+      MDCUtils.addResourceIDInfo(resourceID);
+      runnable.run();
+    } finally {
+      MDCUtils.removeResourceIDInfo();
+    }
+  }
+
+  public static void withMDCForPrimary(HasMetadata primary, Runnable runnable) {
+    try {
+      MDCUtils.addResourceInfo(primary);
+      runnable.run();
+    } finally {
+      MDCUtils.removeResourceInfo();
+    }
+  }
+
   public static void addResourceIDInfo(ResourceID resourceID) {
     if (enabled) {
       MDC.put(NAME, resourceID.getName());

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

@@ -44,8 +44,6 @@
 import io.javaoperatorsdk.operator.processing.retry.Retry;
 import io.javaoperatorsdk.operator.processing.retry.RetryExecution;
 
-import static io.javaoperatorsdk.operator.processing.KubernetesResourceUtils.getName;
-
 public class EventProcessor<P extends HasMetadata> implements EventHandler, LifecycleAware {
 
   private static final Logger log = LoggerFactory.getLogger(EventProcessor.class);
@@ -187,9 +185,8 @@ private void submitReconciliationExecution(ResourceState state) {
         executor.execute(new ReconcilerExecutor(resourceID, executionScope));
       } else {
         log.debug(
-            "Skipping executing controller for resource id: {}. Controller in execution: {}. Latest"
+            "Skipping executing controller. Controller in execution: {}. Latest"
                 + " Resource present: {}",
-            resourceID,
             controllerUnderExecution,
             maybeLatest.isPresent());
         if (maybeLatest.isEmpty()) {
@@ -198,7 +195,7 @@ private void submitReconciliationExecution(ResourceState state) {
           // resource. Other is that simply there is no primary resource present for an event, this
           // might indicate issue with the implementation, but could happen also naturally, thus
           // this is not necessarily a problem.
-          log.debug("no primary resource found in cache with resource id: {}", resourceID);
+          log.debug("No primary resource found in cache with resource id: {}", resourceID);
         }
       }
     } finally {
@@ -209,7 +206,7 @@ private void submitReconciliationExecution(ResourceState state) {
   @SuppressWarnings("unchecked")
   private P getResourceFromState(ResourceState state) {
     if (triggerOnAllEvents()) {
-      log.debug("Getting resource from state for {}", state.getId());
+      log.debug("Getting resource from state");
       return (P) state.getLastKnownResource();
     } else {
       throw new IllegalStateException(
@@ -218,19 +215,17 @@ private P getResourceFromState(ResourceState state) {
   }
 
   private void handleEventMarking(Event event, ResourceState state) {
-    final var relatedCustomResourceID = event.getRelatedCustomResourceID();
     if (event instanceof ResourceEvent resourceEvent) {
       if (resourceEvent.getAction() == ResourceAction.DELETED) {
-        log.debug("Marking delete event received for: {}", relatedCustomResourceID);
+        log.debug("Marking delete event received");
         state.markDeleteEventReceived(
             resourceEvent.getResource().orElseThrow(),
             ((ResourceDeleteEvent) resourceEvent).isDeletedFinalStateUnknown());
       } else {
         if (state.processedMarkForDeletionPresent() && isResourceMarkedForDeletion(resourceEvent)) {
           log.debug(
               "Skipping mark of event received, since already processed mark for deletion and"
-                  + " resource marked for deletion: {}",
-              relatedCustomResourceID);
+                  + " resource marked for deletion");
           return;
         }
         // Normally when eventMarker is in state PROCESSED_MARK_FOR_DELETION it is expected to
@@ -260,8 +255,7 @@ private boolean isResourceMarkedForDeletion(ResourceEvent resourceEvent) {
 
   private void handleRateLimitedSubmission(ResourceID resourceID, Duration minimalDuration) {
     var minimalDurationMillis = minimalDuration.toMillis();
-    log.debug(
-        "Rate limited resource: {}, rescheduled in {} millis", resourceID, minimalDurationMillis);
+    log.debug("Rate limited resource; rescheduled in {} millis", minimalDurationMillis);
     retryEventSource()
         .scheduleOnce(
             resourceID, Math.max(minimalDurationMillis, MINIMAL_RATE_LIMIT_RESCHEDULE_DURATION));
@@ -334,7 +328,7 @@ private void reScheduleExecutionIfInstructed(
         .ifPresentOrElse(
             delay -> {
               var resourceID = ResourceID.fromResource(customResource);
-              log.debug("Rescheduling event for resource: {} with delay: {}", resourceID, delay);
+              log.debug("Rescheduling event with delay: {}", delay);
               retryEventSource().scheduleOnce(resourceID, delay);
             },
             () -> scheduleExecutionForMaxReconciliationInterval(customResource));
@@ -347,11 +341,7 @@ private void scheduleExecutionForMaxReconciliationInterval(P customResource) {
             m -> {
               var resourceID = ResourceID.fromResource(customResource);
               var delay = m.toMillis();
-              log.debug(
-                  "Rescheduling event for max reconciliation interval for resource: {} : "
-                      + "with delay: {}",
-                  resourceID,
-                  delay);
+              log.debug("Rescheduling event for max reconciliation interval with delay: {}", delay);
               retryEventSource().scheduleOnce(resourceID, delay);
             });
   }
@@ -375,16 +365,15 @@ private void handleRetryOnException(ExecutionScope<P> executionScope, Exception
 
     retryAwareErrorLogging(state.getRetry(), eventPresent, exception, executionScope);
     if (eventPresent) {
-      log.debug("New events exists for for resource id: {}", resourceID);
+      log.debug("New events exist for resource id");
       submitReconciliationExecution(state);
       return;
     }
     Optional<Long> nextDelay = state.getRetry().nextDelay();
 
     nextDelay.ifPresentOrElse(
         delay -> {
-          log.debug(
-              "Scheduling timer event for retry with delay:{} for resource: {}", delay, resourceID);
+          log.debug("Scheduling timer event for retry with delay:{}", delay);
           metrics.failedReconciliation(executionScope.getResource(), exception, metricsMetadata);
           retryEventSource().scheduleOnce(resourceID, delay);
         },
@@ -425,8 +414,7 @@ private void retryAwareErrorLogging(
   }
 
   private void cleanupOnSuccessfulExecution(ExecutionScope<P> executionScope) {
-    log.debug(
-        "Cleanup for successful execution for resource: {}", getName(executionScope.getResource()));
+    log.debug("Cleanup for successful execution");
     if (isRetryConfigured()) {
       resourceStateManager.getOrCreate(executionScope.getResourceID()).setRetry(null);
     }
@@ -444,7 +432,7 @@ private ResourceState getOrInitRetryExecution(ExecutionScope<P> executionScope)
   }
 
   private void cleanupForDeletedEvent(ResourceID resourceID) {
-    log.debug("Cleaning up for delete event for: {}", resourceID);
+    log.debug("Cleaning up for delete event");
     resourceStateManager.remove(resourceID);
     metrics.cleanupDoneFor(resourceID, metricsMetadata);
   }
@@ -509,6 +497,7 @@ public void run() {
         log.debug("Event processor not running skipping resource processing: {}", resourceID);
         return;
       }
+      MDCUtils.addResourceIDInfo(resourceID);
       log.debug("Running reconcile executor for: {}", executionScope);
       // change thread name for easier debugging
       final var thread = Thread.currentThread();
@@ -518,9 +507,7 @@ public void run() {
         var actualResource = cache.get(resourceID);
         if (actualResource.isEmpty()) {
           if (triggerOnAllEvents()) {
-            log.debug(
-                "Resource not found in the cache, checking for delete event resource: {}",
-                resourceID);
+            log.debug("Resource not found in the cache, checking for delete event resource");
             if (executionScope.isDeleteEvent()) {
               var state = resourceStateManager.get(resourceID);
               actualResource =
@@ -538,7 +525,7 @@ public void run() {
               return;
             }
           } else {
-            log.debug("Skipping execution; primary resource missing from cache: {}", resourceID);
+            log.debug("Skipping execution; primary resource missing from cache");
             return;
           }
         }

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

@@ -83,19 +83,13 @@ PostExecutionControl<P> handleDispatch(ExecutionScope<P> executionScope, Context
       throws Exception {
     P originalResource = executionScope.getResource();
     var resourceForExecution = cloneResource(originalResource);
-    log.debug(
-        "Handling dispatch for resource name: {} namespace: {}",
-        getName(originalResource),
-        originalResource.getMetadata().getNamespace());
+    log.debug("Handling dispatch");
 
     final var markedForDeletion = originalResource.isMarkedForDeletion();
     if (!triggerOnAllEvents()
         && markedForDeletion
         && shouldNotDispatchToCleanupWhenMarkedForDeletion(originalResource)) {
-      log.debug(
-          "Skipping cleanup of resource {} because finalizer(s) {} don't allow processing yet",
-          getName(originalResource),
-          originalResource.getMetadata().getFinalizers());
+      log.debug("Skipping cleanup because finalizer(s) don't allow processing yet");
       return PostExecutionControl.defaultDispatch();
     }
     // context can be provided only for testing purposes
@@ -165,11 +159,7 @@ private PostExecutionControl<P> reconcileExecution(
       P originalResource,
       Context<P> context)
       throws Exception {
-    log.debug(
-        "Reconciling resource {} with version: {} with execution scope: {}",
-        getName(resourceForExecution),
-        getVersion(resourceForExecution),
-        executionScope);
+    log.debug("Reconciling resource execution scope: {}", executionScope);
 
     UpdateControl<P> updateControl = controller.reconcile(resourceForExecution, context);
 
@@ -246,9 +236,8 @@ public boolean isLastAttempt() {
             exceptionLevel = Level.DEBUG;
             failedMessage = " due to conflict";
             log.info(
-                "ErrorStatusUpdateControl.patchStatus of {} failed due to a conflict, but the next"
-                    + " reconciliation is imminent.",
-                ResourceID.fromResource(originalResource));
+                "ErrorStatusUpdateControl.patchStatus failed due to a conflict, but the next"
+                    + " reconciliation is imminent");
           } else {
             exceptionLevel = Level.WARN;
             failedMessage = ", but will be retried soon,";
@@ -312,10 +301,7 @@ private void updatePostExecutionControlWithReschedule(
   private PostExecutionControl<P> handleCleanup(
       P resourceForExecution, Context<P> context, ExecutionScope<P> executionScope) {
     if (log.isDebugEnabled()) {
-      log.debug(
-          "Executing delete for resource: {} with version: {}",
-          ResourceID.fromResource(resourceForExecution),
-          getVersion(resourceForExecution));
+      log.debug("Executing delete for resource");
     }
     DeleteControl deleteControl = controller.cleanup(resourceForExecution, context);
     final var useFinalizer = controller.useFinalizer();
@@ -329,10 +315,7 @@ private PostExecutionControl<P> handleCleanup(
       }
     }
     log.debug(
-        "Skipping finalizer remove for resource: {} with version: {}. delete control: {}, uses"
-            + " finalizer: {}",
-        getUID(resourceForExecution),
-        getVersion(resourceForExecution),
+        "Skipping finalizer remove for resource. Delete control: {}, uses finalizer: {}",
         deleteControl,
         useFinalizer);
     PostExecutionControl<P> postExecutionControl = PostExecutionControl.defaultDispatch();
@@ -342,11 +325,7 @@ private PostExecutionControl<P> handleCleanup(
 
   private P patchResource(Context<P> context, P resource, P originalResource) {
     if (log.isDebugEnabled()) {
-      log.debug(
-          "Updating resource: {} with version: {}; SSA: {}",
-          resource.getMetadata().getName(),
-          getVersion(resource),
-          useSSA);
+      log.debug("Updating resource; with SSA: {}", useSSA);
     }
     log.trace("Resource before update: {}", resource);
 
@@ -384,10 +363,7 @@ public CustomResourceFacade(ControllerConfiguration<R> configuration, Cloner clo
 
     public R patchResource(Context<R> context, R resource, R originalResource) {
       if (log.isDebugEnabled()) {
-        log.debug(
-            "Trying to replace resource {}, version: {}",
-            ResourceID.fromResource(resource),
-            resource.getMetadata().getResourceVersion());
+        log.debug("Trying to replace resource");
       }
       if (useSSA) {
         return context.resourceOperations().serverSideApplyPrimary(resource);