fix(tracing): Ensure clean MDC context at top coroutine scopes (#1845)

* fix(tracing): Ensure clean MDC context at top coroutine scopes * fix(pr): Rename clearMDC to blankMDC per review * chore(logs): Improve log message for stale promotion checks Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>
spinnaker · Mar 4, 2021 · 935da9b · 935da9b
1 parent a2db125
commit 935da9b
Show file tree

Hide file tree

Showing 5 changed files with 16 additions and 12 deletions.
diff --git a/keel-core/src/main/kotlin/com/netflix/spinnaker/keel/actuation/CheckScheduler.kt b/keel-core/src/main/kotlin/com/netflix/spinnaker/keel/actuation/CheckScheduler.kt
@@ -2,6 +2,7 @@ package com.netflix.spinnaker.keel.actuation
 
 import com.netflix.spinnaker.keel.activation.ApplicationDown
 import com.netflix.spinnaker.keel.activation.ApplicationUp
+import com.netflix.spinnaker.keel.logging.TracingSupport.Companion.blankMDC
 import com.netflix.spinnaker.keel.persistence.AgentLockRepository
 import com.netflix.spinnaker.keel.persistence.KeelRepository
 import com.netflix.spinnaker.keel.telemetry.AgentInvocationComplete
@@ -75,7 +76,7 @@ class CheckScheduler(
   fun checkResources() {
     if (enabled.get()) {
       val startTime = clock.instant()
-      val job = launch {
+      val job = launch(blankMDC) {
         supervisorScope {
           runCatching {
             repository
@@ -114,7 +115,7 @@ class CheckScheduler(
     if (enabled.get()) {
       publisher.publishEvent(ScheduledEnvironmentCheckStarting)
 
-      val job = launch {
+      val job = launch(blankMDC) {
         supervisorScope {
           repository
             .deliveryConfigsDueForCheck(checkMinAge, resourceCheckBatchSize)
@@ -149,7 +150,7 @@ class CheckScheduler(
     if (enabled.get()) {
       val startTime = clock.instant()
       publisher.publishEvent(ScheduledArtifactCheckStarting)
-      val job = launch {
+      val job = launch(blankMDC) {
         supervisorScope {
           repository.artifactsDueForCheck(checkMinAge, resourceCheckBatchSize)
             .forEach { artifact ->
@@ -179,7 +180,7 @@ class CheckScheduler(
       val startTime = clock.instant()
       publisher.publishEvent(ScheduledEnvironmentVerificationStarting)
 
-      val job = launch {
+      val job = launch(blankMDC) {
         supervisorScope {
           repository
             .nextEnvironmentsForVerification(environmentVerificationMinAge, environmentVerificationBatchSize)
@@ -213,7 +214,7 @@ class CheckScheduler(
         val agentName: String = it.javaClass.simpleName
         val lockAcquired = agentLockRepository.tryAcquireLock(agentName, it.lockTimeoutSeconds)
         if (lockAcquired) {
-          runBlocking {
+          runBlocking(blankMDC) {
             it.invokeAgent()
           }
           publisher.publishEvent(AgentInvocationComplete(Duration.between(startTime, clock.instant()), agentName))

diff --git a/keel-core/src/main/kotlin/com/netflix/spinnaker/keel/actuation/ResourceActuator.kt b/keel-core/src/main/kotlin/com/netflix/spinnaker/keel/actuation/ResourceActuator.kt
@@ -110,7 +110,7 @@ class ResourceActuator(
         }
 
         if (deliveryConfig.isPromotionCheckStale()) {
-          log.debug("Environments check for {} is stale, skipping checks", deliveryConfig.name)
+          log.debug("Artifact promotion check for application {} is stale, skipping resource checks", deliveryConfig.application)
           publisher.publishEvent(ResourceCheckSkipped(resource.kind, id, "PromotionCheckStale"))
           return@withTracingContext
         }

diff --git a/keel-core/src/main/kotlin/com/netflix/spinnaker/keel/logging/TracingSupport.kt b/keel-core/src/main/kotlin/com/netflix/spinnaker/keel/logging/TracingSupport.kt
@@ -15,6 +15,8 @@ class TracingSupport {
   companion object {
     const val X_SPINNAKER_RESOURCE_ID = "X-SPINNAKER-RESOURCE-ID"
 
+    val blankMDC: MDCContext = MDCContext(emptyMap())
+
     suspend fun <T : ResourceSpec, R> withTracingContext(
       resource: Resource<T>,
       block: suspend CoroutineScope.() -> R

diff --git a/keel-core/src/main/kotlin/com/netflix/spinnaker/keel/verification/VerificationRunner.kt b/keel-core/src/main/kotlin/com/netflix/spinnaker/keel/verification/VerificationRunner.kt
@@ -59,13 +59,13 @@ class VerificationRunner(
         }
 
       if (statuses.anyStillRunning) {
-        log.debug("Verification already running for {}", environment.name)
+        log.debug("Verification already running for environment {} of application {}", environment.name, deliveryConfig.application)
         return
       }
 
       statuses.firstOutstanding?.let { verification ->
         start(verification, imageFinder.getImages(context.deliveryConfig, context.environmentName))
-      } ?: log.debug("Verification complete for {}", environment.name)
+      } ?: log.debug("Verification complete for environment {} of application {}", environment.name, deliveryConfig.application)
     }
   }
 
@@ -81,7 +81,8 @@ class VerificationRunner(
       evaluators.evaluate(this, verification, state.metadata)
         .also { newStatus ->
           if (newStatus.complete) {
-            log.debug("Verification {} completed with status {} for {}", verification, newStatus, environment.name)
+            log.debug("Verification {} completed with status {} for environment {} of application {}",
+              verification, newStatus, environment.name, deliveryConfig.application)
             markAs(verification, newStatus)
             eventPublisher.publishEvent(VerificationCompleted(this, verification, newStatus, state.metadata))
           }

diff --git a/keel-web/src/main/kotlin/com/netflix/spinnaker/keel/rest/ExportController.kt b/keel-web/src/main/kotlin/com/netflix/spinnaker/keel/rest/ExportController.kt
@@ -2,13 +2,13 @@ package com.netflix.spinnaker.keel.rest
 
 import com.netflix.spinnaker.keel.api.Exportable
 import com.netflix.spinnaker.keel.api.ResourceKind
-import com.netflix.spinnaker.keel.api.ResourceKind.Companion.parseKind
 import com.netflix.spinnaker.keel.api.artifacts.DeliveryArtifact
 import com.netflix.spinnaker.keel.api.plugins.ResourceHandler
 import com.netflix.spinnaker.keel.api.plugins.supporting
 import com.netflix.spinnaker.keel.clouddriver.CloudDriverCache
 import com.netflix.spinnaker.keel.core.api.SubmittedResource
 import com.netflix.spinnaker.keel.core.parseMoniker
+import com.netflix.spinnaker.keel.logging.TracingSupport.Companion.blankMDC
 import com.netflix.spinnaker.keel.logging.TracingSupport.Companion.withTracingContext
 import com.netflix.spinnaker.keel.yaml.APPLICATION_YAML_VALUE
 import kotlinx.coroutines.runBlocking
@@ -74,7 +74,7 @@ class ExportController(
     val handler = handlers.supporting(kind)
     val exportable = generateExportable(cloudProvider, type, account, user, name)
 
-    return runBlocking {
+    return runBlocking(blankMDC) {
       withTracingContext(exportable) {
         log.info("Exporting resource ${exportable.toResourceId()}")
         SubmittedResource(
@@ -99,7 +99,7 @@ class ExportController(
     val handler = handlers.supporting(kind)
     val exportable = generateExportable(cloudProvider, "cluster", account, user, name)
 
-    return runBlocking {
+    return runBlocking(blankMDC) {
       withTracingContext(exportable) {
         log.info("Exporting artifact from cluster ${exportable.toResourceId()}")
         handler.exportArtifact(exportable)