Add NS and domainUID to log messages in more code paths (#2330)

* add NS and domainUID to log messages in more code paths

* remove unnecessary defensive code

Author: doxiao

operator/src/main/java/oracle/kubernetes/operator/DomainRecheck.java

@@ -36,6 +36,7 @@
 
 import static oracle.kubernetes.operator.helpers.EventHelper.EventItem.NAMESPACE_WATCHING_STARTED;
 import static oracle.kubernetes.operator.helpers.NamespaceHelper.getOperatorNamespace;
+import static oracle.kubernetes.operator.logging.LoggingContext.setThreadContext;
 
 class DomainRecheck {
   private static final LoggingFacade LOGGER = LoggingFactory.getLogger("Operator", "Operator");
@@ -93,9 +94,12 @@ public NextAction apply(Packet packet) {
 
       // we don't have the domain presence information yet
       // we add a logging context to pass the namespace information to the LoggingFormatter
-      packet.getComponents().put(
-          LoggingContext.LOGGING_CONTEXT_KEY,
-          Component.createFor(new LoggingContext().namespace(ns)));
+
+      if (isDomainNamespace) {
+        packet.getComponents().put(
+            LoggingContext.LOGGING_CONTEXT_KEY,
+            Component.createFor(new LoggingContext().namespace(ns)));
+      }
 
       V1SubjectRulesReviewStatus status = nss.getRulesReviewStatus().updateAndGet(prev -> {
         if (prev != null) {
@@ -211,10 +215,13 @@ private Step createNamespaceReviewStep(Set<String> namespacesToStartNow) {
   }
 
   private Step startNamespaceSteps(String ns) {
-    return Step.chain(
+    try (LoggingContext ignored =
+             setThreadContext().namespace(ns)) {
+      return Step.chain(
           createNamespaceReview(ns),
           new StartNamespaceBeforeStep(ns),
           domainNamespaces.readExistingResources(ns, domainProcessor));
+    }
   }
 
   // for testing

operator/src/main/java/oracle/kubernetes/operator/Main.java

@@ -547,7 +547,7 @@ void dispatchNamespaceWatch(Watch.Response<V1Namespace> item) {
     }
   }
 
-  private static Packet createPacketWithLoggingContext(String ns) {
+  static Packet createPacketWithLoggingContext(String ns) {
     Packet packet = new Packet();
     packet.getComponents().put(
         LoggingContext.LOGGING_CONTEXT_KEY,

operator/src/main/java/oracle/kubernetes/operator/StuckPodProcessing.java

@@ -17,6 +17,7 @@
 import oracle.kubernetes.operator.calls.CallResponse;
 import oracle.kubernetes.operator.helpers.CallBuilder;
 import oracle.kubernetes.operator.helpers.PodHelper;
+import oracle.kubernetes.operator.logging.LoggingContext;
 import oracle.kubernetes.operator.logging.LoggingFacade;
 import oracle.kubernetes.operator.logging.LoggingFactory;
 import oracle.kubernetes.operator.steps.DefaultResponseStep;
@@ -25,6 +26,7 @@
 import oracle.kubernetes.operator.work.Step;
 import oracle.kubernetes.utils.SystemClock;
 
+import static oracle.kubernetes.operator.logging.LoggingContext.setThreadContext;
 import static oracle.kubernetes.operator.logging.MessageKeys.POD_FORCE_DELETED;
 
 /**
@@ -44,7 +46,7 @@ void checkStuckPods(String namespace) {
     Step step = new CallBuilder()
           .withLabelSelectors(LabelConstants.getCreatedByOperatorSelector())
           .listPodAsync(namespace, new PodListProcessing(namespace, SystemClock.now()));
-    mainDelegate.runSteps(step);
+    mainDelegate.runSteps(Main.createPacketWithLoggingContext(namespace), step, null);
   }
 
   @SuppressWarnings("unchecked")
@@ -124,7 +126,7 @@ private Step createForcedDeletePodStep(V1Pod pod) {
       return new CallBuilder()
             .withGracePeriodSeconds(0)
             .deletePodAsync(getName(pod), getNamespace(pod), getDomainUid(pod), null,
-                  new ForcedDeleteResponseStep(getName(pod), getNamespace(pod)));
+                  new ForcedDeleteResponseStep(getName(pod), getNamespace(pod), getDomainUid(pod)));
     }
 
     private String getName(V1Pod pod) {
@@ -144,15 +146,20 @@ static class ForcedDeleteResponseStep extends DefaultResponseStep<Object> {
 
     private final String name;
     private final String namespace;
+    private final String domainUID;
 
-    public ForcedDeleteResponseStep(String name, String namespace) {
+    public ForcedDeleteResponseStep(String name, String namespace, String domainUID) {
       this.name = name;
       this.namespace = namespace;
+      this.domainUID = domainUID;
     }
 
     @Override
     public NextAction onSuccess(Packet packet, CallResponse<Object> callResponse) {
-      LOGGER.info(POD_FORCE_DELETED, name, namespace);
+      try (LoggingContext ignored =
+               setThreadContext().namespace(namespace).domainUid(domainUID)) {
+        LOGGER.info(POD_FORCE_DELETED, name, namespace);
+      }
       return super.onSuccess(packet, callResponse);
     }
   }

operator/src/main/java/oracle/kubernetes/operator/calls/AsyncRequestStep.java

@@ -32,6 +32,7 @@
 
 import static oracle.kubernetes.operator.calls.CallResponse.createFailure;
 import static oracle.kubernetes.operator.calls.CallResponse.createSuccess;
+import static oracle.kubernetes.operator.helpers.NamespaceHelper.getOperatorNamespace;
 import static oracle.kubernetes.operator.logging.MessageKeys.ASYNC_SUCCESS;
 
 /**
@@ -212,7 +213,7 @@ void onFailure(AsyncFiber fiber, ApiException ae, int statusCode, Map<String, Li
 
     // If this is the first event after the fiber resumes, it indicates that we did not receive
     // a callback within the timeout. So cancel the call and prepare to try again.
-    private void handleTimeout(RequestParams requestParams, AsyncFiber fiber, CancellableCall cc) {
+    private void handleTimeout(AsyncFiber fiber, CancellableCall cc) {
       if (firstTimeResumed()) {
         try {
           cc.cancel();
@@ -249,7 +250,8 @@ public NextAction apply(Packet packet) {
     // add a logging context to pass the namespace information to the LoggingFormatter
     if (requestParams.namespace != null 
         && packet.getSpi(DomainPresenceInfo.class) == null
-        && packet.getSpi(LoggingContext.class) == null) {
+        && packet.getSpi(LoggingContext.class) == null
+        && !requestParams.namespace.equals(getOperatorNamespace())) {
       packet.getComponents().put(
           LoggingContext.LOGGING_CONTEXT_KEY,
           Component.createFor(new LoggingContext()
@@ -284,7 +286,7 @@ public NextAction apply(Packet packet) {
         (fiber) -> {
           try {
             CancellableCall cc = processing.createCall(fiber);
-            scheduleTimeoutCheck(fiber, timeoutSeconds, () -> processing.handleTimeout(requestParams, fiber, cc));
+            scheduleTimeoutCheck(fiber, timeoutSeconds, () -> processing.handleTimeout(fiber, cc));
           } catch (ApiException t) {
             logAsyncFailure(t, t.getResponseBody());
             processing.resumeAfterThrowable(fiber);
@@ -336,7 +338,7 @@ private void logAsyncFailure(Throwable t, String responseBody) {
   private void logTimeout() {
     // called from a code path where we don't have the necessary information for logging context
     // so we need to use the thread context to pass in the logging context
-    try (LoggingContext stack =
+    try (LoggingContext ignored =
              LoggingContext.setThreadContext()
                  .namespace(requestParams.namespace)
                  .domainUid(requestParams.domainUid)) {
@@ -358,7 +360,7 @@ private void logTimeout() {
   private void logSuccess(T result, int statusCode, Map<String, List<String>> responseHeaders) {
     // called from a code path where we don't have the necessary information for logging context
     // so we need to use the thread context to pass in the logging context
-    try (LoggingContext stack =
+    try (LoggingContext ignored =
              LoggingContext.setThreadContext()
                  .namespace(requestParams.namespace)
                  .domainUid(requestParams.domainUid)) {
@@ -375,7 +377,7 @@ private void logSuccess(T result, int statusCode, Map<String, List<String>> resp
   private void logFailure(ApiException ae, int statusCode, Map<String, List<String>> responseHeaders) {
     // called from a code path where we don't have the necessary information for logging context
     // so we need to use the thread context to pass in the logging context
-    try (LoggingContext stack =
+    try (LoggingContext ignored =
              LoggingContext.setThreadContext()
                  .namespace(requestParams.namespace)
                  .domainUid(requestParams.domainUid)) {

operator/src/main/java/oracle/kubernetes/operator/http/HttpAsyncRequestStep.java

@@ -8,9 +8,12 @@
 import java.net.http.HttpClient;
 import java.net.http.HttpRequest;
 import java.net.http.HttpResponse;
+import java.util.Optional;
 import java.util.concurrent.CompletableFuture;
 import java.util.concurrent.TimeUnit;
 
+import oracle.kubernetes.operator.helpers.DomainPresenceInfo;
+import oracle.kubernetes.operator.logging.LoggingContext;
 import oracle.kubernetes.operator.logging.LoggingFacade;
 import oracle.kubernetes.operator.logging.LoggingFactory;
 import oracle.kubernetes.operator.logging.MessageKeys;
@@ -20,6 +23,7 @@
 import oracle.kubernetes.operator.work.Step;
 
 import static oracle.kubernetes.operator.http.TrustAllX509ExtendedTrustManager.getTrustingSSLContext;
+import static oracle.kubernetes.operator.logging.LoggingContext.setThreadContext;
 
 /**
  * An asynchronous step to handle http requests.
@@ -110,12 +114,16 @@ private void checkTimeout(AsyncFiber fiber) {
     }
 
     private void resume(AsyncFiber fiber, HttpResponse<String> response, Throwable throwable) {
-      if (throwable instanceof HttpTimeoutException) {
-        LOGGER.fine(MessageKeys.HTTP_REQUEST_TIMED_OUT, throwable.getMessage());
-      } else if (response != null) {
-        recordResponse(response);
-      } else if (throwable != null) {
-        recordThrowableResponse(throwable);
+      DomainPresenceInfo info = packet.getSpi(DomainPresenceInfo.class);
+      try (LoggingContext ignored =
+               setThreadContext().namespace(getNamespaceFromInfo(info)).domainUid(getDomainUIDFromInfo(info))) {
+        if (throwable instanceof HttpTimeoutException) {
+          LOGGER.fine(MessageKeys.HTTP_REQUEST_TIMED_OUT, throwable.getMessage());
+        } else if (response != null) {
+          recordResponse(response);
+        } else if (throwable != null) {
+          recordThrowableResponse(throwable);
+        }
       }
 
       fiber.resume(packet);
@@ -134,6 +142,14 @@ private void recordThrowableResponse(Throwable throwable) {
     }
   }
 
+  private String getDomainUIDFromInfo(DomainPresenceInfo info) {
+    return Optional.ofNullable(info).map(DomainPresenceInfo::getDomainUid).orElse(null);
+  }
+
+  private String getNamespaceFromInfo(DomainPresenceInfo info) {
+    return Optional.ofNullable(info).map(DomainPresenceInfo::getNamespace).orElse(null);
+  }
+
   private static CompletableFuture<HttpResponse<String>> createFuture(HttpRequest request) {
     return httpClient.sendAsync(request, HttpResponse.BodyHandlers.ofString());
   }

operator/src/test/java/oracle/kubernetes/operator/StuckPodTest.java

@@ -18,6 +18,7 @@
 import oracle.kubernetes.operator.helpers.DomainPresenceInfo;
 import oracle.kubernetes.operator.helpers.KubernetesTestSupport;
 import oracle.kubernetes.operator.helpers.TuningParametersStub;
+import oracle.kubernetes.operator.work.Packet;
 import oracle.kubernetes.operator.work.Step;
 import oracle.kubernetes.utils.SystemClock;
 import oracle.kubernetes.utils.SystemClockTestSupport;
@@ -202,6 +203,11 @@ public void runSteps(Step firstStep) {
       testSupport.runSteps(firstStep);
     }
 
+    @Override
+    public void runSteps(Packet packet, Step firstStep,  Runnable completionAction) {
+      testSupport.runSteps(packet, firstStep);
+    }
+
     @Override
     public DomainProcessor getDomainProcessor() {
       return domainProcessor;

operator/src/test/java/oracle/kubernetes/operator/work/FiberTestSupport.java

@@ -196,6 +196,19 @@ public Packet runSteps(Step step) {
     return packet;
   }
 
+  /**
+   * Starts a unit-test fiber with the specified packet and step.
+   *
+   * @param packet the packet to use
+   * @param step the first step to run
+   */
+  public Packet runSteps(Packet packet, Step step) {
+    fiber = engine.createFiber();
+    fiber.start(step, packet, completionCallback);
+
+    return packet;
+  }
+
   /**
    * Starts a unit-test fiber with the specified step.
    *