Add lock dual read (#517)

* Add lock dual read

* small changes

core/src/main/java/google/registry/model/server/Lock.java

@@ -78,6 +78,18 @@ public class Lock extends ImmutableObject implements Serializable {
   /** When the lock can be considered implicitly released. */
   DateTime expirationTime;
 
+  public String getRequestLogId() {
+    return requestLogId;
+  }
+
+  public DateTime getExpirationTime() {
+    return expirationTime;
+  }
+
+  public DateTime getAcquiredTime() {
+    return acquiredTime;
+  }
+
   /** When was the lock acquired. Used for logging. */
   DateTime acquiredTime;
 
@@ -89,10 +101,10 @@ public class Lock extends ImmutableObject implements Serializable {
   String tld;
 
   /**
-   * Create a new {@link Lock} for the given resource name in the specified tld (which can be
-   * null for cross-tld locks).
+   * Create a new {@link Lock} for the given resource name in the specified tld (which can be null
+   * for cross-tld locks).
    */
-  private static Lock create(
+  public static Lock create(
       String resourceName,
       @Nullable String tld,
       String requestLogId,
@@ -185,6 +197,18 @@ public class Lock extends ImmutableObject implements Serializable {
 
                   // Checking if an unexpired lock still exists - if so, the lock can't be acquired.
                   Lock lock = ofy().load().type(Lock.class).id(lockId).now();
+                  try {
+                    jpaTm()
+                        .transact(
+                            () -> {
+                              Optional<google.registry.schema.server.Lock> cloudSqlLockOptional =
+                                  LockDao.load(resourceName, tld);
+                              LockDao.compare(Optional.ofNullable(lock), cloudSqlLockOptional);
+                            });
+                  } catch (Exception e) {
+                    logger.atSevere().withCause(e).log(
+                        "Issue loading and comparing lock from Cloud SQL");
+                  }
                   if (lock != null) {
                     logger.atInfo().log(
                         "Loaded existing lock: %s for request: %s", lock.lockId, lock.requestLogId);
@@ -221,12 +245,7 @@ public class Lock extends ImmutableObject implements Serializable {
                                       requestStatusChecker.getLogId(),
                                       now,
                                       leaseLength);
-                              // cloudSqlLock should not already exist in Cloud SQL, but call delete
-                              // just in case
-                              // TODO: Remove this delete once dual read is added
-                              LockDao.delete(
-                                  resourceName, Optional.ofNullable(tld).orElse("GLOBAL"));
-                              LockDao.saveNew(cloudSqlLock);
+                              LockDao.save(cloudSqlLock);
                             });
                   } catch (Exception e) {
                     logger.atSevere().withCause(e).log(
@@ -251,6 +270,18 @@ public class Lock extends ImmutableObject implements Serializable {
               // this can happen if release() is called around the expiration time and the lock
               // expires underneath us.
               Lock loadedLock = ofy().load().type(Lock.class).id(lockId).now();
+              try {
+                jpaTm()
+                    .transact(
+                        () -> {
+                          Optional<google.registry.schema.server.Lock> cloudSqlLockOptional =
+                              LockDao.load(resourceName, tld);
+                          LockDao.compare(Optional.ofNullable(loadedLock), cloudSqlLockOptional);
+                        });
+              } catch (Exception e) {
+                logger.atSevere().withCause(e).log(
+                    "Issue loading and comparing lock from Cloud SQL");
+              }
               if (Lock.this.equals(loadedLock)) {
                 // Use noBackupOfy() so that we don't create a commit log entry for deleting the
                 // lock.

core/src/main/java/google/registry/schema/server/LockDao.java

@@ -18,18 +18,22 @@ import static google.registry.persistence.transaction.TransactionManagerFactory.
 import static google.registry.schema.server.Lock.GLOBAL;
 import static google.registry.util.PreconditionsUtils.checkArgumentNotNull;
 
+import com.google.common.flogger.FluentLogger;
 import google.registry.schema.server.Lock.LockId;
+import google.registry.util.DateTimeUtils;
 import java.util.Optional;
 
 /** Data access object class for {@link Lock}. */
 public class LockDao {
 
+  private static final FluentLogger logger = FluentLogger.forEnclosingClass();
+
   /** Saves the {@link Lock} object to Cloud SQL. */
-  public static void saveNew(Lock lock) {
+  public static void save(Lock lock) {
     jpaTm()
         .transact(
             () -> {
-              jpaTm().getEntityManager().persist(lock);
+              jpaTm().getEntityManager().merge(lock);
             });
   }
 
@@ -76,4 +80,57 @@ public class LockDao {
   public static void delete(String resourceName) {
     delete(resourceName, GLOBAL);
   }
+
+  /**
+   * Compares a {@link google.registry.model.server.Lock} object with a {@link Lock} object, logging
+   * a warning if there are any differences.
+   */
+  public static void compare(
+      Optional<google.registry.model.server.Lock> datastoreLockOptional,
+      Optional<Lock> cloudSqlLockOptional) {
+    if (!datastoreLockOptional.isPresent()) {
+      cloudSqlLockOptional.ifPresent(
+          value ->
+              logger.atWarning().log(
+                  String.format(
+                      "Cloud SQL lock for %s with tld %s should be null",
+                      value.resourceName, value.tld)));
+      return;
+    }
+    google.registry.schema.server.Lock cloudSqlLock;
+    google.registry.model.server.Lock datastoreLock = datastoreLockOptional.get();
+    if (cloudSqlLockOptional.isPresent()) {
+      cloudSqlLock = cloudSqlLockOptional.get();
+      if (!datastoreLock.getRequestLogId().equals(cloudSqlLock.requestLogId)) {
+        logger.atWarning().log(
+            String.format(
+                "Datastore lock requestLogId of %s does not equal Cloud SQL lock requestLogId of"
+                    + " %s",
+                datastoreLock.getRequestLogId(), cloudSqlLock.requestLogId));
+      }
+      if (!datastoreLock
+          .getAcquiredTime()
+          .equals(DateTimeUtils.toJodaDateTime(cloudSqlLock.acquiredTime))) {
+        logger.atWarning().log(
+            String.format(
+                "Datastore lock acquiredTime of %s does not equal Cloud SQL lock acquiredTime of"
+                    + " %s",
+                datastoreLock.getAcquiredTime(),
+                DateTimeUtils.toJodaDateTime(cloudSqlLock.acquiredTime)));
+      }
+      if (!datastoreLock
+          .getExpirationTime()
+          .equals(DateTimeUtils.toJodaDateTime(cloudSqlLock.expirationTime))) {
+        logger.atWarning().log(
+            String.format(
+                "Datastore lock expirationTime of %s does not equal Cloud SQL lock expirationTime"
+                    + " of %s",
+                datastoreLock.getExpirationTime(),
+                DateTimeUtils.toJodaDateTime(cloudSqlLock.expirationTime)));
+      }
+    } else {
+      logger.atWarning().log(
+          String.format("Datastore lock: %s was not found in Cloud SQL", datastoreLock));
+    }
+  }
 }

core/src/test/java/google/registry/schema/server/LockDaoTest.java

@@ -15,13 +15,15 @@
 package google.registry.schema.server;
 
 import static com.google.common.truth.Truth.assertThat;
-import static org.junit.Assert.assertThrows;
+import static google.registry.testing.LogsSubject.assertAboutLogs;
 
+import com.google.common.testing.TestLogHandler;
 import google.registry.persistence.transaction.JpaTestRules;
 import google.registry.persistence.transaction.JpaTestRules.JpaIntegrationWithCoverageRule;
 import google.registry.testing.FakeClock;
 import java.util.Optional;
-import javax.persistence.RollbackException;
+import java.util.logging.Level;
+import java.util.logging.Logger;
 import org.joda.time.Duration;
 import org.junit.Rule;
 import org.junit.Test;
@@ -33,6 +35,8 @@ import org.junit.runners.JUnit4;
 public class LockDaoTest {
 
   private final FakeClock fakeClock = new FakeClock();
+  private final TestLogHandler logHandler = new TestLogHandler();
+  private final Logger loggerToIntercept = Logger.getLogger(LockDao.class.getCanonicalName());
 
   @Rule
   public final JpaIntegrationWithCoverageRule jpaRule =
@@ -42,29 +46,28 @@ public class LockDaoTest {
   public void save_worksSuccessfully() {
     Lock lock =
         Lock.create("testResource", "tld", "testLogId", fakeClock.nowUtc(), Duration.millis(2));
-    LockDao.saveNew(lock);
+    LockDao.save(lock);
     Optional<Lock> returnedLock = LockDao.load("testResource", "tld");
     assertThat(returnedLock.get().expirationTime).isEqualTo(lock.expirationTime);
     assertThat(returnedLock.get().requestLogId).isEqualTo(lock.requestLogId);
   }
 
   @Test
-  public void save_failsWhenLockAlreadyExists() {
+  public void save_succeedsWhenLockAlreadyExists() {
     Lock lock =
         Lock.create("testResource", "tld", "testLogId", fakeClock.nowUtc(), Duration.millis(2));
-    LockDao.saveNew(lock);
+    LockDao.save(lock);
     Lock lock2 =
         Lock.create("testResource", "tld", "testLogId2", fakeClock.nowUtc(), Duration.millis(4));
-    RollbackException thrown = assertThrows(RollbackException.class, () -> LockDao.saveNew(lock2));
-    assertThat(thrown.getCause().getCause().getCause().getMessage())
-        .contains("duplicate key value violates unique constraint");
+    LockDao.save(lock2);
+    assertThat(LockDao.load("testResource", "tld").get().requestLogId).isEqualTo("testLogId2");
   }
 
   @Test
   public void save_worksSuccesfullyGlobalLock() {
     Lock lock =
         Lock.createGlobal("testResource", "testLogId", fakeClock.nowUtc(), Duration.millis(2));
-    LockDao.saveNew(lock);
+    LockDao.save(lock);
     Optional<Lock> returnedLock = LockDao.load("testResource");
     assertThat(returnedLock.get().expirationTime).isEqualTo(lock.expirationTime);
     assertThat(returnedLock.get().requestLogId).isEqualTo(lock.requestLogId);
@@ -74,7 +77,7 @@ public class LockDaoTest {
   public void load_worksSuccessfully() {
     Lock lock =
         Lock.create("testResource", "tld", "testLogId", fakeClock.nowUtc(), Duration.millis(2));
-    LockDao.saveNew(lock);
+    LockDao.save(lock);
     Optional<Lock> returnedLock = LockDao.load("testResource", "tld");
     assertThat(returnedLock.get().expirationTime).isEqualTo(lock.expirationTime);
     assertThat(returnedLock.get().requestLogId).isEqualTo(lock.requestLogId);
@@ -84,7 +87,7 @@ public class LockDaoTest {
   public void load_worksSuccessfullyGlobalLock() {
     Lock lock =
         Lock.createGlobal("testResource", "testLogId", fakeClock.nowUtc(), Duration.millis(2));
-    LockDao.saveNew(lock);
+    LockDao.save(lock);
     Optional<Lock> returnedLock = LockDao.load("testResource");
     assertThat(returnedLock.get().expirationTime).isEqualTo(lock.expirationTime);
     assertThat(returnedLock.get().requestLogId).isEqualTo(lock.requestLogId);
@@ -100,7 +103,7 @@ public class LockDaoTest {
   public void delete_worksSuccesfully() {
     Lock lock =
         Lock.create("testResource", "tld", "testLogId", fakeClock.nowUtc(), Duration.millis(2));
-    LockDao.saveNew(lock);
+    LockDao.save(lock);
     Optional<Lock> returnedLock = LockDao.load("testResource", "tld");
     assertThat(returnedLock.get().expirationTime).isEqualTo(lock.expirationTime);
     LockDao.delete("testResource", "tld");
@@ -112,7 +115,7 @@ public class LockDaoTest {
   public void delete_worksSuccessfullyGlobalLock() {
     Lock lock =
         Lock.createGlobal("testResource", "testLogId", fakeClock.nowUtc(), Duration.millis(2));
-    LockDao.saveNew(lock);
+    LockDao.save(lock);
     Optional<Lock> returnedLock = LockDao.load("testResource");
     assertThat(returnedLock.get().expirationTime).isEqualTo(lock.expirationTime);
     LockDao.delete("testResource");
@@ -124,4 +127,63 @@ public class LockDaoTest {
   public void delete_succeedsLockDoesntExist() {
     LockDao.delete("testResource");
   }
+
+  @Test
+  public void compare_logsWarningWhenCloudSqlLockMissing() {
+    loggerToIntercept.addHandler(logHandler);
+    google.registry.model.server.Lock datastoreLock =
+        google.registry.model.server.Lock.create(
+            "resourceName", "tld", "id", fakeClock.nowUtc(), Duration.millis(2));
+    LockDao.compare(Optional.of(datastoreLock), Optional.empty());
+    assertAboutLogs()
+        .that(logHandler)
+        .hasLogAtLevelWithMessage(
+            Level.WARNING,
+            String.format("Datastore lock: %s was not found in Cloud SQL", datastoreLock));
+  }
+
+  @Test
+  public void compare_logsWarningWhenCloudSqlLockExistsWhenItShouldNot() {
+    loggerToIntercept.addHandler(logHandler);
+    Lock lock =
+        Lock.createGlobal("testResource", "testLogId", fakeClock.nowUtc(), Duration.millis(2));
+    LockDao.compare(Optional.ofNullable(null), Optional.of(lock));
+    assertAboutLogs()
+        .that(logHandler)
+        .hasLogAtLevelWithMessage(
+            Level.WARNING,
+            String.format("Cloud SQL lock for testResource with tld GLOBAL should be null"));
+  }
+
+  @Test
+  public void compare_logsWarningWhenLocksDontMatch() {
+    loggerToIntercept.addHandler(logHandler);
+    Lock cloudSqlLock =
+        Lock.create("testResource", "tld", "testLogId", fakeClock.nowUtc(), Duration.millis(2));
+    google.registry.model.server.Lock datastoreLock =
+        google.registry.model.server.Lock.create(
+            "testResource", "tld", "wrong", fakeClock.nowUtc().minusDays(1), Duration.millis(3));
+    LockDao.compare(Optional.of(datastoreLock), Optional.of(cloudSqlLock));
+    assertAboutLogs()
+        .that(logHandler)
+        .hasLogAtLevelWithMessage(
+            Level.WARNING,
+            String.format(
+                "Datastore lock requestLogId of wrong does not equal Cloud SQL lock requestLogId"
+                    + " of testLogId"));
+    assertAboutLogs()
+        .that(logHandler)
+        .hasLogAtLevelWithMessage(
+            Level.WARNING,
+            String.format(
+                "Datastore lock acquiredTime of 1969-12-31T00:00:00.000Z does not equal Cloud SQL"
+                    + " lock acquiredTime of 1970-01-01T00:00:00.000Z"));
+    assertAboutLogs()
+        .that(logHandler)
+        .hasLogAtLevelWithMessage(
+            Level.WARNING,
+            String.format(
+                "Datastore lock expirationTime of 1969-12-31T00:00:00.003Z does not equal Cloud"
+                    + " SQL lock expirationTime of 1970-01-01T00:00:00.002Z"));
+  }
 }