diff --git a/java/google/registry/request/lock/LockHandlerImpl.java b/java/google/registry/request/lock/LockHandlerImpl.java index 6269f6e73..e6a42f62a 100644 --- a/java/google/registry/request/lock/LockHandlerImpl.java +++ b/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), - leaseLength.minus(LOCK_TIMEOUT_FUDGE).getMillis(), - TimeUnit.MILLISECONDS); + 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) { diff --git a/javatests/google/registry/request/lock/LockHandlerImplTest.java b/javatests/google/registry/request/lock/LockHandlerImplTest.java index bd895da69..a8c3c0147 100644 --- a/javatests/google/registry/request/lock/LockHandlerImplTest.java +++ b/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 { int numCalled = 0; @@ -54,19 +57,22 @@ public final class LockHandlerImplTest { private static class ThrowingCallable implements Callable { 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 callable, final @Nullable Lock acquiredLock) { - LockHandler lockHandler = new LockHandlerImpl() { + LockHandlerImpl lockHandler = new LockHandlerImpl() { private static final long serialVersionUID = 0L; @Override Optional 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(); }