Add metric for DNS UPDATE latency

Added:
- dns/update_latency, which measures the time since a DNS update was added to the pull queue until that updates is committed to the DnsWriter
- - It doesn't check that after being committed, it was actually published in the DNS.

- dns/publish_queue_delay, which measures how long since the initial insertion to the push queue until a publishDnsUpdate action was handled. It measures both for successes (which is what we care about) and various failures (which are important because the success for that publishDnsUpdate will be > than any of the previous failures)

-------------
Created by MOE: https://github.com/google/moe
MOE_MIGRATED_REVID=185995678

java/google/registry/dns/DnsConstants.java

@@ -30,6 +30,9 @@ public class DnsConstants {
   /** The parameter to use for storing the target name (domain or host name) with the task. */
   public static final String DNS_TARGET_NAME_PARAM = "Target-Name";
 
-  /** The possible values of the {@code DNS_TARGET_NAME_PARAM} parameter. */
+  /** The parameter to use for storing the creation time with the task. */
+  public static final String DNS_TARGET_CREATE_TIME_PARAM = "Create-Time";
+
+  /** The possible values of the {@code DNS_TARGET_TYPE_PARAM} parameter. */
   public enum TargetType { DOMAIN, HOST, ZONE }
 }

java/google/registry/dns/DnsMetrics.java

