From 80f8f5ac7faf57c59a45ad5e50059b2e588b0cfe Mon Sep 17 00:00:00 2001
From: mcilwain <mcilwain@google.com>
Date: Thu, 29 Jun 2017 11:39:31 -0700
Subject: [PATCH] Add basic logging for async operation processing time

We're already storing this as a metric, but on a registry of our
scale these operations tend to only happen on a daily-ish basis,
for which seeing results in logs is easier to deal with than metrics
(and also still very light-weight).

-------------
Created by MOE: https://github.com/google/moe
MOE_MIGRATED_REVID=160552291
---
 .../registry/flows/async/AsyncFlowMetrics.java       | 12 +++++++++++-
 1 file changed, 11 insertions(+), 1 deletion(-)

diff --git a/java/google/registry/flows/async/AsyncFlowMetrics.java b/java/google/registry/flows/async/AsyncFlowMetrics.java
index 5da702464..f408ed903 100644
--- a/java/google/registry/flows/async/AsyncFlowMetrics.java
+++ b/java/google/registry/flows/async/AsyncFlowMetrics.java
@@ -18,6 +18,7 @@ import static com.google.appengine.api.taskqueue.QueueConstants.maxLeaseCount;
 import static google.registry.flows.async.AsyncFlowMetrics.OperationType.CONTACT_AND_HOST_DELETE;
 import static google.registry.flows.async.AsyncFlowMetrics.OperationType.DNS_REFRESH;
 import static google.registry.monitoring.metrics.EventMetric.DEFAULT_FITTER;
+import static google.registry.util.FormattingLogger.getLoggerForCallerClass;
 
 import com.google.common.annotations.VisibleForTesting;
 import com.google.common.collect.ImmutableSet;
@@ -28,6 +29,7 @@ import google.registry.monitoring.metrics.IncrementableMetric;
 import google.registry.monitoring.metrics.LabelDescriptor;
 import google.registry.monitoring.metrics.MetricRegistryImpl;
 import google.registry.util.Clock;
+import google.registry.util.FormattingLogger;
 import google.registry.util.NonFinalForTesting;
 import javax.inject.Inject;
 import org.joda.time.DateTime;
@@ -40,6 +42,8 @@ import org.joda.time.Duration;
  */
 public class AsyncFlowMetrics {
 
+  private static final FormattingLogger logger = getLoggerForCallerClass();
+
   private final Clock clock;
 
   @Inject
@@ -144,10 +148,16 @@ public class AsyncFlowMetrics {
       OperationType operationType, OperationResult operationResult, DateTime whenEnqueued) {
     asyncFlowOperationCounts.increment(
         operationType.getMetricLabelValue(), operationResult.getMetricLabelValue());
+    long processingMillis = new Duration(whenEnqueued, clock.nowUtc()).getMillis();
     asyncFlowOperationProcessingTime.record(
-        new Duration(whenEnqueued, clock.nowUtc()).getMillis(),
+        processingMillis,
         operationType.getMetricLabelValue(),
         operationResult.getMetricLabelValue());
+    logger.infofmt(
+        "Asynchronous %s operation took %d ms to process, yielding result: %s.",
+        operationType.getMetricLabelValue(),
+        processingMillis,
+        operationResult.getMetricLabelValue());
   }
 
   public void recordContactHostDeletionBatchSize(long batchSize) {