Handle timeouts better in lock handler

Rather than just logging a generic TimeoutException, this will say what action
timed out and how long it had been executing for.

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

java/google/registry/request/lock/LockHandlerImpl.java

@@ -18,12 +18,14 @@ import static com.google.common.base.Preconditions.checkArgument;
 import static com.google.common.base.Throwables.throwIfUnchecked;
 
 import com.google.common.annotations.VisibleForTesting;
+import com.google.common.base.Joiner;
 import com.google.common.base.Strings;
 import com.google.common.collect.ImmutableSortedSet;
 import com.google.common.flogger.FluentLogger;
 import com.google.common.util.concurrent.UncheckedExecutionException;
 import google.registry.model.server.Lock;
 import google.registry.util.AppEngineTimeLimiter;
+import google.registry.util.Clock;
 import google.registry.util.RequestStatusChecker;
 import java.util.HashSet;
 import java.util.Optional;
@@ -31,8 +33,10 @@ import java.util.Set;
 import java.util.concurrent.Callable;
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.TimeUnit;
+import java.util.concurrent.TimeoutException;
 import javax.annotation.Nullable;
 import javax.inject.Inject;
+import org.joda.time.DateTime;
 import org.joda.time.Duration;
 
 /** Implementation of {@link LockHandler} that uses the datastore lock. */
@@ -45,6 +49,7 @@ public class LockHandlerImpl implements LockHandler {
   /** Fudge factor to make sure we kill threads before a lock actually expires. */
   private static final Duration LOCK_TIMEOUT_FUDGE = Duration.standardSeconds(5);
 
+  @Inject Clock clock;
   @Inject RequestStatusChecker requestStatusChecker;
 
   @Inject public LockHandlerImpl() {}
@@ -65,14 +70,27 @@ public class LockHandlerImpl implements LockHandler {
       @Nullable String tld,
       Duration leaseLength,
       String... lockNames) {
+    DateTime startTime = clock.nowUtc();
+    String sanitizedTld = Strings.emptyToNull(tld);
     try {
-      return AppEngineTimeLimiter.create().callWithTimeout(
-          new LockingCallable(callable, Strings.emptyToNull(tld), leaseLength, lockNames),
+      return AppEngineTimeLimiter.create()
+          .callWithTimeout(
+              new LockingCallable(callable, sanitizedTld, leaseLength, lockNames),
               leaseLength.minus(LOCK_TIMEOUT_FUDGE).getMillis(),
               TimeUnit.MILLISECONDS);
     } catch (ExecutionException | UncheckedExecutionException e) {
       // Unwrap the execution exception and throw its root cause.
       Throwable cause = e.getCause();
+      if (cause instanceof TimeoutException) {
+        throw new RuntimeException(
+            String.format(
+                "Execution on locks '%s' for TLD '%s' timed out after %s; started at %s",
+                Joiner.on(", ").join(lockNames),
+                Optional.ofNullable(sanitizedTld).orElse("(null)"),
+                new Duration(startTime, clock.nowUtc()),
+                startTime),
+            cause);
+      }
       throwIfUnchecked(cause);
       throw new RuntimeException(cause);
     } catch (Exception e) {

javatests/google/registry/request/lock/LockHandlerImplTest.java

@@ -22,9 +22,12 @@ import static org.mockito.Mockito.verify;
 
 import google.registry.model.server.Lock;
 import google.registry.testing.AppEngineRule;
+import google.registry.testing.FakeClock;
 import java.util.Optional;
 import java.util.concurrent.Callable;
+import java.util.concurrent.TimeoutException;
 import javax.annotation.Nullable;
+import org.joda.time.DateTime;
 import org.joda.time.Duration;
 import org.junit.Before;
 import org.junit.Rule;
@@ -38,9 +41,9 @@ public final class LockHandlerImplTest {
 
   private static final Duration ONE_DAY = Duration.standardDays(1);
 
-  @Rule
-  public final AppEngineRule appEngine = AppEngineRule.builder()
-      .build();
+  private final FakeClock clock = new FakeClock(DateTime.parse("2001-08-29T12:20:00Z"));
+
+  @Rule public final AppEngineRule appEngine = AppEngineRule.builder().build();
 
   private static class CountingCallable implements Callable<Void> {
     int numCalled = 0;
@@ -54,19 +57,22 @@ public final class LockHandlerImplTest {
 
   private static class ThrowingCallable implements Callable<Void> {
     Exception exception;
+    FakeClock clock;
 
-    ThrowingCallable(Exception exception) {
+    ThrowingCallable(Exception exception, FakeClock clock) {
       this.exception = exception;
+      this.clock = clock;
     }
 
     @Override
     public Void call() throws Exception {
+      clock.advanceBy(Duration.standardSeconds(77));
       throw exception;
     }
   }
 
   private boolean executeWithLocks(Callable<Void> callable, final @Nullable Lock acquiredLock) {
-    LockHandler lockHandler = new LockHandlerImpl() {
+    LockHandlerImpl lockHandler = new LockHandlerImpl() {
       private static final long serialVersionUID = 0L;
       @Override
       Optional<Lock> acquire(String resourceName, String tld, Duration leaseLength) {
@@ -76,6 +82,7 @@ public final class LockHandlerImplTest {
         return Optional.ofNullable(acquiredLock);
       }
     };
+    lockHandler.clock = clock;
 
     return lockHandler.executeWithLocks(callable, "tld", ONE_DAY, "resourceName");
   }
@@ -99,11 +106,28 @@ public final class LockHandlerImplTest {
     RuntimeException exception =
         assertThrows(
             RuntimeException.class,
-            () -> executeWithLocks(new ThrowingCallable(expectedException), lock));
+            () -> executeWithLocks(new ThrowingCallable(expectedException, clock), lock));
     assertThat(exception).isSameAs(expectedException);
     verify(lock, times(1)).release();
   }
 
+  @Test
+  public void testLockSucceeds_timeoutException() {
+    Lock lock = mock(Lock.class);
+    Exception expectedException = new TimeoutException("test");
+    RuntimeException thrown =
+        assertThrows(
+            RuntimeException.class,
+            () -> executeWithLocks(new ThrowingCallable(expectedException, clock), lock));
+    assertThat(thrown).hasCauseThat().isSameAs(expectedException);
+    assertThat(thrown)
+        .hasMessageThat()
+        .isEqualTo(
+            "Execution on locks 'resourceName' for TLD 'tld'"
+                + " timed out after PT77S; started at 2001-08-29T12:20:00.000Z");
+    verify(lock, times(1)).release();
+  }
+
   @Test
   public void testLockSucceeds_checkedException() throws Exception {
     Lock lock = mock(Lock.class);
@@ -111,7 +135,7 @@ public final class LockHandlerImplTest {
     RuntimeException exception =
         assertThrows(
             RuntimeException.class,
-            () -> executeWithLocks(new ThrowingCallable(expectedException), lock));
+            () -> executeWithLocks(new ThrowingCallable(expectedException, clock), lock));
     assertThat(exception).hasCauseThat().isSameAs(expectedException);
     verify(lock, times(1)).release();
   }