From 935da9bfb5a131a923791a1787732ed4e27b1fdb Mon Sep 17 00:00:00 2001 From: Luis Pollo <1323478+luispollo@users.noreply.github.com> Date: Thu, 4 Mar 2021 14:44:50 -0800 Subject: [PATCH] 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/keel/actuation/CheckScheduler.kt | 11 ++++++----- .../spinnaker/keel/actuation/ResourceActuator.kt | 2 +- .../netflix/spinnaker/keel/logging/TracingSupport.kt | 2 ++ .../spinnaker/keel/verification/VerificationRunner.kt | 7 ++++--- .../netflix/spinnaker/keel/rest/ExportController.kt | 6 +++--- 5 files changed, 16 insertions(+), 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 index 9f815e7b87..3eeead030d 100644 --- 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 index 00803ddd0a..730170a388 100644 --- 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 index 5375fe3cf6..c3a9563e17 100644 --- 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 withTracingContext( resource: Resource, 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 index 7ad70fac9b..65ce51eb31 100644 --- 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 index 56a0f9b855..9735567c2f 100644 --- 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)