diff --git a/docs/content/en/docs/documentation/observability.md b/docs/content/en/docs/documentation/observability.md index 312c31967e..acadaea182 100644 --- a/docs/content/en/docs/documentation/observability.md +++ b/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 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 index 01a8b62e9d..68043be070 100644 --- 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 @@ -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()); diff --git a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/EventProcessor.java b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/EventProcessor.java index b476c39614..6c9aee67c1 100644 --- a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/EventProcessor.java +++ b/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

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,10 +215,9 @@ 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()); @@ -229,8 +225,7 @@ private void handleEventMarking(Event event, ResourceState state) { 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,7 +365,7 @@ private void handleRetryOnException(ExecutionScope

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; } @@ -383,8 +373,7 @@ private void handleRetryOnException(ExecutionScope

executionScope, Exception 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

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

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; } } diff --git a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/ReconciliationDispatcher.java b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/ReconciliationDispatcher.java index 010b161979..6e7ace0447 100644 --- a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/ReconciliationDispatcher.java +++ b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/ReconciliationDispatcher.java @@ -83,19 +83,13 @@ PostExecutionControl

handleDispatch(ExecutionScope

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

reconcileExecution( P originalResource, Context

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

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

handleCleanup( P resourceForExecution, Context

context, ExecutionScope

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

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

postExecutionControl = PostExecutionControl.defaultDispatch(); @@ -342,11 +325,7 @@ private PostExecutionControl

handleCleanup( private P patchResource(Context

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 configuration, Cloner clo public R patchResource(Context 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); diff --git a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/controller/ControllerEventSource.java b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/controller/ControllerEventSource.java index 8412e1ccbe..e0682d5808 100644 --- a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/controller/ControllerEventSource.java +++ b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/controller/ControllerEventSource.java @@ -35,7 +35,6 @@ import io.javaoperatorsdk.operator.processing.event.source.informer.TemporaryResourceCache.EventHandling; import static io.javaoperatorsdk.operator.ReconcilerUtilsInternal.handleKubernetesClientException; -import static io.javaoperatorsdk.operator.processing.KubernetesResourceUtils.getVersion; import static io.javaoperatorsdk.operator.processing.event.source.controller.InternalEventFilters.*; public class ControllerEventSource @@ -88,12 +87,7 @@ protected synchronized void handleEvent( ResourceAction action, T resource, T oldResource, Boolean deletedFinalStateUnknown) { try { if (log.isDebugEnabled()) { - log.debug( - "Event received for resource: {} version: {} uuid: {} action: {}", - ResourceID.fromResource(resource), - getVersion(resource), - resource.getMetadata().getUid(), - action); + log.debug("Event received with action: {}", action); log.trace("Event Old resource: {},\n new resource: {}", oldResource, resource); } MDCUtils.addResourceInfo(resource); @@ -112,7 +106,7 @@ protected synchronized void handleEvent( .handleEvent(new ResourceEvent(action, ResourceID.fromResource(resource), resource)); } } else { - log.debug("Skipping event handling resource {}", ResourceID.fromResource(resource)); + log.debug("Skipping event handling for resource"); } } finally { MDCUtils.removeResourceInfo(); @@ -124,23 +118,27 @@ private boolean isAcceptedByFilters(ResourceAction action, T resource, T oldReso if (genericFilter != null && !genericFilter.accept(resource)) { return false; } - switch (action) { - case ADDED: - return onAddFilter == null || onAddFilter.accept(resource); - case UPDATED: - return onUpdateFilter.accept(resource, oldResource); - } - return true; + return switch (action) { + case ADDED -> onAddFilter == null || onAddFilter.accept(resource); + case UPDATED -> onUpdateFilter.accept(resource, oldResource); + default -> true; + }; } @Override public synchronized void onAdd(T resource) { - handleOnAddOrUpdate(ResourceAction.ADDED, null, resource); + withMDC( + resource, + ResourceAction.ADDED, + () -> handleOnAddOrUpdate(ResourceAction.ADDED, null, resource)); } @Override public synchronized void onUpdate(T oldCustomResource, T newCustomResource) { - handleOnAddOrUpdate(ResourceAction.UPDATED, oldCustomResource, newCustomResource); + withMDC( + newCustomResource, + ResourceAction.UPDATED, + () -> handleOnAddOrUpdate(ResourceAction.UPDATED, oldCustomResource, newCustomResource)); } private void handleOnAddOrUpdate( @@ -150,20 +148,21 @@ private void handleOnAddOrUpdate( if (handling == EventHandling.NEW) { handleEvent(action, newCustomResource, oldCustomResource, null); } else if (log.isDebugEnabled()) { - log.debug( - "{} event propagation for action: {} resource id: {} ", - handling, - action, - ResourceID.fromResource(newCustomResource)); + log.debug("{} event propagation for action: {}", handling, action); } } @Override public synchronized void onDelete(T resource, boolean deletedFinalStateUnknown) { - temporaryResourceCache.onDeleteEvent(resource, deletedFinalStateUnknown); - // delete event is quite special here, that requires special care, since we clean up caches on - // delete event. - handleEvent(ResourceAction.DELETED, resource, null, deletedFinalStateUnknown); + withMDC( + resource, + ResourceAction.DELETED, + () -> { + temporaryResourceCache.onDeleteEvent(resource, deletedFinalStateUnknown); + // delete event is quite special here, that requires special care, since we clean up + // caches on delete event. + handleEvent(ResourceAction.DELETED, resource, null, deletedFinalStateUnknown); + }); } @Override diff --git a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/ExtendedResourceEvent.java b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/ExtendedResourceEvent.java index 4ae476a3de..5d30d1b0e1 100644 --- a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/ExtendedResourceEvent.java +++ b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/ExtendedResourceEvent.java @@ -15,6 +15,7 @@ */ package io.javaoperatorsdk.operator.processing.event.source.informer; +import java.util.Objects; import java.util.Optional; import io.fabric8.kubernetes.api.model.HasMetadata; @@ -25,7 +26,7 @@ /** Used only for resource event filtering. */ public class ExtendedResourceEvent extends ResourceEvent { - private HasMetadata previousResource; + private final HasMetadata previousResource; public ExtendedResourceEvent( ResourceAction action, @@ -39,4 +40,33 @@ public ExtendedResourceEvent( public Optional getPreviousResource() { return Optional.ofNullable(previousResource); } + + @Override + public String toString() { + return "ExtendedResourceEvent{" + + getPreviousResource() + .map(r -> "previousResourceVersion=" + r.getMetadata().getResourceVersion()) + .orElse("") + + ", action=" + + getAction() + + getResource() + .map(r -> ", resourceVersion=" + r.getMetadata().getResourceVersion()) + .orElse("") + + ", relatedCustomResourceName=" + + getRelatedCustomResourceID().getName() + + '}'; + } + + @Override + public boolean equals(Object o) { + if (o == null || getClass() != o.getClass()) return false; + if (!super.equals(o)) return false; + ExtendedResourceEvent that = (ExtendedResourceEvent) o; + return Objects.equals(previousResource, that.previousResource); + } + + @Override + public int hashCode() { + return Objects.hash(super.hashCode(), previousResource); + } } diff --git a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/InformerEventSource.java b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/InformerEventSource.java index b778747417..fcec8ae68b 100644 --- a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/InformerEventSource.java +++ b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/InformerEventSource.java @@ -100,42 +100,48 @@ private InformerEventSource( @Override public void onAdd(R newResource) { - if (log.isDebugEnabled()) { - log.debug( - "On add event received for resource id: {} type: {} version: {}", - ResourceID.fromResource(newResource), - resourceType().getSimpleName(), - newResource.getMetadata().getResourceVersion()); - } - onAddOrUpdate(ResourceAction.ADDED, newResource, null); + withMDC( + newResource, + ResourceAction.ADDED, + () -> { + if (log.isDebugEnabled()) { + log.debug("On add event received"); + } + onAddOrUpdate(ResourceAction.ADDED, newResource, null); + }); } @Override public void onUpdate(R oldObject, R newObject) { - if (log.isDebugEnabled()) { - log.debug( - "On update event received for resource id: {} type: {} version: {} old version: {} ", - ResourceID.fromResource(newObject), - resourceType().getSimpleName(), - newObject.getMetadata().getResourceVersion(), - oldObject.getMetadata().getResourceVersion()); - } - onAddOrUpdate(ResourceAction.UPDATED, newObject, oldObject); + withMDC( + newObject, + ResourceAction.UPDATED, + () -> { + if (log.isDebugEnabled()) { + log.debug( + "On update event received. Old version: {}", + oldObject.getMetadata().getResourceVersion()); + } + onAddOrUpdate(ResourceAction.UPDATED, newObject, oldObject); + }); } @Override - public synchronized void onDelete(R resource, boolean b) { - if (log.isDebugEnabled()) { - log.debug( - "On delete event received for resource id: {} type: {}", - ResourceID.fromResource(resource), - resourceType().getSimpleName()); - } - primaryToSecondaryIndex.onDelete(resource); - temporaryResourceCache.onDeleteEvent(resource, b); - if (acceptedByDeleteFilters(resource, b)) { - propagateEvent(resource); - } + public synchronized void onDelete(R resource, boolean deletedFinalStateUnknown) { + withMDC( + resource, + ResourceAction.DELETED, + () -> { + if (log.isDebugEnabled()) { + log.debug( + "On delete event received. deletedFinalStateUnknown: {}", deletedFinalStateUnknown); + } + primaryToSecondaryIndex.onDelete(resource); + temporaryResourceCache.onDeleteEvent(resource, deletedFinalStateUnknown); + if (acceptedByDeleteFilters(resource, deletedFinalStateUnknown)) { + propagateEvent(resource); + } + }); } @Override @@ -160,16 +166,11 @@ private synchronized void onAddOrUpdate(ResourceAction action, R newObject, R ol if (eventHandling != EventHandling.NEW) { log.debug( - "{} event propagation for {}. Resource ID: {}", - eventHandling == EventHandling.DEFER ? "Deferring" : "Skipping", - action, - ResourceID.fromResource(newObject)); + "{} event propagation", eventHandling == EventHandling.DEFER ? "Deferring" : "Skipping"); } else if (eventAcceptedByFilter(action, newObject, oldObject)) { log.debug( - "Propagating event for {}, resource with same version not result of a reconciliation." - + " Resource ID: {}", - action, - resourceID); + "Propagating event for {}, resource with same version not result of a reconciliation.", + action); propagateEvent(newObject); } else { log.debug("Event filtered out for operation: {}, resourceID: {}", action, resourceID); @@ -211,9 +212,8 @@ public Set getSecondaryResources(P primary) { } else { secondaryIDs = primaryToSecondaryMapper.toSecondaryResourceIDs(primary); log.debug( - "Using PrimaryToSecondaryMapper to find secondary resources for primary: {}. Found" + "Using PrimaryToSecondaryMapper to find secondary resources for primary. Found" + " secondary ids: {} ", - primary, secondaryIDs); } return secondaryIDs.stream() diff --git a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/ManagedInformerEventSource.java b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/ManagedInformerEventSource.java index 301ece4424..38c93d03ae 100644 --- a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/ManagedInformerEventSource.java +++ b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/ManagedInformerEventSource.java @@ -40,6 +40,7 @@ import io.javaoperatorsdk.operator.health.InformerHealthIndicator; import io.javaoperatorsdk.operator.health.InformerWrappingEventSourceHealthIndicator; import io.javaoperatorsdk.operator.health.Status; +import io.javaoperatorsdk.operator.processing.MDCUtils; import io.javaoperatorsdk.operator.processing.event.ResourceID; import io.javaoperatorsdk.operator.processing.event.source.*; import io.javaoperatorsdk.operator.processing.event.source.ResourceAction; @@ -93,11 +94,12 @@ public void changeNamespaces(Set namespaces) { @SuppressWarnings("unchecked") public R eventFilteringUpdateAndCacheResource(R resourceToUpdate, UnaryOperator updateMethod) { ResourceID id = ResourceID.fromResource(resourceToUpdate); - log.debug("Update and cache: {}", id); + log.debug("Starting event filtering and caching update"); R updatedResource = null; try { temporaryResourceCache.startEventFilteringModify(id); updatedResource = updateMethod.apply(resourceToUpdate); + log.debug("Resource update successful"); handleRecentResourceUpdate(id, updatedResource, resourceToUpdate); return updatedResource; } finally { @@ -113,17 +115,23 @@ public R eventFilteringUpdateAndCacheResource(R resourceToUpdate, UnaryOperator< // as previous resource version we use the one from successful update, since // we process new event here only if that is more recent then the event from our update. // Note that this is equivalent with the scenario when an informer watch connection - // would - // reconnect and loose some events in between. + // would reconnect and loose some events in between. // If that update was not successful we still record the previous version from the - // actual - // event in the ExtendedResourceEvent. + // actual event in the ExtendedResourceEvent. R extendedResourcePrevVersion = (r instanceof ExtendedResourceEvent) ? (R) ((ExtendedResourceEvent) r).getPreviousResource().orElse(null) : null; R prevVersionOfResource = updatedForLambda != null ? updatedForLambda : extendedResourcePrevVersion; + if (log.isDebugEnabled()) { + log.debug( + "Previous resource version: {} resource from update present: {}" + + " extendedPrevResource present: {}", + prevVersionOfResource.getMetadata().getResourceVersion(), + updatedForLambda != null, + extendedResourcePrevVersion != null); + } handleEvent( r.getAction(), latestResource, @@ -132,7 +140,7 @@ public R eventFilteringUpdateAndCacheResource(R resourceToUpdate, UnaryOperator< ? ((ResourceDeleteEvent) r).isDeletedFinalStateUnknown() : null); }, - () -> log.debug("No new event present after the filtering update; id: {}", id)); + () -> log.debug("No new event present after the filtering update")); } } @@ -257,4 +265,8 @@ public String toString() { public void setControllerConfiguration(ControllerConfiguration controllerConfiguration) { this.controllerConfiguration = controllerConfiguration; } + + protected void withMDC(R resource, ResourceAction action, Runnable runnable) { + MDCUtils.withMDCForEvent(resource, action, runnable, name()); + } } diff --git a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/TemporaryResourceCache.java b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/TemporaryResourceCache.java index 1dbbf36043..43d9dc1fab 100644 --- a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/TemporaryResourceCache.java +++ b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/source/informer/TemporaryResourceCache.java @@ -107,9 +107,6 @@ public void onDeleteEvent(T resource, boolean unknownState) { onEvent(ResourceAction.DELETED, resource, null, unknownState, true); } - /** - * @return true if the resourceVersion was obsolete - */ public EventHandling onAddOrUpdateEvent( ResourceAction action, T resource, T prevResourceVersion) { return onEvent(action, resource, prevResourceVersion, false, false); @@ -127,19 +124,21 @@ private synchronized EventHandling onEvent( var resourceId = ResourceID.fromResource(resource); if (log.isDebugEnabled()) { - log.debug( - "Processing event for resource id: {} version: {} ", - resourceId, - resource.getMetadata().getResourceVersion()); + log.debug("Processing event"); } if (!unknownState) { latestResourceVersion = resource.getMetadata().getResourceVersion(); + log.debug("Setting latest resource version to: {}", latestResourceVersion); } var cached = cache.get(resourceId); EventHandling result = EventHandling.NEW; if (cached != null) { int comp = ReconcilerUtilsInternal.compareResourceVersions(resource, cached); if (comp >= 0 || unknownState) { + log.debug( + "Removing resource from temp cache. comparison: {} unknown state: {}", + comp, + unknownState); cache.remove(resourceId); // we propagate event only for our update or newer other can be discarded since we know we // will receive @@ -151,6 +150,7 @@ private synchronized EventHandling onEvent( } var ed = activeUpdates.get(resourceId); if (ed != null && result != EventHandling.OBSOLETE) { + log.debug("Setting last event for id: {} delete: {}", resourceId, delete); ed.setLastEvent( delete ? new ResourceDeleteEvent(ResourceAction.DELETED, resourceId, resource, unknownState) diff --git a/operator-framework-core/src/test/resources/log4j2.xml b/operator-framework-core/src/test/resources/log4j2.xml index be03b531ac..6c2aa05616 100644 --- a/operator-framework-core/src/test/resources/log4j2.xml +++ b/operator-framework-core/src/test/resources/log4j2.xml @@ -19,7 +19,7 @@ - + diff --git a/operator-framework/src/test/resources/log4j2.xml b/operator-framework/src/test/resources/log4j2.xml index e922079cc8..3a6e259e31 100644 --- a/operator-framework/src/test/resources/log4j2.xml +++ b/operator-framework/src/test/resources/log4j2.xml @@ -19,7 +19,7 @@ - + diff --git a/sample-operators/controller-namespace-deletion/src/main/resources/log4j2.xml b/sample-operators/controller-namespace-deletion/src/main/resources/log4j2.xml index bb61366dcf..147f494c1d 100644 --- a/sample-operators/controller-namespace-deletion/src/main/resources/log4j2.xml +++ b/sample-operators/controller-namespace-deletion/src/main/resources/log4j2.xml @@ -19,7 +19,7 @@ - + diff --git a/sample-operators/leader-election/src/main/resources/log4j2.xml b/sample-operators/leader-election/src/main/resources/log4j2.xml index bb61366dcf..147f494c1d 100644 --- a/sample-operators/leader-election/src/main/resources/log4j2.xml +++ b/sample-operators/leader-election/src/main/resources/log4j2.xml @@ -19,7 +19,7 @@ - + diff --git a/sample-operators/mysql-schema/src/main/resources/log4j2.xml b/sample-operators/mysql-schema/src/main/resources/log4j2.xml index 054261c13f..2979258355 100644 --- a/sample-operators/mysql-schema/src/main/resources/log4j2.xml +++ b/sample-operators/mysql-schema/src/main/resources/log4j2.xml @@ -19,11 +19,11 @@ - + - + diff --git a/sample-operators/tomcat-operator/src/main/resources/log4j2.xml b/sample-operators/tomcat-operator/src/main/resources/log4j2.xml index 21b0ee5480..147f494c1d 100644 --- a/sample-operators/tomcat-operator/src/main/resources/log4j2.xml +++ b/sample-operators/tomcat-operator/src/main/resources/log4j2.xml @@ -19,11 +19,11 @@ - + - + diff --git a/sample-operators/webpage/src/main/resources/log4j2.xml b/sample-operators/webpage/src/main/resources/log4j2.xml index 0bf270c7e6..2979258355 100644 --- a/sample-operators/webpage/src/main/resources/log4j2.xml +++ b/sample-operators/webpage/src/main/resources/log4j2.xml @@ -19,7 +19,7 @@ - +