feat(log): annotations for json logging (#282)

spinnaker · Oct 11, 2017 · cf4619f · cf4619f
1 parent b17bf1c
commit cf4619f
Show file tree

Hide file tree

Showing 13 changed files with 143 additions and 74 deletions.
diff --git a/build.gradle b/build.gradle
@@ -36,7 +36,7 @@ allprojects { project ->
   group = "com.netflix.spinnaker.front50"
 
   ext {
-    spinnakerDependenciesVersion = project.hasProperty('spinnakerDependenciesVersion') ? project.property('spinnakerDependenciesVersion') : '0.109.2'
+    spinnakerDependenciesVersion = project.hasProperty('spinnakerDependenciesVersion') ? project.property('spinnakerDependenciesVersion') : '0.111.1'
   }
 
   def checkLocalVersions = [spinnakerDependenciesVersion: spinnakerDependenciesVersion]

diff --git a/front50-azure/src/main/java/com/netflix/spinnaker/front50/model/AzureStorageService.java b/front50-azure/src/main/java/com/netflix/spinnaker/front50/model/AzureStorageService.java
@@ -31,6 +31,8 @@
 import java.io.IOException;
 import java.util.*;
 
+import static net.logstash.logback.argument.StructuredArguments.value;
+
 public class AzureStorageService implements StorageService {
   private static final Logger log = LoggerFactory.getLogger(AzureStorageService.class);
   private String containerName;
@@ -98,7 +100,10 @@ public <T extends Timestamped> T loadObject(ObjectType objectType, String object
       logStorageException(se, key);
     }
     catch (Exception e) {
-      log.error("Failed to retrieve {} object: {}: {}", objectType.group, key, e.getMessage());
+      log.error("Failed to retrieve {} object: {}: {}",
+        value("group", objectType.group),
+        value("key", key),
+        value("exception", e.getMessage()));
     }
     return null;
   }
@@ -109,13 +114,17 @@ public void deleteObject(ObjectType objectType, String objectKey) {
     try {
       CloudBlockBlob blob = getBlobContainer().getBlockBlobReference(key);
       if (blob.deleteIfExists(DeleteSnapshotsOption.INCLUDE_SNAPSHOTS, null, null, null)) {
-        log.info("{} object {} has been successfully deleted", objectType.group, key);
+        log.info("{} object {} has been successfully deleted",
+          value("group", objectType.group),
+          value("key", key));
       }
       writeLastModified(objectType.group);
     } catch (StorageException se) {
       logStorageException(se, key);
     } catch (Exception e) {
-      log.error("Error encountered attempting to delete {} from storage: {}", key, e.getMessage());
+      log.error("Error encountered attempting to delete {} from storage: {}",
+        value("key", key),
+        value("exception", e.getMessage()));
     }
   }
 
@@ -133,14 +142,18 @@ public <T extends Timestamped> void storeObject(ObjectType objectType, String ob
       }
       blob.uploadFromByteArray(bytes, 0, bytes.length);
       writeLastModified(objectType.group);
-      log.info("{} object {} for  has been successfully uploaded.", objectType.group, key);
+      log.info("{} object {} for  has been successfully uploaded.",
+        value("group", objectType.group),
+        value("key", key));
     }
     catch (StorageException se) {
       logStorageException(se, key);
     }
     catch (Exception e)
     {
-      log.error("Error encountered attempting to store {}: {}", key, e.getMessage());
+      log.error("Error encountered attempting to store {}: {}",
+        value("key", key),
+        value("exception", e.getMessage()));
     }
   }
 
@@ -163,7 +176,9 @@ public Map<String, Long> listObjectKeys(ObjectType objectType) {
     } catch (StorageException se) {
       logStorageException(se, "");
     } catch (Exception e) {
-      log.error("Failed to retrieve objects from {}: {}", objectType.group, e.getMessage());
+      log.error("Failed to retrieve objects from {}: {}",
+        value("group", objectType.group),
+        value("exception", e.getMessage()));
     }
     return objectKeys;
   }