@@ -40,6 +40,9 @@ public class DnsMetrics {
   /** Disposition of writer.commit(). */
   public enum CommitStatus { SUCCESS, FAILURE }
 
+  /** Disposition of the publish action. */
+  public enum ActionStatus { SUCCESS, COMMIT_FAILURE, LOCK_FAILURE, BAD_WRITER }
+
   private static final ImmutableSet<LabelDescriptor> LABEL_DESCRIPTORS_FOR_PUBLISH_REQUESTS =
       ImmutableSet.of(
           LabelDescriptor.create("tld", "TLD"),
@@ -52,10 +55,16 @@ public class DnsMetrics {
           LabelDescriptor.create("status", "Whether writer.commit() succeeded or failed."),
           LabelDescriptor.create("dnsWriter", "The DnsWriter used."));
 
-  // Finer-grained fitter than the DEFAULT_FITTER, allows values between 1. and 2^20, which gives
+  private static final ImmutableSet<LabelDescriptor> LABEL_DESCRIPTORS_FOR_LATENCY =
-  // over 15 minutes.
+      ImmutableSet.of(
+          LabelDescriptor.create("tld", "TLD"),
+          LabelDescriptor.create("status", "Whether the publish succeeded, or why it failed."),
+          LabelDescriptor.create("dnsWriter", "The DnsWriter used."));
+
+  // Finer-grained fitter than the DEFAULT_FITTER, allows values between 100 ms and just over 29
+  // hours.
   private static final DistributionFitter EXPONENTIAL_FITTER =
-      ExponentialFitter.create(20, 2.0, 1.0);
+      ExponentialFitter.create(20, 2.0, 100.0);
 
   // Fibonacci fitter more suitible for integer-type values. Allows values between 0 and 10946,
   // which is the 21th Fibonacci number.
@@ -156,6 +165,24 @@ public class DnsMetrics {
               LABEL_DESCRIPTORS_FOR_COMMIT,
               FIBONACCI_FITTER);
 
+  private static final EventMetric updateRequestLatency =
+      MetricRegistryImpl.getDefault()
+          .newEventMetric(
+              "/dns/update_latency",
+              "Time elapsed since refresh request was created until it was published",
+              "milliseconds",
+              LABEL_DESCRIPTORS_FOR_LATENCY,
+              EXPONENTIAL_FITTER);
+
+  private static final EventMetric publishQueueDelay =
+      MetricRegistryImpl.getDefault()
+          .newEventMetric(
+              "/dns/publish_queue_delay",
+              "Time elapsed since the publishDnsUpdates action was created until it was executed",
+              "milliseconds",
+              LABEL_DESCRIPTORS_FOR_LATENCY,
+              EXPONENTIAL_FITTER);
+
   @Inject RegistryEnvironment registryEnvironment;
   @Inject @Parameter(PARAM_TLD) String tld;
 
@@ -225,4 +252,15 @@ public class DnsMetrics {
     domainsCommittedCount.incrementBy(numberOfDomains, tld, status.name(), dnsWriter);
     hostsCommittedCount.incrementBy(numberOfHosts, tld, status.name(), dnsWriter);
   }
+
+  void recordActionResult(
+      String dnsWriter,
+      ActionStatus status,
+      int numberOfItems,
+      Duration timeSinceUpdateRequest,
+      Duration timeSinceActionEnqueued) {
+    updateRequestLatency.record(
+        timeSinceUpdateRequest.getMillis(), numberOfItems, tld, status.name(), dnsWriter);
+    publishQueueDelay.record(timeSinceActionEnqueued.getMillis(), tld, status.name(), dnsWriter);
+  }
 }

java/google/registry/dns/DnsModule.java

@@ -19,7 +19,10 @@ import static google.registry.dns.DnsConstants.DNS_PULL_QUEUE_NAME;
 import static google.registry.dns.PublishDnsUpdatesAction.PARAM_DNS_WRITER;
 import static google.registry.dns.PublishDnsUpdatesAction.PARAM_DOMAINS;
 import static google.registry.dns.PublishDnsUpdatesAction.PARAM_HOSTS;
+import static google.registry.dns.PublishDnsUpdatesAction.PARAM_PUBLISH_TASK_ENQUEUED;
+import static google.registry.dns.PublishDnsUpdatesAction.PARAM_REFRESH_REQUEST_CREATED;
 import static google.registry.request.RequestParameters.extractEnumParameter;
+import static google.registry.request.RequestParameters.extractOptionalParameter;
 import static google.registry.request.RequestParameters.extractRequiredParameter;
 import static google.registry.request.RequestParameters.extractSetOfParameters;
 
@@ -32,9 +35,11 @@ import google.registry.dns.DnsConstants.TargetType;
 import google.registry.dns.writer.DnsWriterZone;
 import google.registry.request.Parameter;
 import google.registry.request.RequestParameters;
+import java.util.Optional;
 import java.util.Set;
 import javax.inject.Named;
 import javax.servlet.http.HttpServletRequest;
+import org.joda.time.DateTime;
 
 /** Dagger module for the dns package. */
 @Module
@@ -56,6 +61,20 @@ public abstract class DnsModule {
     return QueueFactory.getQueue(DNS_PUBLISH_PUSH_QUEUE_NAME);
   }
 
+  @Provides
+  @Parameter(PARAM_PUBLISH_TASK_ENQUEUED)
+  // TODO(b/73343464): make the param required once the transition has finished
+  static Optional<DateTime> provideCreateTime(HttpServletRequest req) {
+    return extractOptionalParameter(req, PARAM_PUBLISH_TASK_ENQUEUED).map(DateTime::parse);
+  }
+
+  @Provides
+  @Parameter(PARAM_REFRESH_REQUEST_CREATED)
+  // TODO(b/73343464): make the param required once the transition has finished
+  static Optional<DateTime> provideItemsCreateTime(HttpServletRequest req) {
+    return extractOptionalParameter(req, PARAM_REFRESH_REQUEST_CREATED).map(DateTime::parse);
+  }
+
   @Provides
   @Parameter(PARAM_DNS_WRITER)
   static String provideDnsWriter(HttpServletRequest req) {

java/google/registry/dns/DnsQueue.java

@@ -17,6 +17,7 @@ package google.registry.dns;
 import static com.google.appengine.api.taskqueue.QueueFactory.getQueue;
 import static com.google.common.base.Preconditions.checkArgument;
 import static google.registry.dns.DnsConstants.DNS_PULL_QUEUE_NAME;
+import static google.registry.dns.DnsConstants.DNS_TARGET_CREATE_TIME_PARAM;
 import static google.registry.dns.DnsConstants.DNS_TARGET_NAME_PARAM;
 import static google.registry.dns.DnsConstants.DNS_TARGET_TYPE_PARAM;
 import static google.registry.model.registry.Registries.assertTldExists;
@@ -37,8 +38,10 @@ import com.google.common.net.InternetDomainName;
 import com.google.common.util.concurrent.RateLimiter;
 import google.registry.dns.DnsConstants.TargetType;
 import google.registry.model.registry.Registries;
+import google.registry.util.Clock;
 import google.registry.util.FormattingLogger;
 import google.registry.util.NonFinalForTesting;
+import google.registry.util.SystemClock;
 import java.util.List;
 import java.util.Optional;
 import java.util.logging.Level;
@@ -66,6 +69,8 @@ public class DnsQueue {
 
   private final Queue queue;
 
+  final Clock clock;
+
   // Queue.leaseTasks is limited to 10 requests per second as per
   // https://cloud.google.com/appengine/docs/standard/java/javadoc/com/google/appengine/api/taskqueue/Queue.html
   // "If you generate more than 10 LeaseTasks requests per second, only the first 10 requests will
@@ -73,8 +78,9 @@ public class DnsQueue {
   private static final RateLimiter rateLimiter = RateLimiter.create(9);
 
   @Inject
-  public DnsQueue(@Named(DNS_PULL_QUEUE_NAME) Queue queue) {
+  public DnsQueue(@Named(DNS_PULL_QUEUE_NAME) Queue queue, Clock clock) {
     this.queue = queue;
+    this.clock = clock;
   }
 
   /**
@@ -85,7 +91,12 @@ public class DnsQueue {
    * reducer classes in mapreduces that need to be Serializable.
    */
   public static DnsQueue create() {
-    return new DnsQueue(getQueue(DNS_PULL_QUEUE_NAME));
+    return new DnsQueue(getQueue(DNS_PULL_QUEUE_NAME), new SystemClock());
+  }
+
+  @VisibleForTesting
+  public static DnsQueue createForTesting(Clock clock) {
+    return new DnsQueue(getQueue(DNS_PULL_QUEUE_NAME), clock);
   }
 
   @NonFinalForTesting
@@ -99,11 +110,12 @@ public class DnsQueue {
     logger.infofmt(
         "Adding task type=%s, target=%s, tld=%s to pull queue %s (%d tasks currently on queue)",
         targetType, targetName, tld, DNS_PULL_QUEUE_NAME, queue.fetchStatistics().getNumTasks());
-    return queue.add(TaskOptions.Builder
+    return queue.add(
-        .withDefaults()
+        TaskOptions.Builder.withDefaults()
             .method(Method.PULL)
             .param(DNS_TARGET_TYPE_PARAM, targetType.toString())
             .param(DNS_TARGET_NAME_PARAM, targetName)
+            .param(DNS_TARGET_CREATE_TIME_PARAM, clock.nowUtc().toString())
             .param(PARAM_TLD, tld));
   }
 

java/google/registry/dns/PublishDnsUpdatesAction.java

@@ -20,6 +20,7 @@ import static google.registry.util.CollectionUtils.nullToEmpty;
 
 import com.google.common.net.InternetDomainName;
 import google.registry.config.RegistryConfig.Config;
+import google.registry.dns.DnsMetrics.ActionStatus;
 import google.registry.dns.DnsMetrics.CommitStatus;
 import google.registry.dns.DnsMetrics.PublishStatus;
 import google.registry.dns.writer.DnsWriter;
@@ -32,6 +33,7 @@ import google.registry.request.lock.LockHandler;
 import google.registry.util.Clock;
 import google.registry.util.DomainNameUtils;
 import google.registry.util.FormattingLogger;
+import java.util.Optional;
 import java.util.Set;
 import java.util.concurrent.Callable;
 import javax.inject.Inject;
@@ -51,6 +53,8 @@ public final class PublishDnsUpdatesAction implements Runnable, Callable<Void> {
   public static final String PARAM_DNS_WRITER = "dnsWriter";
   public static final String PARAM_DOMAINS = "domains";
   public static final String PARAM_HOSTS = "hosts";
+  public static final String PARAM_PUBLISH_TASK_ENQUEUED = "enqueued";
+  public static final String PARAM_REFRESH_REQUEST_CREATED = "itemsCreated";
   public static final String LOCK_NAME = "DNS updates";
 
   private static final FormattingLogger logger = FormattingLogger.getLoggerForCallerClass();
@@ -69,6 +73,10 @@ public final class PublishDnsUpdatesAction implements Runnable, Callable<Void> {
    * out (and not necessarily currently).
    */
   @Inject @Parameter(PARAM_DNS_WRITER) String dnsWriter;
+  // TODO(b/73343464): make not-optional once transition has ended
+  @Inject @Parameter(PARAM_PUBLISH_TASK_ENQUEUED) Optional<DateTime> enqueuedTime;
+  // TODO(b/73343464): make not-optional once transition has ended
+  @Inject @Parameter(PARAM_REFRESH_REQUEST_CREATED) Optional<DateTime> itemsCreateTime;
 
   @Inject @Parameter(PARAM_DOMAINS) Set<String> domains;
   @Inject @Parameter(PARAM_HOSTS) Set<String> hosts;
@@ -77,6 +85,26 @@ public final class PublishDnsUpdatesAction implements Runnable, Callable<Void> {
   @Inject Clock clock;
   @Inject PublishDnsUpdatesAction() {}
 
+  private void recordActionResult(ActionStatus status) {
+    DateTime now = clock.nowUtc();
+
+    dnsMetrics.recordActionResult(
+        dnsWriter,
+        status,
+        nullToEmpty(domains).size() + nullToEmpty(hosts).size(),
+        new Duration(itemsCreateTime.orElse(now), now),
+        new Duration(enqueuedTime.orElse(now), now));
+    logger.infofmt(
+        "publishDnsWriter latency statistics: TLD: %s, dnsWriter: %s, actionStatus: %s, "
+            + "numItems: %s, timeSinceCreation: %s, timeInQueue: %s",
+        tld,
+        dnsWriter,
+        status,
+        nullToEmpty(domains).size() + nullToEmpty(hosts).size(),
+        new Duration(itemsCreateTime.orElse(now), now),
+        new Duration(enqueuedTime.orElse(now), now));
+  }
+
   /** Runs the task. */
   @Override
   public void run() {
@@ -85,6 +113,7 @@ public final class PublishDnsUpdatesAction implements Runnable, Callable<Void> {
     // in the update task being dequeued and dropped. A message will already have been logged
     // to indicate the problem.
     if (!lockHandler.executeWithLocks(this, tld, timeout, LOCK_NAME)) {
+      recordActionResult(ActionStatus.LOCK_FAILURE);
       throw new ServiceUnavailableException("Lock failure");
     }
   }
@@ -116,6 +145,7 @@ public final class PublishDnsUpdatesAction implements Runnable, Callable<Void> {
       logger.warningfmt(
           "Couldn't get writer %s for TLD %s, pushing domains back to the queue for retry",
           dnsWriter, tld);
+      recordActionResult(ActionStatus.BAD_WRITER);
       requeueBatch();
       return;
     }
@@ -155,11 +185,14 @@ public final class PublishDnsUpdatesAction implements Runnable, Callable<Void> {
     // If we got here it means we managed to stage the entire batch without any errors.
     // Next we will commit the batch.
     CommitStatus commitStatus = CommitStatus.FAILURE;
+    ActionStatus actionStatus = ActionStatus.COMMIT_FAILURE;
     try {
       writer.commit();
       // No error was thrown
       commitStatus = CommitStatus.SUCCESS;
+      actionStatus = ActionStatus.SUCCESS;
     } finally {
+      recordActionResult(actionStatus);
       Duration duration = new Duration(timeAtStart, clock.nowUtc());
       dnsMetrics.recordCommit(
           dnsWriter,
@@ -168,9 +201,10 @@ public final class PublishDnsUpdatesAction implements Runnable, Callable<Void> {
           domainsPublished,
           hostsPublished);
       logger.infofmt(
-          "writer.commit() statistics:: TLD: %s, commitStatus: %s, duration: %s, "
+          "writer.commit() statistics: TLD: %s, dnsWriter: %s, commitStatus: %s, duration: %s, "
               + "domainsPublished: %d, domainsRejected: %d, hostsPublished: %d, hostsRejected: %d",
           tld,
+          dnsWriter,
           commitStatus,
           duration,
           domainsPublished,

java/google/registry/dns/ReadDnsQueueAction.java

@@ -17,6 +17,7 @@ package google.registry.dns;
 import static com.google.appengine.api.taskqueue.TaskOptions.Builder.withUrl;
 import static com.google.common.collect.Sets.difference;
 import static google.registry.dns.DnsConstants.DNS_PUBLISH_PUSH_QUEUE_NAME;
+import static google.registry.dns.DnsConstants.DNS_TARGET_CREATE_TIME_PARAM;
 import static google.registry.dns.DnsConstants.DNS_TARGET_NAME_PARAM;
 import static google.registry.dns.DnsConstants.DNS_TARGET_TYPE_PARAM;
 import static java.util.concurrent.TimeUnit.SECONDS;
@@ -44,6 +45,7 @@ import google.registry.util.FormattingLogger;
 import google.registry.util.TaskEnqueuer;
 import java.io.UnsupportedEncodingException;
 import java.util.Collection;
+import java.util.Comparator;
 import java.util.List;
 import java.util.Map;
 import java.util.Optional;
@@ -99,19 +101,22 @@ public final class ReadDnsQueueAction implements Runnable {
   /** Container for items we pull out of the DNS pull queue and process for fanout. */
   @AutoValue
   abstract static class RefreshItem implements Comparable<RefreshItem> {
-    static RefreshItem create(TargetType type, String name) {
+    static RefreshItem create(TargetType type, String name, DateTime creationTime) {
-      return new AutoValue_ReadDnsQueueAction_RefreshItem(type, name);
+      return new AutoValue_ReadDnsQueueAction_RefreshItem(type, name, creationTime);
     }
 
     abstract TargetType type();
 
     abstract String name();
 
+    abstract DateTime creationTime();
+
     @Override
     public int compareTo(RefreshItem other) {
       return ComparisonChain.start()
           .compare(this.type(), other.type())
           .compare(this.name(), other.name())
+          .compare(this.creationTime(), other.creationTime())
           .result();
     }
   }
@@ -207,7 +212,7 @@ public final class ReadDnsQueueAction implements Runnable {
    * tasks for paused TLDs or tasks for TLDs not part of {@link Registries#getTlds()}.
    */
   private void dispatchTasks(ImmutableSet<TaskHandle> tasks, ImmutableSet<String> tlds) {
-    ClassifiedTasks classifiedTasks = classifyTasks(tasks, tlds);
+    ClassifiedTasks classifiedTasks = classifyTasks(tasks, tlds, clock.nowUtc());
     if (!classifiedTasks.pausedTlds().isEmpty()) {
       logger.infofmt("The dns-pull queue is paused for TLDs: %s.", classifiedTasks.pausedTlds());
     }
@@ -244,7 +249,7 @@ public final class ReadDnsQueueAction implements Runnable {
    * taken on them) or in no category (if no action is to be taken on them)
    */
   private static ClassifiedTasks classifyTasks(
-      ImmutableSet<TaskHandle> tasks, ImmutableSet<String> tlds) {
+      ImmutableSet<TaskHandle> tasks, ImmutableSet<String> tlds, DateTime now) {
 
     ClassifiedTasks.Builder classifiedTasksBuilder = ClassifiedTasks.builder();
 
@@ -252,6 +257,14 @@ public final class ReadDnsQueueAction implements Runnable {
     for (TaskHandle task : tasks) {
       try {
         Map<String, String> params = ImmutableMap.copyOf(task.extractParams());
+        // We allow 'null' create-time for the transition period - and during that time we set the
+        // create-time to "now".
+        //
+        // TODO(b/73343464):remove support for null create-time once transition is over.
+        DateTime creationTime =
+            Optional.ofNullable(params.get(DNS_TARGET_CREATE_TIME_PARAM))
+                .map(DateTime::parse)
+                .orElse(now);
         String tld = params.get(RequestParameters.PARAM_TLD);
         if (tld == null) {
           logger.severefmt("Discarding invalid DNS refresh request %s; no TLD specified.", task);
@@ -270,7 +283,7 @@ public final class ReadDnsQueueAction implements Runnable {
             case HOST:
               classifiedTasksBuilder
                   .refreshItemsByTldBuilder()
-                  .put(tld, RefreshItem.create(type, name));
+                  .put(tld, RefreshItem.create(type, name, creationTime));
               break;
             default:
               logger.severefmt("Discarding DNS refresh request %s of type %s.", task, typeString);
@@ -292,13 +305,23 @@ public final class ReadDnsQueueAction implements Runnable {
       String tld = tldRefreshItemsEntry.getKey();
       for (List<RefreshItem> chunk :
           Iterables.partition(tldRefreshItemsEntry.getValue(), tldUpdateBatchSize)) {
+        DateTime earliestCreateTime =
+            chunk.stream().map(RefreshItem::creationTime).min(Comparator.naturalOrder()).get();
         for (String dnsWriter : Registry.get(tld).getDnsWriters()) {
-          TaskOptions options = withUrl(PublishDnsUpdatesAction.PATH)
+          TaskOptions options =
-              .countdownMillis(jitterSeconds.isPresent()
+              withUrl(PublishDnsUpdatesAction.PATH)
+                  .countdownMillis(
+                      jitterSeconds.isPresent()
                           ? random.nextInt((int) SECONDS.toMillis(jitterSeconds.get()))
                           : 0)
                   .param(RequestParameters.PARAM_TLD, tld)
-              .param(PublishDnsUpdatesAction.PARAM_DNS_WRITER, dnsWriter);
+                  .param(PublishDnsUpdatesAction.PARAM_DNS_WRITER, dnsWriter)
+                  .param(
+                      PublishDnsUpdatesAction.PARAM_PUBLISH_TASK_ENQUEUED,
+                      clock.nowUtc().toString())
+                  .param(
+                      PublishDnsUpdatesAction.PARAM_REFRESH_REQUEST_CREATED,
+                      earliestCreateTime.toString());
           for (RefreshItem refreshItem : chunk) {
             options.param(
                 (refreshItem.type() == TargetType.HOST)

javatests/google/registry/dns/DnsQueueTest.java

@@ -21,7 +21,9 @@ import static google.registry.testing.TaskQueueHelper.assertNoTasksEnqueued;
 import static google.registry.testing.TaskQueueHelper.assertTasksEnqueued;
 
 import google.registry.testing.AppEngineRule;
+import google.registry.testing.FakeClock;
 import google.registry.testing.TaskQueueHelper.TaskMatcher;
+import org.joda.time.DateTime;
 import org.junit.Before;
 import org.junit.Rule;
 import org.junit.Test;
@@ -38,10 +40,11 @@ public class DnsQueueTest {
       .withTaskQueue()
       .build();
   private DnsQueue dnsQueue;
+  private final FakeClock clock = new FakeClock(DateTime.parse("2010-01-01T10:00:00Z"));
 
   @Before
   public void init() {
-    dnsQueue = DnsQueue.create();
+    dnsQueue = DnsQueue.createForTesting(clock);
     dnsQueue.leaseTasksBatchSize = 10;
   }
 
@@ -54,6 +57,7 @@ public class DnsQueueTest {
         new TaskMatcher()
             .param("Target-Type", "HOST")
             .param("Target-Name", "octopus.tld")
+            .param("Create-Time", "2010-01-01T10:00:00.000Z")
             .param("tld", "tld"));
   }
 
@@ -83,6 +87,7 @@ public class DnsQueueTest {
         new TaskMatcher()
             .param("Target-Type", "DOMAIN")
             .param("Target-Name", "octopus.tld")
+            .param("Create-Time", "2010-01-01T10:00:00.000Z")
             .param("tld", "tld"));
   }
 
@@ -101,4 +106,3 @@ public class DnsQueueTest {
     assertThat(thrown).hasMessageThat().contains("TLD notatld does not exist");
   }
 }
-

javatests/google/registry/dns/PublishDnsUpdatesActionTest.java

@@ -20,12 +20,14 @@ import static google.registry.testing.DatastoreHelper.persistActiveDomain;
 import static google.registry.testing.DatastoreHelper.persistActiveSubordinateHost;
 import static google.registry.testing.DatastoreHelper.persistResource;
 import static google.registry.testing.JUnitBackports.expectThrows;
+import static org.mockito.Mockito.doThrow;
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.verifyNoMoreInteractions;
 
 import com.google.common.collect.ImmutableMap;
 import com.google.common.collect.ImmutableSet;
+import google.registry.dns.DnsMetrics.ActionStatus;
 import google.registry.dns.DnsMetrics.CommitStatus;
 import google.registry.dns.DnsMetrics.PublishStatus;
 import google.registry.dns.writer.DnsWriter;
@@ -37,6 +39,7 @@ import google.registry.testing.AppEngineRule;
 import google.registry.testing.FakeClock;
 import google.registry.testing.FakeLockHandler;
 import google.registry.testing.InjectRule;
+import java.util.Optional;
 import org.joda.time.DateTime;
 import org.joda.time.Duration;
 import org.junit.Before;
@@ -87,6 +90,8 @@ public class PublishDnsUpdatesActionTest {
     action.tld = tld;
     action.hosts = ImmutableSet.of();
     action.domains = ImmutableSet.of();
+    action.itemsCreateTime = Optional.of(clock.nowUtc().minusHours(2));
+    action.enqueuedTime = Optional.of(clock.nowUtc().minusHours(1));
     action.dnsWriter = "correctWriter";
     action.dnsWriterProxy = new DnsWriterProxy(ImmutableMap.of("correctWriter", dnsWriter));
     action.dnsMetrics = dnsMetrics;
@@ -111,6 +116,13 @@ public class PublishDnsUpdatesActionTest {
     verify(dnsMetrics).incrementPublishHostRequests(1, PublishStatus.ACCEPTED);
     verify(dnsMetrics).incrementPublishHostRequests(0, PublishStatus.REJECTED);
     verify(dnsMetrics).recordCommit("correctWriter", CommitStatus.SUCCESS, Duration.ZERO, 0, 1);
+    verify(dnsMetrics)
+        .recordActionResult(
+            "correctWriter",
+            ActionStatus.SUCCESS,
+            1,
+            Duration.standardHours(2),
+            Duration.standardHours(1));
     verifyNoMoreInteractions(dnsMetrics);
 
     verifyNoMoreInteractions(dnsQueue);
@@ -131,6 +143,40 @@ public class PublishDnsUpdatesActionTest {
     verify(dnsMetrics).incrementPublishHostRequests(0, PublishStatus.ACCEPTED);
     verify(dnsMetrics).incrementPublishHostRequests(0, PublishStatus.REJECTED);
     verify(dnsMetrics).recordCommit("correctWriter", CommitStatus.SUCCESS, Duration.ZERO, 1, 0);
+    verify(dnsMetrics)
+        .recordActionResult(
+            "correctWriter",
+            ActionStatus.SUCCESS,
+            1,
+            Duration.standardHours(2),
+            Duration.standardHours(1));
+    verifyNoMoreInteractions(dnsMetrics);
+
+    verifyNoMoreInteractions(dnsQueue);
+  }
+
+  @Test
+  public void testPublish_commitFails() throws Exception {
+    action = createAction("xn--q9jyb4c");
+    action.domains = ImmutableSet.of("example.xn--q9jyb4c", "example2.xn--q9jyb4c");
+    action.hosts =
+        ImmutableSet.of(
+            "ns1.example.xn--q9jyb4c", "ns2.example.xn--q9jyb4c", "ns1.example2.xn--q9jyb4c");
+    doThrow(new RuntimeException()).when(dnsWriter).commit();
+    expectThrows(RuntimeException.class, action::run);
+
+    verify(dnsMetrics).incrementPublishDomainRequests(2, PublishStatus.ACCEPTED);
+    verify(dnsMetrics).incrementPublishDomainRequests(0, PublishStatus.REJECTED);
+    verify(dnsMetrics).incrementPublishHostRequests(3, PublishStatus.ACCEPTED);
+    verify(dnsMetrics).incrementPublishHostRequests(0, PublishStatus.REJECTED);
+    verify(dnsMetrics).recordCommit("correctWriter", CommitStatus.FAILURE, Duration.ZERO, 2, 3);
+    verify(dnsMetrics)
+        .recordActionResult(
+            "correctWriter",
+            ActionStatus.COMMIT_FAILURE,
+            5,
+            Duration.standardHours(2),
+            Duration.standardHours(1));
     verifyNoMoreInteractions(dnsMetrics);
 
     verifyNoMoreInteractions(dnsQueue);
@@ -157,6 +203,13 @@ public class PublishDnsUpdatesActionTest {
     verify(dnsMetrics).incrementPublishHostRequests(3, PublishStatus.ACCEPTED);
     verify(dnsMetrics).incrementPublishHostRequests(0, PublishStatus.REJECTED);
     verify(dnsMetrics).recordCommit("correctWriter", CommitStatus.SUCCESS, Duration.ZERO, 2, 3);
+    verify(dnsMetrics)
+        .recordActionResult(
+            "correctWriter",
+            ActionStatus.SUCCESS,
+            5,
+            Duration.standardHours(2),
+            Duration.standardHours(1));
     verifyNoMoreInteractions(dnsMetrics);
 
     verifyNoMoreInteractions(dnsQueue);
@@ -177,6 +230,13 @@ public class PublishDnsUpdatesActionTest {
     verify(dnsMetrics).incrementPublishHostRequests(0, PublishStatus.ACCEPTED);
     verify(dnsMetrics).incrementPublishHostRequests(3, PublishStatus.REJECTED);
     verify(dnsMetrics).recordCommit("correctWriter", CommitStatus.SUCCESS, Duration.ZERO, 0, 0);
+    verify(dnsMetrics)
+        .recordActionResult(
+            "correctWriter",
+            ActionStatus.SUCCESS,
+            5,
+            Duration.standardHours(2),
+            Duration.standardHours(1));
     verifyNoMoreInteractions(dnsMetrics);
 
     verifyNoMoreInteractions(dnsQueue);
@@ -184,24 +244,26 @@ public class PublishDnsUpdatesActionTest {
 
   @Test
   public void testLockIsntAvailable() throws Exception {
-    ServiceUnavailableException thrown =
-        expectThrows(
-            ServiceUnavailableException.class,
-            () -> {
     action = createAction("xn--q9jyb4c");
     action.domains = ImmutableSet.of("example.com", "example2.com");
-              action.hosts =
+    action.hosts = ImmutableSet.of("ns1.example.com", "ns2.example.com", "ns1.example2.com");
-                  ImmutableSet.of("ns1.example.com", "ns2.example.com", "ns1.example2.com");
     action.lockHandler = new FakeLockHandler(false);
-              action.run();
+    ServiceUnavailableException thrown =
+        expectThrows(ServiceUnavailableException.class, action::run);
+    assertThat(thrown).hasMessageThat().contains("Lock failure");
 
     verifyNoMoreInteractions(dnsWriter);
 
+    verify(dnsMetrics)
+        .recordActionResult(
+            "correctWriter",
+            ActionStatus.LOCK_FAILURE,
+            5,
+            Duration.standardHours(2),
+            Duration.standardHours(1));
     verifyNoMoreInteractions(dnsMetrics);
 
     verifyNoMoreInteractions(dnsQueue);
-            });
-    assertThat(thrown).hasMessageThat().contains("Lock failure");
   }
 
   @Test
@@ -214,6 +276,13 @@ public class PublishDnsUpdatesActionTest {
 
     verifyNoMoreInteractions(dnsWriter);
 
+    verify(dnsMetrics)
+        .recordActionResult(
+            "wrongWriter",
+            ActionStatus.BAD_WRITER,
+            5,
+            Duration.standardHours(2),
+            Duration.standardHours(1));
     verifyNoMoreInteractions(dnsMetrics);
 
     verify(dnsQueue).addDomainRefreshTask("example.com");

javatests/google/registry/dns/ReadDnsQueueActionTest.java

@@ -21,6 +21,7 @@ import static com.google.common.truth.Truth.assertThat;
 import static com.google.common.truth.Truth8.assertThat;
 import static google.registry.dns.DnsConstants.DNS_PUBLISH_PUSH_QUEUE_NAME;
 import static google.registry.dns.DnsConstants.DNS_PULL_QUEUE_NAME;
+import static google.registry.dns.DnsConstants.DNS_TARGET_CREATE_TIME_PARAM;
 import static google.registry.dns.DnsConstants.DNS_TARGET_NAME_PARAM;
 import static google.registry.dns.DnsConstants.DNS_TARGET_TYPE_PARAM;
 import static google.registry.request.RequestParameters.PARAM_TLD;
@@ -52,7 +53,6 @@ import java.util.Map.Entry;
 import java.util.Optional;
 import java.util.stream.IntStream;
 import org.joda.time.DateTime;
-import org.joda.time.DateTimeZone;
 import org.joda.time.Duration;
 import org.junit.Before;
 import org.junit.Rule;
@@ -66,7 +66,7 @@ public class ReadDnsQueueActionTest {
 
   private static final int TEST_TLD_UPDATE_BATCH_SIZE = 100;
   private DnsQueue dnsQueue;
-  private FakeClock clock = new FakeClock(DateTime.now(DateTimeZone.UTC));
+  private FakeClock clock = new FakeClock(DateTime.parse("3000-01-01TZ"));
 
   @Rule
   public final AppEngineRule appEngine = AppEngineRule.builder()
@@ -88,7 +88,9 @@ public class ReadDnsQueueActionTest {
 
   @Before
   public void before() throws Exception {
-    clock.setTo(DateTime.now(DateTimeZone.UTC));
+    // Because of b/73372999 - the FakeClock can't be in the past, or the TaskQueues stop working.
+    // To make sure it's never in the past, we set the date far-far into the future
+    clock.setTo(DateTime.parse("3000-01-01TZ"));
     createTlds("com", "net", "example");
     persistResource(
         Registry.get("com").asBuilder().setDnsWriters(ImmutableSet.of("comWriter")).build());
@@ -100,7 +102,7 @@ public class ReadDnsQueueActionTest {
             .setTldType(TldType.TEST)
             .setDnsWriters(ImmutableSet.of("exampleWriter"))
             .build());
-    dnsQueue = DnsQueue.create();
+    dnsQueue = DnsQueue.createForTesting(clock);
   }
 
   private void run() throws Exception {
@@ -113,7 +115,7 @@ public class ReadDnsQueueActionTest {
     action.taskEnqueuer = new TaskEnqueuer(new Retrier(null, 1));
     action.jitterSeconds = Optional.empty();
     // Advance the time a little, to ensure that leaseTasks() returns all tasks.
-    clock.setTo(DateTime.now(DateTimeZone.UTC).plusMillis(1));
+    clock.advanceBy(Duration.standardHours(1));
     action.run();
   }
 
@@ -134,6 +136,8 @@ public class ReadDnsQueueActionTest {
 
   private void assertTldsEnqueuedInPushQueue(ImmutableMultimap<String, String> tldsToDnsWriters)
       throws Exception {
+    // By default, the publishDnsUpdates tasks will be enqueued one hour after the update items were
+    // created in the pull queue. This is because of the clock.advanceBy in run()
     assertTasksEnqueued(
         DNS_PUBLISH_PUSH_QUEUE_NAME,
         transform(
@@ -143,6 +147,8 @@ public class ReadDnsQueueActionTest {
                     .url(PublishDnsUpdatesAction.PATH)
                     .param("tld", tldToDnsWriter.getKey())
                     .param("dnsWriter", tldToDnsWriter.getValue())
+                    .param("itemsCreated", "3000-01-01T00:00:00.000Z")
+                    .param("enqueued", "3000-01-01T01:00:00.000Z")
                     .header("content-type", "application/x-www-form-urlencoded")));
   }
 
@@ -208,6 +214,29 @@ public class ReadDnsQueueActionTest {
     assertTldsEnqueuedInPushQueue(ImmutableMultimap.of("com", "comWriter", "com", "otherWriter"));
   }
 
+  @Test
+  public void testSuccess_differentUpdateTimes_usesMinimum() throws Exception {
+    clock.setTo(DateTime.parse("3000-02-03TZ"));
+    dnsQueue.addDomainRefreshTask("domain1.com");
+    clock.setTo(DateTime.parse("3000-02-04TZ"));
+    dnsQueue.addDomainRefreshTask("domain2.com");
+    clock.setTo(DateTime.parse("3000-02-05TZ"));
+    dnsQueue.addDomainRefreshTask("domain3.com");
+    run();
+    assertNoTasksEnqueued(DNS_PULL_QUEUE_NAME);
+    assertThat(getQueuedParams(DNS_PUBLISH_PUSH_QUEUE_NAME))
+        .containsExactly(
+            new ImmutableMultimap.Builder<String, String>()
+                .put("enqueued", "3000-02-05T01:00:00.000Z")
+                .put("itemsCreated", "3000-02-03T00:00:00.000Z")
+                .put("tld", "com")
+                .put("dnsWriter", "comWriter")
+                .put("domains", "domain1.com")
+                .put("domains", "domain2.com")
+                .put("domains", "domain3.com")
+                .build());
+  }
+
   @Test
   public void testSuccess_oneTldPaused_returnedToQueue() throws Exception {
     persistResource(Registry.get("net").asBuilder().setDnsPaused(true).build());
@@ -248,6 +277,7 @@ public class ReadDnsQueueActionTest {
                 .method(Method.PULL)
                 .param(DNS_TARGET_TYPE_PARAM, TargetType.DOMAIN.toString())
                 .param(DNS_TARGET_NAME_PARAM, "domain.wrongtld")
+                .param(DNS_TARGET_CREATE_TIME_PARAM, "3000-01-01TZ")
                 .param(PARAM_TLD, "net"));
     run();
     assertNoTasksEnqueued(DNS_PULL_QUEUE_NAME);