chore(logging): propagate and log orca executionId (#371)

spinnaker · May 15, 2019 · f85fdf6 · f85fdf6
1 parent 6d78af6
commit f85fdf6
Show file tree

Hide file tree

Showing 10 changed files with 58 additions and 16 deletions.
diff --git a/rosco-core/src/main/groovy/com/netflix/spinnaker/rosco/api/BakeRequest.groovy b/rosco-core/src/main/groovy/com/netflix/spinnaker/rosco/api/BakeRequest.groovy
@@ -82,6 +82,8 @@ class BakeRequest {
   @ApiModelProperty("The name of a configured account to use when baking the image")
   String account_name
 
+  String spinnaker_execution_id
+
   static enum CloudProviderType {
     aws, azure, docker, gce, oracle
   }

diff --git a/rosco-core/src/main/groovy/com/netflix/spinnaker/rosco/executor/BakePoller.groovy b/rosco-core/src/main/groovy/com/netflix/spinnaker/rosco/executor/BakePoller.groovy
@@ -125,8 +125,10 @@ class BakePoller implements ApplicationListener<ContextRefreshedEvent> {
                             // This can only be true if the rosco instance that owns this bake has not been updating the status.
                             // Note that this only applies to bakes owned by _other_ rosco instances, not _this_ one.
                             if (eTimeMinutes >= orphanedJobTimeoutMinutes) {
+                              BakeRequest bakeRequest = bakeStore.retrieveBakeRequestById(statusId)
                               log.info("The staleness of bake $statusId ($eTimeMinutes minutes) has met or exceeded the " +
-                                       "value of orphanedJobTimeoutMinutes ($orphanedJobTimeoutMinutes minutes).")
+                                       "value of orphanedJobTimeoutMinutes ($orphanedJobTimeoutMinutes minutes)" +
+                                       "(executionId: $bakeRequest.spinnaker_execution_id).")
 
                               boolean cancellationSucceeded = bakeStore.cancelBakeById(statusId)
 

diff --git a/rosco-core/src/main/groovy/com/netflix/spinnaker/rosco/jobs/JobRequest.groovy b/rosco-core/src/main/groovy/com/netflix/spinnaker/rosco/jobs/JobRequest.groovy
@@ -28,6 +28,7 @@ class JobRequest {
   List<String> tokenizedCommand
   List<String> maskedParameters = []
   String jobId
+  String executionId
   /** Whether to merge command output and error streams. */
   boolean combineStdOutAndErr = true
 

diff --git a/rosco-core/src/main/groovy/com/netflix/spinnaker/rosco/jobs/local/JobExecutorLocal.groovy b/rosco-core/src/main/groovy/com/netflix/spinnaker/rosco/jobs/local/JobExecutorLocal.groovy
@@ -74,7 +74,8 @@ class JobExecutorLocal implements JobExecutor {
           CommandLine commandLine
 
           if (jobRequest.tokenizedCommand) {
-            log.info("Executing $jobId with tokenized command: $jobRequest.maskedTokenizedCommand")
+            log.info("Executing $jobId with tokenized command: $jobRequest.maskedTokenizedCommand " +
+              "(executionId: $jobRequest.executionId)")
 
             // Grab the first element as the command.
             commandLine = new CommandLine(jobRequest.tokenizedCommand[0])
@@ -84,7 +85,7 @@ class JobExecutorLocal implements JobExecutor {
 
             commandLine.addArguments(arguments, false)
           } else {
-            log.info("No tokenizedCommand specified for $jobId.")
+            log.info("No tokenizedCommand specified for $jobId. (executionId: $jobRequest.executionId)")
 
             throw new IllegalArgumentException("No tokenizedCommand specified for $jobId.")
           }
@@ -96,7 +97,7 @@ class JobExecutorLocal implements JobExecutor {
               // If a watchdog is passed in, this was an actual time-out. Otherwise, it is likely
               // the result of calling watchdog.destroyProcess().
               if (w) {
-                log.info("Job $jobId timed-out (after $timeoutMinutes minutes).")
+                log.info("Job $jobId timed-out (after $timeoutMinutes minutes, executionId: $jobRequest.executionId)")
 
                 cancelJob(jobId)
               }
@@ -116,7 +117,8 @@ class JobExecutorLocal implements JobExecutor {
             handler: resultHandler,
             watchdog: watchdog,
             stdOut: stdOut,
-            stdErr: stdErr
+            stdErr: stdErr,
+            executionId: jobRequest.executionId
           ])
         }
       }
@@ -132,8 +134,10 @@ class JobExecutorLocal implements JobExecutor {
 
   @Override
   BakeStatus updateJob(String jobId) {
+    String executionId = jobIdToHandlerMap.getOrDefault(jobId, [:]).get("executionId")
+
     try {
-      log.info("Polling state for $jobId...")
+      log.info("Polling state for $jobId (executionId: $executionId)...")
 
       if (jobIdToHandlerMap[jobId]) {
         BakeStatus bakeStatus = new BakeStatus(id: jobId, resource_id: jobId)
@@ -152,7 +156,7 @@ class JobExecutorLocal implements JobExecutor {
         String logsContent = (stdErr == null) ? outputContent : new String(stdErr.toByteArray())
 
         if (resultHandler.hasResult()) {
-          log.info("State for $jobId changed with exit code $resultHandler.exitValue.")
+          log.info("State for $jobId changed with exit code $resultHandler.exitValue (executionId: $executionId).")
 
           if (!logsContent) {
             logsContent = resultHandler.exception ? resultHandler.exception.message : "No output from command."
@@ -185,7 +189,7 @@ class JobExecutorLocal implements JobExecutor {
         return null
       }
     } catch (Exception e) {
-      log.error("Failed to update $jobId", e)
+      log.error("Failed to update $jobId (executionId: $executionId)", e)
 
       return null
     }
@@ -194,7 +198,9 @@ class JobExecutorLocal implements JobExecutor {
 
   @Override
   void cancelJob(String jobId) {
-    log.info("Canceling job $jobId...")
+    String executionId = jobIdToHandlerMap.getOrDefault(jobId, [:]).get("executionId")
+
+    log.info("Canceling job $jobId (executionId: $executionId)...")
 
     // Remove the job from this rosco instance's handler map.
     def canceledJob = jobIdToHandlerMap.remove(jobId)

diff --git a/...-core/src/main/groovy/com/netflix/spinnaker/rosco/persistence/RedisBackedBakeStore.groovy b/...-core/src/main/groovy/com/netflix/spinnaker/rosco/persistence/RedisBackedBakeStore.groovy
@@ -555,7 +555,7 @@ class RedisBackedBakeStore implements BakeStore {
   @CompileStatic
   private Set<String> scanIncompleteBakesKeys() {
     def incompleteBakesKeys = new HashSet()
-    redisClientDelegate.withKeyScan(allIncompleteBakesKeyPattern, 1000, { page ->
+    redisClientDelegate.withKeyScan(allIncompleteBakesKeyPattern, 100, { page ->
       incompleteBakesKeys.addAll(page.getResults())
     })
     return incompleteBakesKeys

diff --git a/...re/src/main/groovy/com/netflix/spinnaker/rosco/providers/util/PackageNameConverter.groovy b/...re/src/main/groovy/com/netflix/spinnaker/rosco/providers/util/PackageNameConverter.groovy
@@ -80,7 +80,8 @@ class PackageNameConverter {
     }
 
     if (!AppVersion.parseName(appVersion)) {
-      log.debug("AppVersion.parseName() was unable to parse appVersionStr =$appVersion.")
+      log.debug("AppVersion.parseName() was unable to parse appVersionStr =$appVersion " +
+        "(executionId: $bakeRequest.spinnaker_execution_id)")
       return null
     }
 

diff --git a/...o-core/src/test/groovy/com/netflix/spinnaker/rosco/jobs/local/JobExecutorLocalSpec.groovy b/...o-core/src/test/groovy/com/netflix/spinnaker/rosco/jobs/local/JobExecutorLocalSpec.groovy
@@ -65,7 +65,7 @@ class JobExecutorLocalSpec extends Specification implements TestDefaults {
     when:
       def jobId = jobExecutorLocal.startJob(jobRequest)
       // Give the script time to run + 100 ms fudge factor
-      sleep(1100)
+      sleep(3000)
       def bakeStatus = jobExecutorLocal.updateJob(jobId)
 
     then:

diff --git a/...sts/src/main/java/com/netflix/spinnaker/rosco/manifests/helm/HelmBakeManifestService.java b/...sts/src/main/java/com/netflix/spinnaker/rosco/manifests/helm/HelmBakeManifestService.java
@@ -8,6 +8,7 @@
 import com.netflix.spinnaker.rosco.manifests.BakeManifestRequest;
 import com.netflix.spinnaker.rosco.manifests.TemplateUtils;
 import com.netflix.spinnaker.rosco.manifests.TemplateUtils.BakeManifestEnvironment;
+import com.netflix.spinnaker.security.AuthenticatedRequest;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.stereotype.Component;
 
@@ -41,11 +42,16 @@ public Artifact bake(HelmBakeManifestRequest request) {
     HelmTemplateUtils utils = templateUtils(request);
     BakeManifestEnvironment env = new BakeManifestEnvironment();
     BakeRecipe recipe = utils.buildBakeRecipe(env, request);
-
     BakeStatus bakeStatus;
 
     try {
-      JobRequest jobRequest = new JobRequest(recipe.getCommand(), new ArrayList<>(), UUID.randomUUID().toString(), false);
+      JobRequest jobRequest = new JobRequest(
+        recipe.getCommand(),
+        new ArrayList<>(),
+        UUID.randomUUID().toString(),
+        AuthenticatedRequest.getSpinnakerExecutionId().orElse(null),
+        false
+      );
       String jobId = jobExecutor.startJob(jobRequest);
 
       bakeStatus = jobExecutor.updateJob(jobId);

diff --git a/rosco-web/src/main/groovy/com/netflix/spinnaker/rosco/WebConfig.groovy b/rosco-web/src/main/groovy/com/netflix/spinnaker/rosco/WebConfig.groovy
@@ -17,13 +17,19 @@
 package com.netflix.spinnaker.rosco
 
 import com.netflix.spectator.api.Registry
+import com.netflix.spinnaker.filters.AuthenticatedRequestFilter
 import com.netflix.spinnaker.kork.web.interceptors.MetricsInterceptor
+import groovy.transform.CompileStatic
 import org.springframework.beans.factory.annotation.Autowired
+import org.springframework.boot.web.servlet.FilterRegistrationBean
+import org.springframework.context.annotation.Bean
 import org.springframework.context.annotation.Configuration
+import org.springframework.core.Ordered
 import org.springframework.web.servlet.config.annotation.InterceptorRegistry
 import org.springframework.web.servlet.config.annotation.WebMvcConfigurerAdapter
 
 @Configuration
+@CompileStatic
 public class WebConfig extends WebMvcConfigurerAdapter {
 
   @Autowired
@@ -37,4 +43,12 @@ public class WebConfig extends WebMvcConfigurerAdapter {
       )
     )
   }
+
+  @Bean
+  FilterRegistrationBean authenticatedRequestFilter() {
+    def frb = new FilterRegistrationBean(new AuthenticatedRequestFilter(true))
+    frb.order = Ordered.HIGHEST_PRECEDENCE
+    return frb
+  }
+
 }
diff --git a/rosco-web/src/main/groovy/com/netflix/spinnaker/rosco/controllers/BakeryController.groovy b/rosco-web/src/main/groovy/com/netflix/spinnaker/rosco/controllers/BakeryController.groovy
@@ -27,6 +27,7 @@ import com.netflix.spinnaker.rosco.jobs.JobRequest
 import com.netflix.spinnaker.rosco.persistence.BakeStore
 import com.netflix.spinnaker.rosco.providers.CloudProviderBakeHandler
 import com.netflix.spinnaker.rosco.providers.registry.CloudProviderBakeHandlerRegistry
+import com.netflix.spinnaker.security.AuthenticatedRequest
 import groovy.transform.InheritConstructors
 import groovy.util.logging.Slf4j
 import io.swagger.annotations.ApiOperation
@@ -35,6 +36,7 @@ import org.springframework.beans.factory.annotation.Autowired
 import org.springframework.beans.factory.annotation.Value
 import org.springframework.http.HttpStatus
 import org.springframework.web.bind.annotation.*
+import org.springframework.web.method.annotation.RequestHeaderMapMethodArgumentResolver
 
 import java.util.concurrent.TimeUnit
 
@@ -148,8 +150,15 @@ class BakeryController {
   BakeStatus createBake(@PathVariable("region") String region,
                         @RequestBody BakeRequest bakeRequest,
                         @RequestParam(value = "rebake", defaultValue = "0") String rebake) {
+    String executionId = AuthenticatedRequest.getSpinnakerExecutionId().orElse(null)
+
     if (!bakeRequest.cloud_provider_type) {
-      bakeRequest = bakeRequest.copyWith(cloud_provider_type: defaultCloudProviderType)
+      bakeRequest = bakeRequest.copyWith(
+        cloud_provider_type: defaultCloudProviderType,
+        spinnaker_execution_id: executionId
+      )
+    } else if (executionId != null) {
+      bakeRequest = bakeRequest.copyWith(spinnaker_execution_id: executionId)
     }
 
     CloudProviderBakeHandler cloudProviderBakeHandler = cloudProviderBakeHandlerRegistry.lookup(bakeRequest.cloud_provider_type)
@@ -180,7 +189,8 @@ class BakeryController {
       def bakeRecipe = cloudProviderBakeHandler.produceBakeRecipe(region, bakeRequest)
       def jobRequest = new JobRequest(tokenizedCommand: bakeRecipe.command,
                                       maskedParameters: cloudProviderBakeHandler.maskedPackerParameters,
-                                      jobId: bakeRequest.request_id)
+                                      jobId: bakeRequest.request_id,
+                                      executionId: bakeRequest.spinnaker_execution_id)
 
       if (bakeStore.acquireBakeLock(bakeKey)) {
         return runBake(bakeKey, region, bakeRecipe, bakeRequest, jobRequest)