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
This commit is contained in:
Michael Muller 2021-10-11 12:54:03 -04:00 committed by GitHub
parent a755bedda0
commit 34f5e532b5
4 changed files with 43 additions and 27 deletions

View file

@ -487,7 +487,8 @@ public final class AppEngineExtension implements BeforeEachCallback, AfterEachCa
if (replayer != null) {
replayer.replay();
}
} finally {
try {
if (withCloudSql) {
if (enableJpaEntityCoverageCheck) {
jpaIntegrationWithCoverageExtension.afterEach(context);
@ -504,6 +505,7 @@ public final class AppEngineExtension implements BeforeEachCallback, AfterEachCa
}
}
}
}
/**
* Tears down the fake App Engine environment after use.

View file

@ -43,6 +43,15 @@ public final class TestLogHandlerUtils {
handler.getStoredLogRecords(), logRecord -> logRecord.getMessage().startsWith(prefix));
}
/** Assert that the specified log message is <em>not</em> 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)) {

View file

@ -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<C extends Command> {
// 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<C extends Command> {
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<C extends Command> {
public final void afterEachCommandTestCase() {
System.setOut(oldStdout);
System.setErr(oldStderr);
streamsLock.unlock();
}
void runCommandInEnvironment(RegistryToolEnvironment env, String... args) throws Exception {

View file

@ -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<UpdateDomainCommand> {
private final CapturingLogHandler logHandler = new CapturingLogHandler();
private DomainBase domain;
@RegisterExtension public final InjectExtension inject = new InjectExtension();
@ -62,6 +70,12 @@ class UpdateDomainCommandTest extends EppToolCommandTestCase<UpdateDomainCommand
inject.setStaticField(Ofy.class, "clock", fakeClock);
command.clock = fakeClock;
domain = persistActiveDomain("example.tld");
LoggerConfig.getConfig(UpdateDomainCommand.class).addHandler(logHandler);
}
@AfterEach
void afterEach() {
LoggerConfig.getConfig(UpdateDomainCommand.class).removeHandler(logHandler);
}
@TestOfyAndSql
@ -299,7 +313,7 @@ class UpdateDomainCommandTest extends EppToolCommandTestCase<UpdateDomainCommand
runCommandForced("--client=NewRegistrar", "--autorenews=false", "example.tld");
eppVerifier.verifySent(
"domain_update_set_autorenew.xml", ImmutableMap.of("AUTORENEWS", "false"));
assertThat(getStderrAsString()).doesNotContain("autorenew grace period");
assertNoLogMessage(logHandler, Level.WARNING, "autorenew grace period");
}
@TestOfyAndSql
@ -340,9 +354,9 @@ class UpdateDomainCommandTest extends EppToolCommandTestCase<UpdateDomainCommand
runCommandForced("--client=NewRegistrar", "--autorenews=false", "example.tld");
eppVerifier.verifySent(
"domain_update_set_autorenew.xml", ImmutableMap.of("AUTORENEWS", "false"));
String stdErr = getStderrAsString();
assertThat(stdErr).contains("The following domains are in autorenew grace periods.");
assertThat(stdErr).contains("example.tld");
assertLogMessage(
logHandler, Level.WARNING, "The following domains are in autorenew grace periods.");
assertLogMessage(logHandler, Level.WARNING, "example.tld");
}
@TestOfyAndSql