refactor(logs): Structured logs (#152)

build.gradle

@@ -36,7 +36,7 @@ allprojects {
     group = "com.netflix.spinnaker.echo"
 
     ext {
-        spinnakerDependenciesVersion = project.hasProperty('spinnakerDependenciesVersion') ? project.property('spinnakerDependenciesVersion') : '0.91.0'
+        spinnakerDependenciesVersion = project.hasProperty('spinnakerDependenciesVersion') ? project.property('spinnakerDependenciesVersion') : '0.99.0'
     }
 
     def checkLocalVersions = [spinnakerDependenciesVersion: spinnakerDependenciesVersion]

echo-core/echo-core.gradle

@@ -19,6 +19,7 @@ dependencies {
 
     compile project(":echo-model")
     compile spinnaker.dependency('rxJava')
+    compile spinnaker.dependency('logstashEncoder')
     testCompile spinnaker.dependency('spockSpring')
     testCompile spinnaker.dependency('springTest')
 }

echo-core/src/main/groovy/com/netflix/spinnaker/echo/events/EventPropagator.groovy

@@ -22,7 +22,6 @@ import rx.Observable
 import rx.Scheduler
 import rx.functions.Action0
 import rx.schedulers.Schedulers
-
 /**
  *  responsible for sending events to classes that implement an EchoEventListener
  */

echo-notifications/src/main/groovy/com/netflix/spinnaker/echo/notification/EmailNotificationAgent.groovy

@@ -26,6 +26,7 @@ import org.springframework.stereotype.Service
 import org.springframework.ui.velocity.VelocityEngineUtils
 import static groovy.json.JsonOutput.prettyPrint
 import static groovy.json.JsonOutput.toJson
+import static net.logstash.logback.argument.StructuredArguments.*
 
 @Slf4j
 @ConditionalOnProperty('mail.enabled')
@@ -70,7 +71,7 @@ class EmailNotificationAgent extends AbstractEventNotificationAgent {
       status == 'complete' ? 'completed successfully' : status
     }"""
 
-    log.info("Send Email: ${preference.address} for ${application} ${config.type} ${status} ${event.content?.execution?.id}")
+    log.info('Sending email {} for {} {} {} {}', kv('address', preference.address), kv('application', application), kv('type', config.type), kv('status', status), kv('executionId', event.content?.execution?.id))
 
     sendMessage(
       preference.address ? [preference.address] as String[] : null,

echo-notifications/src/main/groovy/com/netflix/spinnaker/echo/notification/HipchatNotificationAgent.groovy

@@ -26,6 +26,8 @@ import org.springframework.beans.factory.annotation.Value
 import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty
 import org.springframework.stereotype.Service
 
+import static net.logstash.logback.argument.StructuredArguments.kv
+
 @Slf4j
 @ConditionalOnProperty('hipchat.enabled')
 @Service
@@ -65,8 +67,8 @@ class HipchatNotificationAgent extends AbstractEventNotificationAgent {
         }
       }
 
-      log.info("Send Hipchat message to" +
-        " ${preference.address} for ${application} ${config.type} ${status} ${event.content?.execution?.id}")
+      log.info('Sending Hipchat message {} for {} {} {} {}', kv('address', preference.address), kv('application', application), kv('type', config.type), kv('status', status), kv('executionId', event.content?.execution?.id))
+
 
       String message = ''
 

echo-notifications/src/main/groovy/com/netflix/spinnaker/echo/notification/SlackNotificationAgent.groovy

@@ -24,6 +24,8 @@ import org.springframework.beans.factory.annotation.Autowired
 import org.springframework.beans.factory.annotation.Value
 import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty
 import org.springframework.stereotype.Service
+import static net.logstash.logback.argument.StructuredArguments.*
+
 
 @Slf4j
 @ConditionalOnProperty('slack.enabled')
@@ -63,8 +65,7 @@ class SlackNotificationAgent extends AbstractEventNotificationAgent {
         }
       }
 
-      log.info("Send Slack message to" +
-        " ${preference.address} for ${application} ${config.type} ${status} ${event.content?.execution?.id}")
+      log.info('Sending Slack message {} for {} {} {} {}', kv('address', preference.address), kv('application', application), kv('type', config.type), kv('status', status), kv('executionId', event.content?.execution?.id))
 
       String body = ''
 

echo-notifications/src/main/groovy/com/netflix/spinnaker/echo/pagerduty/PagerDutyNotificationService.groovy

@@ -26,6 +26,8 @@ import org.springframework.beans.factory.annotation.Value
 import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty
 import org.springframework.stereotype.Component
 
+import static net.logstash.logback.argument.StructuredArguments.kv
+
 @Slf4j
 @Component
 @ConditionalOnProperty('pagerDuty.enabled')
@@ -58,7 +60,7 @@ class PagerDutyNotificationService implements NotificationService {
         )
       )
 
-      log.info("Sent page (serviceKey: ${it}, message: '${notification.additionalContext.message}')")
+      log.info('Sent page {} {}', kv('serviceKey', it), kv('message', notification.additionalContext.message))
     }
   }
 }

echo-scheduler/src/main/groovy/com/netflix/spinnaker/echo/scheduler/actions/pipeline/impl/MissedPipelineTriggerCompensationJob.groovy

@@ -41,6 +41,8 @@ import java.time.ZoneId
 import java.time.temporal.ChronoUnit
 import java.util.concurrent.TimeUnit
 
+import static net.logstash.logback.argument.StructuredArguments.*
+
 /**
  * Finds and executes all pipeline triggers that should have run in the last configured time window during startup.
  * This job will wait until the {@link com.netflix.spinnaker.echo.pipelinetriggers.PipelineCache} has run prior to
@@ -112,7 +114,7 @@ class MissedPipelineTriggerCompensationJob implements ApplicationListener<Contex
   }
 
   void onPipelineCacheError(Throwable t) {
-    log.error("Error waiting for pipeline cache: ${t.message}")
+    log.error("Error waiting for pipeline cache", t)
   }
 
   void triggerMissedExecutions(List<Pipeline> pipelines) {
@@ -149,7 +151,7 @@ class MissedPipelineTriggerCompensationJob implements ApplicationListener<Contex
       expr.timeZone = dateContext.timeZone
 
       if (missedExecution(expr, lastExecution, dateContext.triggerWindowFloor, dateContext.now)) {
-        log.info("Triggering missed execution on pipeline application:${pipeline.application}, pipelineConfigId:${pipeline.id}")
+        log.info('Triggering missed execution on pipeline {} {}', kv('application', pipeline.application), kv('pipelineConfigId', pipeline.id))
         pipelineInitiator.call(pipeline)
       }
     }

echo-scheduler/src/main/groovy/com/netflix/spinnaker/echo/scheduler/actions/pipeline/impl/PipelineConfigsPollingAgent.groovy

@@ -21,7 +21,6 @@ import com.netflix.scheduledactions.ActionsOperator
 import com.netflix.spinnaker.echo.model.Pipeline
 import com.netflix.spinnaker.echo.model.Trigger
 import com.netflix.spinnaker.echo.pipelinetriggers.PipelineCache
-import com.netflix.spinnaker.echo.services.Front50Service
 import groovy.util.logging.Slf4j
 import org.springframework.beans.factory.annotation.Autowired
 import org.springframework.beans.factory.annotation.Value
@@ -30,6 +29,8 @@ import org.springframework.boot.actuate.metrics.GaugeService
 import org.springframework.boot.autoconfigure.condition.ConditionalOnExpression
 import org.springframework.stereotype.Component
 
+import static net.logstash.logback.argument.StructuredArguments.*
+
 /**
  * This component does the polling of pipeline configs and does the CRUD operations on scheduled-actions
  * as needed
@@ -204,7 +205,7 @@ class PipelineConfigsPollingAgent extends AbstractPollingAgent {
              */
             ActionInstance actionInstance = PipelineTriggerConverter.toScheduledAction(pipeline, trigger, timeZoneId)
             actionsOperator.registerActionInstance(actionInstance)
-            log.info("Registered scheduled trigger '${actionInstance.id}' for ${trigger} of ${pipeline}")
+            log.info('Registered scheduled trigger {} {} {}', kv('id', actionInstance.id), kv('trigger', trigger), kv('pipeline', pipeline))
             counterService.increment("newTriggers.count")
 
           } catch (Exception e) {

echo-webhooks/src/main/groovy/com/netflix/spinnaker/echo/controllers/WebhooksController.groovy

@@ -30,6 +30,8 @@ import org.springframework.web.bind.annotation.RequestMapping
 import org.springframework.web.bind.annotation.RequestMethod
 import org.springframework.web.bind.annotation.RestController
 
+import static net.logstash.logback.argument.StructuredArguments.*
+
 @RestController
 @Slf4j
 class WebhooksController {
@@ -67,7 +69,7 @@ class WebhooksController {
         }
       } else if (source == 'github') {
         if (event.content.hook_id) {
-          log.info("Webook ping received from github hook_id=${event.content.hook_id} repository=${event.content.repository.full_name}")
+          log.info('Webhook ping received from github {} {} {}', kv('hook_id', event.content.hook_id), kv('repository', event.content.repository.full_name))
           sendEvent = false
         } else {
           event.content.hash = postedEvent.after
@@ -93,7 +95,7 @@ class WebhooksController {
         if (event.content.hash.toString().startsWith('000000000')) {
           sendEvent = false
         }
-        log.info("Webhook event received from ${type} event_type=${event.content.event_type} hook_id=${event.content.hook_id} repository=${event.content.repository.full_name} request_id=${event.content.request_id} branch=${event.content.branch}")
+        log.info('Webhook event received {} {} {} {} {} {}', kv('type', type), kv('event_type', event.content.event_type), kv('hook_id', event.content.hook_id), kv('repository', event.content.repository.full_name), kv('request_id', event.content.request_id), kv('branch', event.content.branch))
       }
     }