From 34f5e532b5b2d230f99709a0adcaf16fa12f78e4 Mon Sep 17 00:00:00 2001 From: Michael Muller Date: Mon, 11 Oct 2021 12:54:03 -0400 Subject: [PATCH] Implement several fixes affecting test flakiness (#1379) * Implement several fixes affecting test flakiness - Continued to do transaction manager cleanups on reply failure (lack of this may be causing cascading failures. - Fix UpdateDomainCommandTest's output check (the test was checking for error output in standard error, but the command writes its output to the logs. Apparently, these may or may not be reflected in standard error depending on current global state) - Remove unnecessary locking and incorrect comment in CommandTestCase. The JUnit tests are not run in parallel in the same JVM and, in general, there are much bigger obstacles to this than standard output stream locking. * Fix bad log message check --- .../registry/testing/AppEngineExtension.java | 28 ++++++++++--------- .../registry/testing/TestLogHandlerUtils.java | 9 ++++++ .../registry/tools/CommandTestCase.java | 11 +------- .../tools/UpdateDomainCommandTest.java | 22 ++++++++++++--- 4 files changed, 43 insertions(+), 27 deletions(-) diff --git a/core/src/test/java/google/registry/testing/AppEngineExtension.java b/core/src/test/java/google/registry/testing/AppEngineExtension.java index aceeb0400..b86d16405 100644 --- a/core/src/test/java/google/registry/testing/AppEngineExtension.java +++ b/core/src/test/java/google/registry/testing/AppEngineExtension.java @@ -487,20 +487,22 @@ public final class AppEngineExtension implements BeforeEachCallback, AfterEachCa if (replayer != null) { replayer.replay(); } - - if (withCloudSql) { - if (enableJpaEntityCoverageCheck) { - jpaIntegrationWithCoverageExtension.afterEach(context); - } else if (withJpaUnitTest) { - jpaUnitTestExtension.afterEach(context); - } else { - jpaIntegrationTestExtension.afterEach(context); - } - } - tearDown(); } finally { - if (isWithDatastoreAndCloudSql()) { - restoreTmAfterDualDatabaseTest(context); + try { + if (withCloudSql) { + if (enableJpaEntityCoverageCheck) { + jpaIntegrationWithCoverageExtension.afterEach(context); + } else if (withJpaUnitTest) { + jpaUnitTestExtension.afterEach(context); + } else { + jpaIntegrationTestExtension.afterEach(context); + } + } + tearDown(); + } finally { + if (isWithDatastoreAndCloudSql()) { + restoreTmAfterDualDatabaseTest(context); + } } } } diff --git a/core/src/test/java/google/registry/testing/TestLogHandlerUtils.java b/core/src/test/java/google/registry/testing/TestLogHandlerUtils.java index 9e541b6b2..fc384cac1 100644 --- a/core/src/test/java/google/registry/testing/TestLogHandlerUtils.java +++ b/core/src/test/java/google/registry/testing/TestLogHandlerUtils.java @@ -43,6 +43,15 @@ public final class TestLogHandlerUtils { handler.getStoredLogRecords(), logRecord -> logRecord.getMessage().startsWith(prefix)); } + /** Assert that the specified log message is not found. */ + public static void assertNoLogMessage(CapturingLogHandler handler, Level level, String message) { + for (LogRecord logRecord : handler.getRecords()) { + if (logRecord.getLevel().equals(level) && logRecord.getMessage().contains(message)) { + assertWithMessage("Log message \"%s\" found: %s", message, logRecord.getMessage()).fail(); + } + } + } + public static void assertLogMessage(CapturingLogHandler handler, Level level, String message) { for (LogRecord logRecord : handler.getRecords()) { if (logRecord.getLevel().equals(level) && logRecord.getMessage().contains(message)) { diff --git a/core/src/test/java/google/registry/tools/CommandTestCase.java b/core/src/test/java/google/registry/tools/CommandTestCase.java index 556af5f60..5f404119f 100644 --- a/core/src/test/java/google/registry/tools/CommandTestCase.java +++ b/core/src/test/java/google/registry/tools/CommandTestCase.java @@ -42,7 +42,6 @@ import java.io.OutputStream; import java.io.PrintStream; import java.nio.file.Path; import java.util.List; -import java.util.concurrent.locks.ReentrantLock; import org.joda.time.DateTime; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; @@ -59,10 +58,6 @@ import org.mockito.junit.jupiter.MockitoExtension; @ExtendWith(MockitoExtension.class) public abstract class CommandTestCase { - // Lock for stdout/stderr. Note that this is static: since we're dealing with globals, we need - // to lock for the entire JVM. - private static final ReentrantLock streamsLock = new ReentrantLock(); - private final ByteArrayOutputStream stdout = new ByteArrayOutputStream(); private final ByteArrayOutputStream stderr = new ByteArrayOutputStream(); private PrintStream oldStdout, oldStderr; @@ -90,10 +85,7 @@ public abstract class CommandTestCase { RegistryToolEnvironment.UNITTEST.setup(systemPropertyExtension); command = newCommandInstance(); - // Capture standard output/error. This is problematic because gradle tests run in parallel in - // the same JVM. So first lock out any other tests in this JVM that are trying to do this - // trick. - streamsLock.lock(); + // Capture standard output/error. oldStdout = System.out; System.setOut(new PrintStream(new OutputSplitter(System.out, stdout))); oldStderr = System.err; @@ -104,7 +96,6 @@ public abstract class CommandTestCase { public final void afterEachCommandTestCase() { System.setOut(oldStdout); System.setErr(oldStderr); - streamsLock.unlock(); } void runCommandInEnvironment(RegistryToolEnvironment env, String... args) throws Exception { diff --git a/core/src/test/java/google/registry/tools/UpdateDomainCommandTest.java b/core/src/test/java/google/registry/tools/UpdateDomainCommandTest.java index a8ed424c3..6d1be6d6a 100644 --- a/core/src/test/java/google/registry/tools/UpdateDomainCommandTest.java +++ b/core/src/test/java/google/registry/tools/UpdateDomainCommandTest.java @@ -25,12 +25,15 @@ import static google.registry.testing.DatabaseHelper.newDomainBase; import static google.registry.testing.DatabaseHelper.persistActiveDomain; import static google.registry.testing.DatabaseHelper.persistActiveHost; import static google.registry.testing.DatabaseHelper.persistResource; +import static google.registry.testing.TestLogHandlerUtils.assertLogMessage; +import static google.registry.testing.TestLogHandlerUtils.assertNoLogMessage; import static google.registry.util.DateTimeUtils.END_OF_TIME; import static org.junit.jupiter.api.Assertions.assertThrows; import com.beust.jcommander.ParameterException; import com.google.common.collect.ImmutableMap; import com.google.common.collect.ImmutableSet; +import com.google.common.flogger.LoggerConfig; import google.registry.model.billing.BillingEvent; import google.registry.model.billing.BillingEvent.Flag; import google.registry.model.billing.BillingEvent.Reason; @@ -46,6 +49,9 @@ import google.registry.persistence.VKey; import google.registry.testing.DualDatabaseTest; import google.registry.testing.InjectExtension; import google.registry.testing.TestOfyAndSql; +import google.registry.util.CapturingLogHandler; +import java.util.logging.Level; +import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.extension.RegisterExtension; @@ -53,6 +59,8 @@ import org.junit.jupiter.api.extension.RegisterExtension; @DualDatabaseTest class UpdateDomainCommandTest extends EppToolCommandTestCase { + private final CapturingLogHandler logHandler = new CapturingLogHandler(); + private DomainBase domain; @RegisterExtension public final InjectExtension inject = new InjectExtension(); @@ -62,6 +70,12 @@ class UpdateDomainCommandTest extends EppToolCommandTestCase