@@ -191,7 +206,9 @@ public <T extends Timestamped> Collection<T> listObjectVersions(ObjectType objec
     } catch (StorageException se) {
       logStorageException(se,fullKey);
     } catch (Exception e) {
-      log.error("Error retrieving versions for {} object: {}", fullKey, e.getMessage());
+      log.error("Error retrieving versions for {} object: {}",
+        value("key", fullKey),
+        value("exception", e.getMessage()));
     }
     return results;
   }
@@ -207,7 +224,9 @@ public long getLastModified(ObjectType objectType) {
     } catch (StorageException se) {
       logStorageException(se, "");
     } catch (Exception e) {
-      log.error("Exception occurred retrieving last modifed for {}: {}", objectType.group, e.getMessage());
+      log.error("Exception occurred retrieving last modifed for {}: {}",
+        value("group", objectType.group),
+        value("exception", e.getMessage()));
     }
     return 0;
   }
@@ -225,7 +244,7 @@ private void writeLastModified(String group) {
       logStorageException(se, "");
     }
     catch (Exception e) {
-      log.error("Exception occurred setting last modified date/time: {} ", e.getMessage());
+      log.error("Exception occurred setting last modified date/time: {} ", value("exception", e.getMessage()));
     }
   }
 
@@ -242,9 +261,16 @@ private void logStorageException(StorageException storageException, String key)
     String errorMsg = storageException.getExtendedErrorInformation().getErrorMessage();
     String errorCode = storageException.getExtendedErrorInformation().getErrorCode();
     if (key.isEmpty()) {
-      log.error("Exception occurred accessing object(s) from storage: HTTPStatusCode {} ErrorCode: {} {}", storageException.getHttpStatusCode(), errorCode, errorMsg);
+      log.error("Exception occurred accessing object(s) from storage: HTTPStatusCode {} ErrorCode: {} {}",
+        value("responseStatus", storageException.getHttpStatusCode()),
+        value("errorCode", errorCode),
+        value("errorMsg", errorMsg));
     } else {
-      log.error("Exception occurred accessing object(s) from storage: Key {} HTTPStatusCode {} ErrorCode: {} {}", key, storageException.getHttpStatusCode(), errorCode, errorMsg);
+      log.error("Exception occurred accessing object(s) from storage: Key {} HTTPStatusCode {} ErrorCode: {} {}",
+        value("key", key),
+        value("responseStatus", storageException.getHttpStatusCode()),
+        value("errorCode", errorCode),
+        value("errorMsg", errorMsg));
     }
   }
 

diff --git a/front50-core/src/main/groovy/com/netflix/spinnaker/front50/model/StorageServiceSupport.java b/front50-core/src/main/groovy/com/netflix/spinnaker/front50/model/StorageServiceSupport.java
@@ -36,6 +36,7 @@
 import java.util.function.ToDoubleFunction;
 import java.util.stream.Collectors;
 
