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/Event.java b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/Event.java
index 036274c5d3..1f17aafe7c 100644
--- a/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/Event.java
+++ b/operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/Event.java
@@ -19,7 +19,7 @@
public class Event {
- private final ResourceID relatedCustomResource;
+ protected final ResourceID relatedCustomResource;
public Event(ResourceID targetCustomResource) {
this.relatedCustomResource = targetCustomResource;
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..4409c3886d 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(
@@ -221,7 +218,7 @@ 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 +226,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 +256,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 +329,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 +342,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 +366,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 +374,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 +415,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 +433,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 +498,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 +508,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 +526,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..ba46f5b3d0 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; 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..1b73349b61 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();
@@ -135,12 +129,18 @@ private boolean isAcceptedByFilters(ResourceAction action, T resource, T oldReso
@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 +150,22 @@ 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..ce79c19187 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,29 @@ 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="
+ + relatedCustomResource.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..e2378b35a5 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,49 @@ 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 for resource. deletedFinalStateUnknown: {}",
+ deletedFinalStateUnknown);
+ }
+ primaryToSecondaryIndex.onDelete(resource);
+ temporaryResourceCache.onDeleteEvent(resource, deletedFinalStateUnknown);
+ if (acceptedByDeleteFilters(resource, deletedFinalStateUnknown)) {
+ propagateEvent(resource);
+ }
+ });
}
@Override
@@ -160,16 +167,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 +213,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..ccc4226a8b 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 filter and cache update");
R updatedResource = null;
try {
temporaryResourceCache.startEventFilteringModify(id);
updatedResource = updateMethod.apply(resourceToUpdate);
+ log.debug("Resource update successful");
handleRecentResourceUpdate(id, updatedResource, resourceToUpdate);
return updatedResource;
} finally {
@@ -124,6 +126,14 @@ public R eventFilteringUpdateAndCacheResource(R resourceToUpdate, UnaryOperator<
: null;
R prevVersionOfResource =
updatedForLambda != null ? updatedForLambda : extendedResourcePrevVersion;
+ if (log.isDebugEnabled()) {
+ log.debug(
+ "Extended previous resource version: {} resource from update present: {}"
+ + " extendedPrevResource present: {}",
+ prevVersionOfResource.getMetadata().getResourceVersion(),
+ updatedForLambda != null,
+ extendedResourcePrevVersion != null);
+ }
handleEvent(
r.getAction(),
latestResource,
@@ -132,7 +142,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 +267,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..201e061acf 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
@@ -127,12 +127,10 @@ 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 for resource");
}
if (!unknownState) {
+ log.debug("Setting latest resource version to: {}", latestResourceVersion);
latestResourceVersion = resource.getMetadata().getResourceVersion();
}
var cached = cache.get(resourceId);
@@ -140,6 +138,10 @@ private synchronized EventHandling onEvent(
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 +153,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 @@
-
+