From f640d765e8155b3bf84c5ee26821e8027946d8f0 Mon Sep 17 00:00:00 2001 From: nickfelt Date: Mon, 1 May 2017 11:00:14 -0700 Subject: [PATCH] Log EppExceptions in EppController at INFO (vs FlowRunner at WARNING) The logging for exceptions in FlowRunner - always at WARNING - has long been sub-optimal. For EppExceptions it's too aggressive/spammy to log at WARNING because it's generally not actionable - EppException gets properly thrown for all kinds of ordinary reasons (trying to create a resource when one already exists with that foreign key) and/or for client misbehavior that we can't control (sending bad parameter values, etc.). For non-EppException RuntimeExceptions, it's redundant with existing logging in EppController. This CL resolves this by removing that logging in FlowRunner entirely in favor of the EppController logging, where we're now logging EppExceptions at INFO in parallel with the existing logging of RuntimeExceptions at SEVERE. This has the benefit that we're now logging EppExceptions that come from FlowPicker (by way of EppExceptionInProviderException), which previously were unlogged. Note however that this does mean that in places where we run FlowRunner without EppController - exclusively test code as it stands today - we'd no longer be logging EppExceptions. If that seems like a loss, we could either reinstate logging there (at INFO) and just deal with redundant messages for most EppExceptions, or we could add it manually to places where we call FlowRunner.run() in tests and avoid the redundancy that way. ------------- Created by MOE: https://github.com/google/moe MOE_MIGRATED_REVID=154733365 --- java/google/registry/flows/EppController.java | 8 +- java/google/registry/flows/FlowRunner.java | 23 ++-- .../registry/flows/EppControllerTest.java | 115 ++++++++++++++++-- .../registry/flows/FlowReporterTest.java | 45 ++----- .../google/registry/flows/FlowRunnerTest.java | 33 ++--- .../registry/testing/TestLogHandlerUtils.java | 48 ++++++++ 6 files changed, 196 insertions(+), 76 deletions(-) create mode 100644 javatests/google/registry/testing/TestLogHandlerUtils.java diff --git a/java/google/registry/flows/EppController.java b/java/google/registry/flows/EppController.java index 5fc6cf969..4f62cc0fa 100644 --- a/java/google/registry/flows/EppController.java +++ b/java/google/registry/flows/EppController.java @@ -118,12 +118,14 @@ public final class EppController { try { return flowComponent.flowRunner().run(eppMetricBuilder); } catch (EppException | EppExceptionInProviderException e) { - // The command failed. Send the client an error message. + // The command failed. Send the client an error message, but only log at INFO since many of + // these failures are innocuous or due to client error, so there's nothing we have to change. + logger.info(e, "Flow returned failure response"); EppException eppEx = (EppException) (e instanceof EppException ? e : e.getCause()); return getErrorResponse(eppEx.getResult(), flowComponent.trid()); } catch (Throwable e) { - // Something bad and unexpected happened. Send the client a generic error, and log it. - logger.severe(e, "Unexpected failure"); + // Something bad and unexpected happened. Send the client a generic error, and log at SEVERE. + logger.severe(e, "Unexpected failure in flow execution"); return getErrorResponse(Result.create(Code.COMMAND_FAILED), flowComponent.trid()); } } diff --git a/java/google/registry/flows/FlowRunner.java b/java/google/registry/flows/FlowRunner.java index e56d829d9..3e3edbd32 100644 --- a/java/google/registry/flows/FlowRunner.java +++ b/java/google/registry/flows/FlowRunner.java @@ -14,7 +14,6 @@ package google.registry.flows; -import static com.google.common.base.Throwables.getStackTraceAsString; import static google.registry.model.ofy.ObjectifyService.ofy; import static google.registry.xml.XmlTransformer.prettyPrint; @@ -100,17 +99,13 @@ public class FlowRunner { } return output; } catch (EppException e) { - throw new RuntimeException(e); + throw new EppRuntimeException(e); } }}); } catch (DryRunException e) { return e.output; - } catch (RuntimeException e) { - logger.warning(getStackTraceAsString(e)); - if (e.getCause() instanceof EppException) { - throw (EppException) e.getCause(); - } - throw e; + } catch (EppRuntimeException e) { + throw e.getCause(); } } @@ -122,4 +117,16 @@ public class FlowRunner { this.output = output; } } + + /** Exception for explicitly propagating an EppException out of the transactional {@code Work}. */ + private static class EppRuntimeException extends RuntimeException { + EppRuntimeException(EppException cause) { + super(cause); + } + + @Override + public synchronized EppException getCause() { + return (EppException) super.getCause(); + } + } } diff --git a/javatests/google/registry/flows/EppControllerTest.java b/javatests/google/registry/flows/EppControllerTest.java index 7731b5862..368532d47 100644 --- a/javatests/google/registry/flows/EppControllerTest.java +++ b/javatests/google/registry/flows/EppControllerTest.java @@ -14,15 +14,24 @@ package google.registry.flows; +import static com.google.common.io.BaseEncoding.base64; import static com.google.common.truth.Truth.assertThat; import static google.registry.flows.EppXmlTransformer.marshal; +import static google.registry.testing.LogsSubject.assertAboutLogs; import static google.registry.testing.TestDataHelper.loadFileWithSubstitutions; +import static google.registry.testing.TestLogHandlerUtils.findFirstLogRecordWithMessagePrefix; import static java.nio.charset.StandardCharsets.UTF_8; +import static java.util.logging.Level.INFO; +import static java.util.logging.Level.SEVERE; import static org.mockito.Mockito.verify; import static org.mockito.Mockito.when; +import com.google.common.base.Splitter; import com.google.common.collect.ImmutableMap; +import com.google.common.testing.TestLogHandler; +import google.registry.flows.EppException.UnimplementedExtensionException; import google.registry.flows.EppTestComponent.FakeServerTridProvider; +import google.registry.flows.FlowModule.EppExceptionInProviderException; import google.registry.model.eppcommon.Trid; import google.registry.model.eppoutput.EppOutput; import google.registry.model.eppoutput.EppResponse; @@ -35,7 +44,12 @@ import google.registry.testing.FakeClock; import google.registry.testing.ShardableTestCase; import google.registry.util.Clock; import google.registry.xml.ValidationMode; +import java.util.List; +import java.util.Map; +import java.util.logging.LogRecord; +import java.util.logging.Logger; import org.joda.time.DateTime; +import org.json.simple.JSONValue; import org.junit.Before; import org.junit.Rule; import org.junit.Test; @@ -66,11 +80,18 @@ public class EppControllerTest extends ShardableTestCase { private static final DateTime startTime = DateTime.parse("2016-09-01T00:00:00Z"); private final Clock clock = new FakeClock(startTime); + private final TestLogHandler logHandler = new TestLogHandler(); + + private final String domainCreateXml = + loadFileWithSubstitutions( + getClass(), "domain_create_prettyprinted.xml", ImmutableMap.of()); private EppController eppController; @Before public void setUp() throws Exception { + Logger.getLogger(EppController.class.getCanonicalName()).addHandler(logHandler); + when(sessionMetadata.getClientId()).thenReturn("some-client"); when(flowComponentBuilder.flowModule(Matchers.any())) .thenReturn(flowComponentBuilder); @@ -99,8 +120,7 @@ public class EppControllerTest extends ShardableTestCase { } @Test - public void testHandleEppCommand_unmarshallableData_exportsMetric() { - ArgumentCaptor metricCaptor = ArgumentCaptor.forClass(EppMetric.class); + public void testHandleEppCommand_unmarshallableData_exportsMetric() throws Exception { eppController.handleEppCommand( sessionMetadata, transportCredentials, @@ -109,6 +129,7 @@ public class EppControllerTest extends ShardableTestCase { false, new byte[0]); + ArgumentCaptor metricCaptor = ArgumentCaptor.forClass(EppMetric.class); verify(metricsEnqueuer).export(metricCaptor.capture()); EppMetric metric = metricCaptor.getValue(); assertThat(metric.getRequestId()).isEqualTo("request-id-1"); @@ -120,11 +141,7 @@ public class EppControllerTest extends ShardableTestCase { } @Test - public void testHandleEppCommand_regularEppCommand_exportsMetric() { - ArgumentCaptor metricCaptor = ArgumentCaptor.forClass(EppMetric.class); - String domainCreateXml = - loadFileWithSubstitutions( - getClass(), "domain_create_prettyprinted.xml", ImmutableMap.of()); + public void testHandleEppCommand_regularEppCommand_exportsMetric() throws Exception { eppController.handleEppCommand( sessionMetadata, transportCredentials, @@ -133,6 +150,7 @@ public class EppControllerTest extends ShardableTestCase { true, domainCreateXml.getBytes(UTF_8)); + ArgumentCaptor metricCaptor = ArgumentCaptor.forClass(EppMetric.class); verify(metricsEnqueuer).export(metricCaptor.capture()); EppMetric metric = metricCaptor.getValue(); assertThat(metric.getRequestId()).isEqualTo("request-id-1"); @@ -143,4 +161,87 @@ public class EppControllerTest extends ShardableTestCase { assertThat(metric.getStatus()).hasValue(Code.SUCCESS_WITH_NO_MESSAGES); assertThat(metric.getEppTarget()).hasValue("example.tld"); } + + @Test + public void testHandleEppCommand_unmarshallableData_loggedAtInfo_withJsonData() throws Exception { + eppController.handleEppCommand( + sessionMetadata, + transportCredentials, + EppRequestSource.UNIT_TEST, + false, + false, + "GET / HTTP/1.1\n\n".getBytes(UTF_8)); + + assertAboutLogs().that(logHandler) + .hasLogAtLevelWithMessage(INFO, "EPP request XML unmarshalling failed"); + LogRecord logRecord = + findFirstLogRecordWithMessagePrefix(logHandler, "EPP request XML unmarshalling failed"); + List messageParts = Splitter.on('\n').splitToList(logRecord.getMessage()); + assertThat(messageParts.size()).isAtLeast(2); + Map json = parseJsonMap(messageParts.get(1)); + assertThat(json).containsEntry("clientId", "some-client"); + assertThat(json).containsEntry("resultCode", 2001L); // Must be Long to compare equal. + assertThat(json).containsEntry("resultMessage", "Command syntax error"); + assertThat(json) + .containsEntry("xmlBytes", base64().encode("GET / HTTP/1.1\n\n".getBytes(UTF_8))); + } + + @Test + public void testHandleEppCommand_throwsEppException_loggedAtInfo() throws Exception { + when(flowRunner.run(eppController.eppMetricBuilder)) + .thenThrow(new UnimplementedExtensionException()); + eppController.handleEppCommand( + sessionMetadata, + transportCredentials, + EppRequestSource.UNIT_TEST, + false, + true, + domainCreateXml.getBytes(UTF_8)); + assertAboutLogs().that(logHandler) + .hasLogAtLevelWithMessage(INFO, "Flow returned failure response"); + LogRecord logRecord = + findFirstLogRecordWithMessagePrefix(logHandler, "Flow returned failure response"); + assertThat(logRecord.getThrown()).isInstanceOf(UnimplementedExtensionException.class); + } + + @Test + public void testHandleEppCommand_throwsEppExceptionInProviderException_loggedAtInfo() + throws Exception { + when(flowRunner.run(eppController.eppMetricBuilder)) + .thenThrow(new EppExceptionInProviderException(new UnimplementedExtensionException())); + eppController.handleEppCommand( + sessionMetadata, + transportCredentials, + EppRequestSource.UNIT_TEST, + false, + true, + domainCreateXml.getBytes(UTF_8)); + assertAboutLogs().that(logHandler) + .hasLogAtLevelWithMessage(INFO, "Flow returned failure response"); + LogRecord logRecord = + findFirstLogRecordWithMessagePrefix(logHandler, "Flow returned failure response"); + assertThat(logRecord.getThrown()).isInstanceOf(EppExceptionInProviderException.class); + } + + @Test + public void testHandleEppCommand_throwsRuntimeException_loggedAtSevere() throws Exception { + when(flowRunner.run(eppController.eppMetricBuilder)).thenThrow(new IllegalStateException()); + eppController.handleEppCommand( + sessionMetadata, + transportCredentials, + EppRequestSource.UNIT_TEST, + false, + true, + domainCreateXml.getBytes(UTF_8)); + assertAboutLogs().that(logHandler) + .hasLogAtLevelWithMessage(SEVERE, "Unexpected failure in flow execution"); + LogRecord logRecord = + findFirstLogRecordWithMessagePrefix(logHandler, "Unexpected failure in flow execution"); + assertThat(logRecord.getThrown()).isInstanceOf(IllegalStateException.class); + } + + @SuppressWarnings("unchecked") + private static Map parseJsonMap(String json) throws Exception { + return (Map) JSONValue.parseWithException(json); + } } diff --git a/javatests/google/registry/flows/FlowReporterTest.java b/javatests/google/registry/flows/FlowReporterTest.java index 6b1a32184..fa80ec2c1 100644 --- a/javatests/google/registry/flows/FlowReporterTest.java +++ b/javatests/google/registry/flows/FlowReporterTest.java @@ -17,15 +17,14 @@ package google.registry.flows; import static com.google.common.io.BaseEncoding.base64; import static com.google.common.truth.Truth.assertThat; import static google.registry.testing.TestDataHelper.loadFileWithSubstitutions; +import static google.registry.testing.TestLogHandlerUtils.findFirstLogMessageByPrefix; import static java.nio.charset.StandardCharsets.UTF_8; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.when; import com.google.common.base.Optional; -import com.google.common.base.Predicate; import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableMap; -import com.google.common.collect.Iterables; import com.google.common.testing.TestLogHandler; import google.registry.flows.annotations.ReportingSpec; import google.registry.model.eppcommon.Trid; @@ -35,7 +34,6 @@ import google.registry.model.eppoutput.EppResponse; import google.registry.model.reporting.IcannReportingTypes.ActivityReportField; import google.registry.testing.ShardableTestCase; import java.util.Map; -import java.util.logging.LogRecord; import java.util.logging.Logger; import org.json.simple.JSONValue; import org.junit.Before; @@ -82,7 +80,7 @@ public class FlowReporterTest extends ShardableTestCase { @Test public void testRecordToLogs_eppInput_basic() throws Exception { flowReporter.recordToLogs(); - assertThat(parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-EPPINPUT: "))) + assertThat(parseJsonMap(findFirstLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-EPPINPUT: "))) .containsExactly( "xml", "\n", "xmlBytes", "PHhtbC8+"); // Base64-encoding of "". @@ -94,7 +92,7 @@ public class FlowReporterTest extends ShardableTestCase { getClass(), "domain_create_prettyprinted.xml", ImmutableMap.of()); flowReporter.inputXmlBytes = domainCreateXml.getBytes(UTF_8); flowReporter.recordToLogs(); - assertThat(parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-EPPINPUT: "))) + assertThat(parseJsonMap(findFirstLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-EPPINPUT: "))) .containsExactly( "xml", domainCreateXml, "xmlBytes", base64().encode(domainCreateXml.getBytes(UTF_8))); @@ -103,7 +101,7 @@ public class FlowReporterTest extends ShardableTestCase { @Test public void testRecordToLogs_metadata_basic() throws Exception { flowReporter.recordToLogs(); - assertThat(parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: "))) + assertThat(parseJsonMap(findFirstLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: "))) .containsExactly( "serverTrid", "server-456", "clientId", "TheRegistrar", @@ -122,7 +120,7 @@ public class FlowReporterTest extends ShardableTestCase { flowReporter.flowClass = TestReportingSpecCommandFlow.class; flowReporter.recordToLogs(); Map json = - parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); + parseJsonMap(findFirstLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); assertThat(json).containsEntry("flowClassName", "TestReportingSpecCommandFlow"); assertThat(json).containsEntry("icannActivityReportField", "srs-cont-check"); } @@ -132,7 +130,7 @@ public class FlowReporterTest extends ShardableTestCase { flowReporter.clientId = ""; flowReporter.recordToLogs(); Map json = - parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); + parseJsonMap(findFirstLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); assertThat(json).containsEntry("clientId", ""); } @@ -141,7 +139,7 @@ public class FlowReporterTest extends ShardableTestCase { when(flowReporter.eppInput.getResourceType()).thenReturn(Optional.absent()); flowReporter.recordToLogs(); Map json = - parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); + parseJsonMap(findFirstLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); assertThat(json).containsEntry("resourceType", ""); assertThat(json).containsEntry("tld", ""); assertThat(json).containsEntry("tlds", ImmutableList.of()); @@ -153,7 +151,7 @@ public class FlowReporterTest extends ShardableTestCase { when(flowReporter.eppInput.getResourceType()).thenReturn(Optional.of("contact")); flowReporter.recordToLogs(); Map json = - parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); + parseJsonMap(findFirstLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); assertThat(json).containsEntry("resourceType", "contact"); assertThat(json).containsEntry("tld", ""); assertThat(json).containsEntry("tlds", ImmutableList.of()); @@ -165,7 +163,7 @@ public class FlowReporterTest extends ShardableTestCase { when(flowReporter.eppInput.getTargetIds()).thenReturn(ImmutableList.of("target.co.uk")); flowReporter.recordToLogs(); Map json = - parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); + parseJsonMap(findFirstLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); assertThat(json).containsEntry("targetId", "target.co.uk"); assertThat(json).containsEntry("targetIds", ImmutableList.of("target.co.uk")); assertThat(json).containsEntry("tld", "co.uk"); @@ -179,7 +177,7 @@ public class FlowReporterTest extends ShardableTestCase { .thenReturn(ImmutableList.of("target.co.uk", "foo.uk", "bar.uk", "baz.com")); flowReporter.recordToLogs(); Map json = - parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); + parseJsonMap(findFirstLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); assertThat(json).containsEntry("targetId", ""); assertThat(json).containsEntry( "targetIds", ImmutableList.of("target.co.uk", "foo.uk", "bar.uk", "baz.com")); @@ -193,7 +191,7 @@ public class FlowReporterTest extends ShardableTestCase { when(flowReporter.eppInput.getTargetIds()).thenReturn(ImmutableList.of("TARGET.FOO")); flowReporter.recordToLogs(); Map json = - parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); + parseJsonMap(findFirstLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); assertThat(json).containsEntry("targetId", "TARGET.FOO"); assertThat(json).containsEntry("targetIds", ImmutableList.of("TARGET.FOO")); assertThat(json).containsEntry("tld", "foo"); @@ -206,7 +204,7 @@ public class FlowReporterTest extends ShardableTestCase { when(flowReporter.eppInput.getTargetIds()).thenReturn(ImmutableList.of("")); flowReporter.recordToLogs(); Map json = - parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); + parseJsonMap(findFirstLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); assertThat(json).containsEntry("targetId", ""); assertThat(json).containsEntry("targetIds", ImmutableList.of("")); assertThat(json).containsEntry("tld", "com>"); @@ -219,7 +217,7 @@ public class FlowReporterTest extends ShardableTestCase { when(flowReporter.eppInput.getTargetIds()).thenReturn(ImmutableList.of("target,foo")); flowReporter.recordToLogs(); Map json = - parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); + parseJsonMap(findFirstLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: ")); assertThat(json).containsEntry("targetId", "target,foo"); assertThat(json).containsEntry("targetIds", ImmutableList.of("target,foo")); assertThat(json).containsEntry("tld", ""); @@ -230,21 +228,4 @@ public class FlowReporterTest extends ShardableTestCase { private static Map parseJsonMap(String json) throws Exception { return (Map) JSONValue.parseWithException(json); } - - /** - * Find the first log message stored in the handler that has the provided prefix, and return - * that message with the prefix stripped off. - */ - private static String findLogMessageByPrefix(TestLogHandler handler, final String prefix) { - return Iterables.find( - handler.getStoredLogRecords(), - new Predicate() { - @Override - public boolean apply(LogRecord logRecord) { - return logRecord.getMessage().startsWith(prefix); - } - }) - .getMessage() - .replaceFirst("^" + prefix, ""); - } } diff --git a/javatests/google/registry/flows/FlowRunnerTest.java b/javatests/google/registry/flows/FlowRunnerTest.java index 97ad19fc9..4a41d66a5 100644 --- a/javatests/google/registry/flows/FlowRunnerTest.java +++ b/javatests/google/registry/flows/FlowRunnerTest.java @@ -16,6 +16,7 @@ package google.registry.flows; import static com.google.common.truth.Truth.assertThat; import static google.registry.testing.TestDataHelper.loadFileWithSubstitutions; +import static google.registry.testing.TestLogHandlerUtils.findFirstLogMessageByPrefix; import static java.nio.charset.StandardCharsets.UTF_8; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.never; @@ -24,11 +25,9 @@ import static org.mockito.Mockito.verify; import com.google.appengine.api.users.User; import com.google.common.base.Joiner; import com.google.common.base.Optional; -import com.google.common.base.Predicate; import com.google.common.base.Splitter; import com.google.common.collect.ImmutableMap; import com.google.common.collect.ImmutableSet; -import com.google.common.collect.Iterables; import com.google.common.testing.TestLogHandler; import google.registry.model.eppcommon.Trid; import google.registry.model.eppoutput.EppOutput.ResponseOrGreeting; @@ -40,7 +39,6 @@ import google.registry.testing.FakeHttpSession; import google.registry.testing.Providers; import google.registry.testing.ShardableTestCase; import java.util.List; -import java.util.logging.LogRecord; import java.util.logging.Logger; import org.junit.Before; import org.junit.Rule; @@ -129,7 +127,7 @@ public class FlowRunnerTest extends ShardableTestCase { @Test public void testRun_legacyLoggingStatement_basic() throws Exception { flowRunner.run(eppMetricBuilder); - assertThat(Splitter.on("\n\t").split(findLogMessageByPrefix(handler, "EPP Command\n\t"))) + assertThat(Splitter.on("\n\t").split(findFirstLogMessageByPrefix(handler, "EPP Command\n\t"))) .containsExactly( "server-456", "TheRegistrar", @@ -148,7 +146,7 @@ public class FlowRunnerTest extends ShardableTestCase { flowRunner.sessionMetadata = new HttpSessionMetadata(new FakeHttpSession()); flowRunner.sessionMetadata.setClientId("TheRegistrar"); flowRunner.run(eppMetricBuilder); - assertThat(Splitter.on("\n\t").split(findLogMessageByPrefix(handler, "EPP Command\n\t"))) + assertThat(Splitter.on("\n\t").split(findFirstLogMessageByPrefix(handler, "EPP Command\n\t"))) .contains( "HttpSessionMetadata" + "{clientId=TheRegistrar, failedLoginAttempts=0, serviceExtensionUris=}"); @@ -159,7 +157,7 @@ public class FlowRunnerTest extends ShardableTestCase { flowRunner.credentials = GaeUserCredentials.forTestingUser(new User("user@example.com", "authDomain"), false); flowRunner.run(eppMetricBuilder); - assertThat(Splitter.on("\n\t").split(findLogMessageByPrefix(handler, "EPP Command\n\t"))) + assertThat(Splitter.on("\n\t").split(findFirstLogMessageByPrefix(handler, "EPP Command\n\t"))) .contains("GaeUserCredentials{gaeUser=user@example.com, isAdmin=false}"); } @@ -167,7 +165,7 @@ public class FlowRunnerTest extends ShardableTestCase { public void testRun_legacyLoggingStatement_tlsCredentials() throws Exception { flowRunner.credentials = new TlsCredentials("abc123def", Optional.of("127.0.0.1"), "sni"); flowRunner.run(eppMetricBuilder); - assertThat(Splitter.on("\n\t").split(findLogMessageByPrefix(handler, "EPP Command\n\t"))) + assertThat(Splitter.on("\n\t").split(findFirstLogMessageByPrefix(handler, "EPP Command\n\t"))) .contains( "TlsCredentials{clientCertificateHash=abc123def, clientAddress=/127.0.0.1, sni=sni}"); } @@ -176,7 +174,7 @@ public class FlowRunnerTest extends ShardableTestCase { public void testRun_legacyLoggingStatement_dryRun() throws Exception { flowRunner.isDryRun = true; flowRunner.run(eppMetricBuilder); - assertThat(Splitter.on("\n\t").split(findLogMessageByPrefix(handler, "EPP Command\n\t"))) + assertThat(Splitter.on("\n\t").split(findFirstLogMessageByPrefix(handler, "EPP Command\n\t"))) .contains("DRY_RUN"); } @@ -186,27 +184,10 @@ public class FlowRunnerTest extends ShardableTestCase { getClass(), "domain_create_prettyprinted.xml", ImmutableMap.of()); flowRunner.inputXmlBytes = domainCreateXml.getBytes(UTF_8); flowRunner.run(eppMetricBuilder); - String logMessage = findLogMessageByPrefix(handler, "EPP Command\n\t"); + String logMessage = findFirstLogMessageByPrefix(handler, "EPP Command\n\t"); List lines = Splitter.on("\n\t").splitToList(logMessage); assertThat(lines.size()).named("number of lines in log message").isAtLeast(9); String xml = Joiner.on('\n').join(lines.subList(3, lines.size() - 3)); assertThat(xml).isEqualTo(domainCreateXml); } - - /** - * Find the first log message stored in the handler that has the provided prefix, and return - * that message with the prefix stripped off. - */ - private static String findLogMessageByPrefix(TestLogHandler handler, final String prefix) { - return Iterables.find( - handler.getStoredLogRecords(), - new Predicate() { - @Override - public boolean apply(LogRecord logRecord) { - return logRecord.getMessage().startsWith(prefix); - } - }) - .getMessage() - .replaceFirst("^" + prefix, ""); - } } diff --git a/javatests/google/registry/testing/TestLogHandlerUtils.java b/javatests/google/registry/testing/TestLogHandlerUtils.java new file mode 100644 index 000000000..c9e5d286f --- /dev/null +++ b/javatests/google/registry/testing/TestLogHandlerUtils.java @@ -0,0 +1,48 @@ +// Copyright 2017 The Nomulus Authors. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package google.registry.testing; + +import com.google.common.base.Predicate; +import com.google.common.collect.Iterables; +import com.google.common.testing.TestLogHandler; +import java.util.logging.LogRecord; + +/** Utility methods for working with Guava's {@link TestLogHandler}. */ +public final class TestLogHandlerUtils { + private TestLogHandlerUtils() {} + + /** + * Find the first log message stored in the handler that has the provided prefix, and return that + * message with the prefix stripped off. + */ + public static String findFirstLogMessageByPrefix(TestLogHandler handler, String prefix) { + return findFirstLogRecordWithMessagePrefix(handler, prefix) + .getMessage() + .replaceFirst("^" + prefix, ""); + } + + /** Returns the first log record stored in handler whose message has the provided prefix. */ + public static LogRecord findFirstLogRecordWithMessagePrefix( + TestLogHandler handler, final String prefix) { + return Iterables.find( + handler.getStoredLogRecords(), + new Predicate() { + @Override + public boolean apply(LogRecord logRecord) { + return logRecord.getMessage().startsWith(prefix); + } + }); + } +}