Fix timestamp inversion bug (#1144)

* Fix timestamp inversion bug

Set the number of commitLog buckets to 1 in CommitLog replay tests to
expose all timestamp inversion problems due to replay. Fixed
PollAckFlowTest which is related to this problem.

Also fixed a few tests that failed to advance the fake clock when they
should, using the following approaches:

- If DatabaseHelper used but clock is not injected, do it. This
  allows us to remove some unnecessary manual clock advances.
- Manually advance the clock where convenient.
- Enable clock autoIncrement mode when calling production classes that
  performs multiple transactions.

We should consider making 1-bucket the default setting for tests. This
is left to another PR.
This commit is contained in:
Weimin Yu 2021-05-11 14:51:10 -04:00 committed by GitHub
parent 104fc6a5f0
commit b9e8694792
15 changed files with 71 additions and 53 deletions

View file

@ -22,6 +22,7 @@ import google.registry.util.Clock;
import java.util.concurrent.atomic.AtomicLong;
import javax.annotation.concurrent.ThreadSafe;
import org.joda.time.DateTime;
import org.joda.time.Duration;
import org.joda.time.ReadableDuration;
import org.joda.time.ReadableInstant;
@ -81,4 +82,14 @@ public final class FakeClock implements Clock {
public void setTo(ReadableInstant time) {
currentTimeMillis.set(time.getMillis());
}
/** Invokes {@link #setAutoIncrementStep} with one millisecond-step. */
public FakeClock setAutoIncrementByOneMilli() {
return setAutoIncrementStep(Duration.millis(1));
}
/** Disables the auto-increment mode. */
public FakeClock disableAutoIncrement() {
return setAutoIncrementStep(Duration.ZERO);
}
}

View file

@ -16,7 +16,6 @@ package google.registry.batch;
import static com.google.common.truth.Truth.assertThat;
import static google.registry.model.eppcommon.StatusValue.PENDING_DELETE;
import static google.registry.model.ofy.ObjectifyService.ofy;
import static google.registry.model.reporting.HistoryEntry.Type.DOMAIN_CREATE;
import static google.registry.persistence.transaction.TransactionManagerFactory.tm;
import static google.registry.testing.DatabaseHelper.createTld;
@ -81,7 +80,6 @@ class DeleteExpiredDomainsActionTest {
void test_deletesOnlyExpiredDomain() {
// A normal, active autorenewing domain that shouldn't be touched.
DomainBase activeDomain = persistActiveDomain("foo.tld");
clock.advanceOneMilli();
// A non-autorenewing domain that is already pending delete and shouldn't be touched.
DomainBase alreadyDeletedDomain =
@ -91,7 +89,6 @@ class DeleteExpiredDomainsActionTest {
.setAutorenewEndTime(Optional.of(clock.nowUtc().minusDays(10)))
.setDeletionTime(clock.nowUtc().plusDays(17))
.build());
clock.advanceOneMilli();
// A non-autorenewing domain that hasn't reached its expiration time and shouldn't be touched.
DomainBase notYetExpiredDomain =
@ -100,7 +97,6 @@ class DeleteExpiredDomainsActionTest {
.asBuilder()
.setAutorenewEndTime(Optional.of(clock.nowUtc().plusDays(15)))
.build());
clock.advanceOneMilli();
// A non-autorenewing domain that is past its expiration time and should be deleted.
// (This is the only one that needs a full set of subsidiary resources, for the delete flow to
@ -109,6 +105,10 @@ class DeleteExpiredDomainsActionTest {
assertThat(tm().loadByEntity(pendingExpirationDomain).getStatusValues())
.doesNotContain(PENDING_DELETE);
// action.run() does not use any test helper that can advance the fake clock. We manually
// advance the clock to emulate the actual behavior. This works because the action only has
// one transaction.
clock.advanceOneMilli();
action.run();
DomainBase reloadedActiveDomain = tm().loadByEntity(activeDomain);
@ -127,26 +127,11 @@ class DeleteExpiredDomainsActionTest {
DomainBase domain2 = persistNonAutorenewingDomain("veee2.tld");
DomainBase domain3 = persistNonAutorenewingDomain("tarm3.tld");
// action.run() executes an ancestor-less query which is subject to eventual consistency (it
// uses an index that is updated asynchronously). For a deterministic test outcome, we busy
// wait here until all domains above are returned by the query.
for (int attempts = 0; attempts < 3; attempts++) {
ImmutableSet<String> matchingDomains =
ofy()
.load()
.type(DomainBase.class)
.filter("autorenewEndTime <=", clock.nowUtc())
.list()
.stream()
.map(DomainBase::getDomainName)
.collect(ImmutableSet.toImmutableSet());
if (matchingDomains.containsAll(ImmutableSet.of("ecck1.tld", "veee2.tld", "tarm3.tld"))) {
break;
}
Thread.sleep(100);
}
// action.run does multiple write transactions. We cannot emulate the behavior by manually
// advancing the clock. Auto-increment to avoid timestamp inversion.
clock.setAutoIncrementByOneMilli();
action.run();
clock.disableAutoIncrement();
assertThat(tm().loadByEntity(domain1).getStatusValues()).contains(PENDING_DELETE);
assertThat(tm().loadByEntity(domain2).getStatusValues()).contains(PENDING_DELETE);
@ -174,7 +159,6 @@ class DeleteExpiredDomainsActionTest {
.setAutorenewBillingEvent(autorenewBillingEvent.createVKey())
.setAutorenewPollMessage(autorenewPollMessage.createVKey())
.build());
clock.advanceOneMilli();
return pendingExpirationDomain;
}

View file

@ -34,6 +34,7 @@ import google.registry.model.domain.DomainBase;
import google.registry.model.poll.PollMessage;
import google.registry.testing.DualDatabaseTest;
import google.registry.testing.ReplayExtension;
import google.registry.testing.SetClockExtension;
import google.registry.testing.TestOfyAndSql;
import org.joda.time.DateTime;
import org.junit.jupiter.api.BeforeEach;
@ -44,6 +45,10 @@ import org.junit.jupiter.api.extension.RegisterExtension;
@DualDatabaseTest
class PollAckFlowTest extends FlowTestCase<PollAckFlow> {
@Order(value = Order.DEFAULT - 3)
@RegisterExtension
final SetClockExtension setClockExtension = new SetClockExtension(clock, "2011-01-02T01:01:01Z");
@Order(value = Order.DEFAULT - 2)
@RegisterExtension
final ReplayExtension replayExtension = ReplayExtension.createWithCompare(clock);
@ -58,13 +63,9 @@ class PollAckFlowTest extends FlowTestCase<PollAckFlow> {
void setUp() {
setEppInput("poll_ack.xml", ImmutableMap.of("MSGID", "1-3-EXAMPLE-4-3-2011"));
setClientIdForFlow("NewRegistrar");
clock.setTo(DateTime.parse("2011-01-02T01:01:01Z"));
createTld("example");
clock.advanceOneMilli();
contact = persistActiveContact("jd1234");
clock.advanceOneMilli();
domain = persistResource(newDomainBase("test.example", contact));
clock.advanceOneMilli();
}
private void persistOneTimePollMessage(long messageId) {

View file

@ -53,6 +53,7 @@ import google.registry.testing.DatabaseHelper;
import google.registry.testing.DualDatabaseTest;
import google.registry.testing.TestOfyOnly;
import google.registry.testing.TestSqlOnly;
import org.junit.jupiter.api.BeforeEach;
/** Tests for {@link DomainHistory}. */
@DualDatabaseTest
@ -62,6 +63,11 @@ public class DomainHistoryTest extends EntityTestCase {
super(JpaEntityCoverageCheck.ENABLED);
}
@BeforeEach
void beforeEach() {
fakeClock.setAutoIncrementByOneMilli();
}
@TestSqlOnly
void testPersistence() {
DomainBase domain = addGracePeriodForSql(createDomainWithContactsAndHosts());
@ -105,7 +111,6 @@ public class DomainHistoryTest extends EntityTestCase {
tm().insert(host);
tm().insert(contact);
});
fakeClock.advanceOneMilli();
DomainBase domain =
newDomainBase("example.tld", "domainRepoId", contact)
@ -114,7 +119,6 @@ public class DomainHistoryTest extends EntityTestCase {
.build();
tm().transact(() -> tm().insert(domain));
fakeClock.advanceOneMilli();
DomainHistory domainHistory = createDomainHistory(domain);
tm().transact(() -> tm().insert(domainHistory));
@ -164,7 +168,6 @@ public class DomainHistoryTest extends EntityTestCase {
jpaTm().insert(host);
jpaTm().insert(contact);
});
fakeClock.advanceOneMilli();
DomainBase domain =
newDomainBase("example.tld", "domainRepoId", contact)
.asBuilder()
@ -172,7 +175,6 @@ public class DomainHistoryTest extends EntityTestCase {
.build();
tm().transact(() -> tm().insert(domain));
jpaTm().transact(() -> jpaTm().insert(domain));
fakeClock.advanceOneMilli();
DomainHistory domainHistory = createDomainHistory(domain);
tm().transact(() -> tm().insert(domainHistory));

View file

@ -44,6 +44,7 @@ import google.registry.model.registry.Registry.TldState;
import google.registry.model.registry.label.PremiumList;
import google.registry.model.registry.label.PremiumListDualDao;
import google.registry.model.registry.label.ReservedList;
import google.registry.testing.DatabaseHelper;
import google.registry.testing.DualDatabaseTest;
import google.registry.testing.TestOfyAndSql;
import google.registry.testing.TestOfyOnly;
@ -62,6 +63,8 @@ public final class RegistryTest extends EntityTestCase {
@BeforeEach
void beforeEach() {
// Auto-increment fakeClock in DatabaseHelper.
inject.setStaticField(DatabaseHelper.class, "clock", fakeClock);
createTld("tld");
}

View file

@ -29,7 +29,6 @@ import google.registry.model.EntityTestCase;
import google.registry.model.pricing.StaticPremiumListPricingEngine;
import google.registry.model.registry.Registry;
import google.registry.testing.TestCacheExtension;
import org.joda.time.Duration;
import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
@ -49,12 +48,12 @@ public class PremiumListDualDaoTest extends EntityTestCase {
@BeforeEach
void before() {
createTld("tld");
fakeClock.setAutoIncrementStep(Duration.millis(1));
fakeClock.setAutoIncrementByOneMilli();
}
@AfterEach
void after() {
fakeClock.setAutoIncrementStep(Duration.ZERO);
fakeClock.disableAutoIncrement();
}
@Test

View file

@ -32,6 +32,7 @@ public class ReservedListDualDatabaseDaoTest extends EntityTestCase {
@BeforeEach
void setUp() {
fakeClock.setAutoIncrementByOneMilli();
reservations =
ImmutableMap.of(
"food",

View file

@ -36,6 +36,7 @@ import google.registry.model.ofy.Ofy;
import google.registry.model.registry.Registry;
import google.registry.model.registry.label.ReservedList.ReservedListEntry;
import google.registry.testing.AppEngineExtension;
import google.registry.testing.DatabaseHelper;
import google.registry.testing.FakeClock;
import google.registry.testing.InjectExtension;
import org.joda.time.DateTime;
@ -57,6 +58,8 @@ class ReservedListTest {
@BeforeEach
void beforeEach() {
inject.setStaticField(Ofy.class, "clock", clock);
// Auto-increment clock in DatabaseHelper.
inject.setStaticField(DatabaseHelper.class, "clock", clock);
createTld("tld");
reservedListChecks.reset();
reservedListProcessingTime.reset();

View file

@ -76,7 +76,7 @@ public class TransactionManagerTest {
@BeforeEach
void setUp() {
inject.setStaticField(Ofy.class, "clock", fakeClock);
fakeClock.advanceOneMilli();
fakeClock.setAutoIncrementByOneMilli();
}
@TestOfyAndSql
@ -96,6 +96,7 @@ public class TransactionManagerTest {
@TestOfyAndSql
void getTransactionTime_throwsExceptionWhenNotInTransaction() {
assertThrows(IllegalStateException.class, () -> tm().getTransactionTime());
fakeClock.disableAutoIncrement();
tm().transact(() -> assertThat(tm().getTransactionTime()).isEqualTo(fakeClock.nowUtc()));
assertThrows(IllegalStateException.class, () -> tm().getTransactionTime());
}
@ -174,7 +175,6 @@ public class TransactionManagerTest {
TestEntity persisted = tm().transact(() -> tm().loadByKey(theEntity.key()));
assertThat(persisted.data).isEqualTo("foo");
theEntity.data = "bar";
fakeClock.advanceOneMilli();
tm().transact(() -> tm().put(theEntity));
persisted = tm().transact(() -> tm().loadByKey(theEntity.key()));
assertThat(persisted.data).isEqualTo("bar");
@ -197,7 +197,6 @@ public class TransactionManagerTest {
VKey.create(TestEntity.class, theEntity.name, Key.create(theEntity))));
assertThat(persisted.data).isEqualTo("foo");
theEntity.data = "bar";
fakeClock.advanceOneMilli();
tm().transact(() -> tm().update(theEntity));
persisted = tm().transact(() -> tm().loadByKey(theEntity.key()));
assertThat(persisted.data).isEqualTo("bar");
@ -238,7 +237,6 @@ public class TransactionManagerTest {
void delete_succeeds() {
tm().transact(() -> tm().insert(theEntity));
assertEntityExists(theEntity);
fakeClock.advanceOneMilli();
tm().transact(() -> tm().delete(theEntity.key()));
assertEntityNotExist(theEntity);
}
@ -257,7 +255,6 @@ public class TransactionManagerTest {
Set<VKey<TestEntity>> keys =
moreEntities.stream().map(TestEntity::key).collect(toImmutableSet());
assertAllEntitiesExist(moreEntities);
fakeClock.advanceOneMilli();
tm().transact(() -> tm().delete(keys));
assertAllEntitiesNotExist(moreEntities);
}
@ -269,10 +266,8 @@ public class TransactionManagerTest {
List<VKey<TestEntity>> keys =
moreEntities.stream().map(TestEntity::key).collect(toImmutableList());
assertAllEntitiesExist(moreEntities);
fakeClock.advanceOneMilli();
tm().transact(() -> tm().delete(keys.get(0)));
assertEntityNotExist(moreEntities.get(0));
fakeClock.advanceOneMilli();
tm().transact(() -> tm().delete(keys));
assertAllEntitiesNotExist(moreEntities);
}
@ -281,7 +276,6 @@ public class TransactionManagerTest {
void delete_deletesTheGivenEntity() {
tm().transact(() -> tm().insert(theEntity));
assertEntityExists(theEntity);
fakeClock.advanceOneMilli();
tm().transact(() -> tm().delete(theEntity));
assertEntityNotExist(theEntity);
}

View file

@ -86,7 +86,7 @@ public class PendingDepositCheckerTest {
void testMethod_firstDepositOnBrdaDay_depositsBothRdeAndBrda() {
clock.setTo(DateTime.parse("2000-01-04T08:00Z")); // Tuesday
createTldWithEscrowEnabled("lol");
clock.advanceOneMilli();
clock.setAutoIncrementByOneMilli();
assertThat(checker.getTldsAndWatermarksPendingDepositForRdeAndBrda()).isEqualTo(
ImmutableSetMultimap.of(
"lol", PendingDeposit.create(
@ -153,7 +153,7 @@ public class PendingDepositCheckerTest {
createTldWithEscrowEnabled("pal");
clock.advanceOneMilli();
createTldWithEscrowEnabled("fun");
clock.advanceOneMilli();
clock.setAutoIncrementByOneMilli();
assertThat(checker.getTldsAndWatermarksPendingDepositForRdeAndBrda())
.isEqualTo(
ImmutableSetMultimap.of(

View file

@ -592,7 +592,9 @@ public class RdeStagingActionTest extends MapreduceTestCase<RdeStagingAction> {
makeDomainBase(clock, "lol");
clock.setTo(DateTime.parse("2000-01-01TZ"));
clock.setAutoIncrementByOneMilli();
action.run();
clock.disableAutoIncrement();
executeTasksUntilEmpty("mapreduce", clock);
String boggleDeposit = readXml("boggle_2000-01-01_full_S1_R0.xml.ghostryde");
@ -613,7 +615,9 @@ public class RdeStagingActionTest extends MapreduceTestCase<RdeStagingAction> {
makeHostResource(clock, "ns1.kuss.lol", "face::feed");
clock.setTo(DateTime.parse("2000-01-01TZ"));
clock.setAutoIncrementByOneMilli();
action.run();
clock.disableAutoIncrement();
executeTasksUntilEmpty("mapreduce", clock);
String fopDeposit = readXml("fop_2000-01-01_full_S1_R0.xml.ghostryde");

View file

@ -18,10 +18,12 @@ import static com.google.common.truth.Truth.assertThat;
import static google.registry.model.ImmutableObjectSubject.assertAboutImmutableObjects;
import static google.registry.persistence.transaction.TransactionManagerFactory.jpaTm;
import com.google.common.base.Suppliers;
import com.google.common.collect.ImmutableMap;
import com.google.common.collect.ImmutableSet;
import com.googlecode.objectify.Key;
import google.registry.model.ImmutableObject;
import google.registry.model.ofy.CommitLogBucket;
import google.registry.model.ofy.ReplayQueue;
import google.registry.model.ofy.TransactionInfo;
import google.registry.persistence.VKey;
@ -46,6 +48,7 @@ public class ReplayExtension implements BeforeEachCallback, AfterEachCallback {
FakeClock clock;
boolean compare;
InjectExtension injectExtension = new InjectExtension();
private ReplayExtension(FakeClock clock, boolean compare) {
this.clock = clock;
@ -62,6 +65,12 @@ public class ReplayExtension implements BeforeEachCallback, AfterEachCallback {
@Override
public void beforeEach(ExtensionContext context) {
// Use a single bucket to expose timestamp inversion problems. This typically happens when
// a test with this extension rolls back the fake clock in the setup method, creating inverted
// timestamp with the canned data preloaded by AppengineExtension. The solution is to move
// the clock change to the test's constructor.
injectExtension.setStaticField(
CommitLogBucket.class, "bucketIdSupplier", Suppliers.ofInstance(1));
DatabaseHelper.setClock(clock);
DatabaseHelper.setAlwaysSaveWithBackup(true);
ReplayQueue.clear();
@ -74,6 +83,7 @@ public class ReplayExtension implements BeforeEachCallback, AfterEachCallback {
// should be safe to call replayToSql() twice, as the replay queue should be empty the second
// time.
replayToSql();
injectExtension.afterEach(context);
}
private static ImmutableSet<String> NON_REPLICATED_TYPES =

View file

@ -27,10 +27,11 @@ import google.registry.model.common.DatabaseTransitionSchedule.PrimaryDatabaseTr
import google.registry.model.common.DatabaseTransitionSchedule.TransitionId;
import google.registry.model.common.TimedTransitionProperty;
import google.registry.model.ofy.Ofy;
import google.registry.testing.FakeClock;
import google.registry.testing.InjectExtension;
import google.registry.testing.SetClockExtension;
import org.joda.time.DateTime;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Order;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.extension.RegisterExtension;
@ -38,12 +39,16 @@ import org.junit.jupiter.api.extension.RegisterExtension;
public class GetDatabaseTransitionScheduleCommandTest
extends CommandTestCase<GetDatabaseTransitionScheduleCommand> {
@Order(value = Order.DEFAULT - 3)
@RegisterExtension
final SetClockExtension setClockExtension =
new SetClockExtension(fakeClock, "1984-12-21T06:07:08.789Z");
@RegisterExtension public final InjectExtension inject = new InjectExtension();
@BeforeEach
void beforeEach() {
inject.setStaticField(
Ofy.class, "clock", new FakeClock(DateTime.parse("1984-12-21T06:07:08.789Z")));
inject.setStaticField(Ofy.class, "clock", fakeClock);
}
@Test
@ -64,7 +69,6 @@ public class GetDatabaseTransitionScheduleCommandTest
@Test
void testSuccess_multipleArguments() throws Exception {
fakeClock.setTo(DateTime.parse("2020-10-01T00:00:00Z"));
TimedTransitionProperty<PrimaryDatabase, PrimaryDatabaseTransition> databaseTransitions =
TimedTransitionProperty.fromValueMap(
ImmutableSortedMap.of(START_OF_TIME, PrimaryDatabase.DATASTORE),
@ -72,12 +76,13 @@ public class GetDatabaseTransitionScheduleCommandTest
DatabaseTransitionSchedule schedule =
DatabaseTransitionSchedule.create(TransitionId.DOMAIN_LABEL_LISTS, databaseTransitions);
ofyTm().transactNew(() -> ofyTm().put(schedule));
fakeClock.advanceOneMilli(); // Now 1984-12-21T06:07:08.790Z
TimedTransitionProperty<PrimaryDatabase, PrimaryDatabaseTransition> databaseTransitions2 =
TimedTransitionProperty.fromValueMap(
ImmutableSortedMap.of(
START_OF_TIME,
PrimaryDatabase.DATASTORE,
fakeClock.nowUtc(),
DateTime.parse("2020-10-01T00:00:00Z"),
PrimaryDatabase.CLOUD_SQL),
PrimaryDatabaseTransition.class);
DatabaseTransitionSchedule schedule2 =
@ -88,7 +93,7 @@ public class GetDatabaseTransitionScheduleCommandTest
assertStdoutIs(
"DOMAIN_LABEL_LISTS(last updated at 1984-12-21T06:07:08.789Z):"
+ " {1970-01-01T00:00:00.000Z=DATASTORE}\n"
+ "SIGNED_MARK_REVOCATION_LIST(last updated at 1984-12-21T06:07:08.789Z):"
+ "SIGNED_MARK_REVOCATION_LIST(last updated at 1984-12-21T06:07:08.790Z):"
+ " {1970-01-01T00:00:00.000Z=DATASTORE, 2020-10-01T00:00:00.000Z=CLOUD_SQL}\n");
}

View file

@ -85,9 +85,9 @@ public class UnrenewDomainCommandTest extends CommandTestCase<UnrenewDomainComma
fakeClock.nowUtc(),
fakeClock.nowUtc(),
fakeClock.nowUtc().plusYears(4));
fakeClock.advanceOneMilli();
fakeClock.setAutoIncrementByOneMilli();
runCommandForced("-p", "2", "foo.tld", "bar.tld");
fakeClock.advanceOneMilli();
fakeClock.disableAutoIncrement();
assertThat(
loadByForeignKey(DomainBase.class, "foo.tld", fakeClock.nowUtc())
.get()

View file

@ -213,6 +213,7 @@ class ContactSettingsTest extends RegistrarSettingsActionTestCase {
AppEngineExtension.makeRegistrarContact1().toJsonMap(),
newContactMap,
AppEngineExtension.makeRegistrarContact3().toJsonMap()));
clock.advanceOneMilli();
Map<String, Object> response =
action.handleJsonRequest(ImmutableMap.of("op", "update", "id", CLIENT_ID, "args", reqJson));
assertThat(response).containsAtLeastEntriesIn(ImmutableMap.of("status", "SUCCESS"));