+import static net.logstash.logback.argument.StructuredArguments.value;
 
 public abstract class StorageServiceSupport<T extends Timestamped> {
   private static final long HEALTH_MILLIS = TimeUnit.SECONDS.toMillis(90);
@@ -145,7 +146,9 @@ public Collection<T> all(boolean refresh) {
     long lastModified = readLastModified();
     if (lastModified > lastRefreshedTime.get() || allItemsCache.get() == null) {
       // only refresh if there was a modification since our last refresh cycle
-      log.debug("all() forcing refresh (lastModified: {}, lastRefreshed: {})", new Date(lastModified), new Date(lastRefreshedTime.get()));
+      log.debug("all() forcing refresh (lastModified: {}, lastRefreshed: {})",
+        value("lastModified", new Date(lastModified)),
+        value("lastRefreshed", new Date(lastRefreshedTime.get())));
       long startTime = System.nanoTime();
       refresh();
       long elapsed = System.nanoTime() - startTime;
@@ -273,7 +276,7 @@ private Set<T> fetchAllItems(Set<T> existingItems) {
     for (T item : existingItems) {
       if (keyUpdateTime.containsKey(buildObjectKey(item))) {
         if (resultMap.containsKey(item.getId())) {
-          log.error(String.format("Duplicate item id found, last-write wins: (id: %s)", item.getId()));
+          log.error("Duplicate item id found, last-write wins: (id: {})", value("id", item.getId()));
         }
         resultMap.put(item.getId(), item);
       }
@@ -299,7 +302,7 @@ private Set<T> fetchAllItems(Set<T> existingItems) {
 
     if (!existingItems.isEmpty() && !modifiedKeys.isEmpty()) {
       // only log keys that have been modified after initial cache load
-      log.debug("Modified object keys: {}", modifiedKeys);
+      log.debug("Modified object keys: {}", value("keys", modifiedKeys));
     }
 
     Observable
@@ -336,7 +339,9 @@ private Set<T> fetchAllItems(Set<T> existingItems) {
     removeCounter.increment(existingSize + numAdded.get() - resultSize);
     if (existingSize != resultSize) {
       log.info("{}={} delta={}",
-        objectType.group, resultSize, resultSize - existingSize);
+        value("objectType", objectType.group),
+        value("resultSize", resultSize),
+        value("delta", resultSize - existingSize));
     }
 
     return result;

diff --git a/...0-core/src/main/groovy/com/netflix/spinnaker/front50/model/application/Application.groovy b/...0-core/src/main/groovy/com/netflix/spinnaker/front50/model/application/Application.groovy
@@ -42,6 +42,8 @@ import groovy.transform.stc.SimpleType
 import groovy.util.logging.Slf4j
 import org.springframework.validation.Errors
 
+import static net.logstash.logback.argument.StructuredArguments.value
+
 @ToString
 @Slf4j
 class Application implements Timestamped {
@@ -146,7 +148,7 @@ class Application implements Timestamped {
     }
 
     if (!currentApplication) {
-      log.warn("Application does not exist (name: ${name}), nothing to delete")
+      log.warn("Application does not exist (name: {}), nothing to delete", value("application", name))
       return
     }
 
@@ -326,7 +328,8 @@ class Application implements Timestamped {
         log.error("Rollback failed (onRollback)", rollbackException)
       }
 
-      log.error("Failed to perform action (name: ${originalApplication?.name ?: updatedApplication?.name})")
+      log.error("Failed to perform action (name: {})",
+        value("application", originalApplication?.name ?: updatedApplication?.name))
       throw e
     }
   }
@@ -371,8 +374,8 @@ class Application implements Timestamped {
 
     @JsonSetter
     void setRequiredGroupMembership(List<String> requiredGroupMembership) {
-      log.warn("Required group membership settings detected in application ${name}. " +
-        "Please update to `permissions` format.")
+      log.warn("Required group membership settings detected in application {} " +
+        "Please update to `permissions` format.", value("application", name))
 
       if (!permissions.isRestricted()) { // Do not overwrite permissions if it contains values
         Permissions.Builder b = new Permissions.Builder()

diff --git a/front50-gcs/src/main/java/com/netflix/spinnaker/front50/config/GcsConfig.java b/front50-gcs/src/main/java/com/netflix/spinnaker/front50/config/GcsConfig.java
@@ -35,6 +35,8 @@
 import java.util.Optional;
 import java.util.concurrent.Executors;
 
+import static net.logstash.logback.argument.StructuredArguments.value;
+
 @Configuration
 @ConditionalOnExpression("${spinnaker.gcs.enabled:false}")
 @EnableConfigurationProperties(GcsProperties.class)
@@ -95,9 +97,10 @@ private GcsStorageService googleCloudStorageService(String dataFilename, GcsProp
     }
     service.ensureBucketExists();
     log.info("Using Google Cloud Storage bucket={} in project={}",
-      gcsProperties.getBucket(), gcsProperties.getProject());
+      value("bucket", gcsProperties.getBucket()),
+      value("project", gcsProperties.getProject()));
     log.info("Bucket versioning is {}.",
-      service.supportsVersioning() ? "enabled" : "DISABLED");
+      value("versioning", service.supportsVersioning() ? "enabled" : "DISABLED"));
     return service;
   }