diff --git a/java/google/registry/flows/FlowRunner.java b/java/google/registry/flows/FlowRunner.java index fc758fb15..4b81d06b1 100644 --- a/java/google/registry/flows/FlowRunner.java +++ b/java/google/registry/flows/FlowRunner.java @@ -14,12 +14,14 @@ package google.registry.flows; +import static com.google.common.base.Strings.nullToEmpty; import static com.google.common.base.Throwables.getStackTraceAsString; import static com.google.common.io.BaseEncoding.base64; import static google.registry.model.ofy.ObjectifyService.ofy; import static google.registry.xml.XmlTransformer.prettyPrint; import com.google.common.base.Strings; +import com.google.common.collect.ImmutableMap; import com.googlecode.objectify.Work; @@ -36,6 +38,7 @@ import google.registry.util.Clock; import google.registry.util.FormattingLogger; import org.joda.time.DateTime; +import org.json.simple.JSONValue; import javax.annotation.Nullable; import javax.inject.Inject; @@ -44,8 +47,18 @@ import javax.inject.Provider; /** Run a flow, either transactionally or not, with logging and retrying as needed. */ public class FlowRunner { + /** Log format used by legacy ICANN reporting parsing - DO NOT CHANGE. */ + // TODO(b/20725722): remove this log format entirely once we've transitioned to using the + // JSON log line below instead, or change this one to be for human consumption only. private static final String COMMAND_LOG_FORMAT = "EPP Command" + Strings.repeat("\n\t%s", 7); + /** + * Log signature used by reporting pipelines to extract matching log lines. + * + *

WARNING: DO NOT CHANGE this value unless you want to break reporting. + */ + private static final String REPORTING_LOG_SIGNATURE = "EPP-REPORTING-LOG-SIGNATURE"; + private static final FormattingLogger logger = FormattingLogger.getLoggerForCallerClass(); @Inject @Nullable @ClientId String clientId; @@ -64,18 +77,32 @@ public class FlowRunner { @Inject FlowRunner() {} public EppOutput run() throws EppException { - String clientId = sessionMetadata.getClientId(); - // This log is very fragile since it's used for ICANN reporting. + String prettyXml = prettyPrint(inputXmlBytes); + String xmlBase64 = base64().encode(inputXmlBytes); + // This log line is very fragile since it's used for ICANN reporting - DO NOT CHANGE. + // New data to be logged should be added only to the JSON log statement below. + // TODO(b/20725722): remove this log statement entirely once we've transitioned to using the + // log line below instead, or change this one to be for human consumption only. logger.infofmt( COMMAND_LOG_FORMAT, trid.getServerTransactionId(), clientId, sessionMetadata, - prettyPrint(inputXmlBytes).replaceAll("\n", "\n\t"), + prettyXml.replaceAll("\n", "\n\t"), credentials, eppRequestSource, isDryRun ? "DRY_RUN" : "LIVE", isSuperuser ? "SUPERUSER" : "NORMAL"); + // WARNING: This JSON log statement is parsed by reporting pipelines - be careful when changing. + // It should be safe to add new keys, but be very cautious in changing existing keys. + logger.infofmt( + "%s: %s", + REPORTING_LOG_SIGNATURE, + JSONValue.toJSONString(ImmutableMap.of( + "trid", trid.getServerTransactionId(), + "clientId", nullToEmpty(clientId), + "xml", prettyXml, + "xmlBytes", xmlBase64))); if (!isTransactional) { metrics.incrementAttempts(); return createAndInitFlow(clock.nowUtc()).run(); @@ -86,7 +113,7 @@ public class FlowRunner { logger.info("EPP_Mutation " + new JsonLogStatement(trid) .add("client", clientId) .add("privileges", isSuperuser ? "SUPERUSER" : "NORMAL") - .add("xmlBytes", base64().encode(inputXmlBytes))); + .add("xmlBytes", xmlBase64)); try { EppOutput flowResult = ofy().transact(new Work() { @Override diff --git a/javatests/google/registry/flows/BUILD b/javatests/google/registry/flows/BUILD index 0a352ae8d..f0b2de9f0 100644 --- a/javatests/google/registry/flows/BUILD +++ b/javatests/google/registry/flows/BUILD @@ -29,6 +29,7 @@ java_library( "//java/com/google/common/collect", "//java/com/google/common/io", "//java/com/google/common/net", + "//java/com/google/common/testing", "//third_party/java/appengine:appengine-api-testonly", "//third_party/java/appengine:appengine-testing", "//third_party/java/dagger", diff --git a/javatests/google/registry/flows/FlowRunnerTest.java b/javatests/google/registry/flows/FlowRunnerTest.java new file mode 100644 index 000000000..181bfcb8f --- /dev/null +++ b/javatests/google/registry/flows/FlowRunnerTest.java @@ -0,0 +1,218 @@ +// Copyright 2016 The Domain Registry 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.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 java.nio.charset.StandardCharsets.UTF_8; +import static org.mockito.Mockito.mock; + +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.eppinput.EppInput; +import google.registry.model.eppoutput.EppOutput; +import google.registry.monitoring.whitebox.EppMetrics; +import google.registry.testing.AppEngineRule; +import google.registry.testing.FakeClock; +import google.registry.testing.FakeHttpSession; +import google.registry.testing.Providers; +import google.registry.testing.ShardableTestCase; + +import org.json.simple.JSONValue; +import org.junit.Before; +import org.junit.Rule; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.junit.runners.JUnit4; + +import java.util.List; +import java.util.Map; +import java.util.logging.LogRecord; +import java.util.logging.Logger; + +/** Unit tests for {@link FlowRunner}. */ +@RunWith(JUnit4.class) +public class FlowRunnerTest extends ShardableTestCase { + + @Rule + public final AppEngineRule appEngineRule = new AppEngineRule.Builder().build(); + + private final FlowRunner flowRunner = new FlowRunner(); + + private final TestLogHandler handler = new TestLogHandler(); + + @Before + public void before() { + Logger.getLogger(FlowRunner.class.getCanonicalName()).addHandler(handler); + + flowRunner.clientId = "TheRegistrar"; + flowRunner.clock = new FakeClock(); + flowRunner.credentials = new PasswordOnlyTransportCredentials(); + flowRunner.eppInput = new EppInput(); + flowRunner.eppRequestSource = EppRequestSource.UNIT_TEST; + flowRunner.flowProvider = + Providers.of( + new Flow() { + @Override + protected EppOutput run() { + return null; + }}); + flowRunner.inputXmlBytes = "".getBytes(UTF_8); + flowRunner.isDryRun = false; + flowRunner.isSuperuser = false; + flowRunner.isTransactional = false; + flowRunner.metrics = mock(EppMetrics.class); + flowRunner.sessionMetadata = + new StatelessRequestSessionMetadata("TheRegistrar", ImmutableSet.of()); + flowRunner.trid = Trid.create("client-123", "server-456"); + } + + @Test + public void testRun_reportingLogStatement_basic() throws Exception { + flowRunner.run(); + assertThat(parseJsonMap(findLogMessageByPrefix(handler, "EPP-REPORTING-LOG-SIGNATURE: "))) + .containsExactly( + "trid", "server-456", + "clientId", "TheRegistrar", + "xml", "\n", + // Base64-encoding of "": + "xmlBytes", "PHhtbC8+"); + } + + @Test + public void testRun_reportingLogStatement_noClientId() throws Exception { + flowRunner.clientId = null; + flowRunner.run(); + assertThat(parseJsonMap(findLogMessageByPrefix(handler, "EPP-REPORTING-LOG-SIGNATURE: "))) + .containsExactly( + "trid", "server-456", + "clientId", "", + "xml", "\n", + // Base64-encoding of "": + "xmlBytes", "PHhtbC8+"); + } + + @Test + public void testRun_reportingLogStatement_complexEppInput() throws Exception { + String domainCreateXml = loadFileWithSubstitutions( + getClass(), "domain_create_prettyprinted.xml", ImmutableMap.of()); + flowRunner.inputXmlBytes = domainCreateXml.getBytes(UTF_8); + flowRunner.run(); + assertThat(parseJsonMap(findLogMessageByPrefix(handler, "EPP-REPORTING-LOG-SIGNATURE: "))) + .containsExactly( + "trid", "server-456", + "clientId", "TheRegistrar", + "xml", domainCreateXml, + "xmlBytes", base64().encode(domainCreateXml.getBytes(UTF_8))); + } + + @Test + public void testRun_legacyLoggingStatement_basic() throws Exception { + flowRunner.run(); + assertThat(Splitter.on("\n\t").split(findLogMessageByPrefix(handler, "EPP Command\n\t"))) + .containsExactly( + "server-456", + "TheRegistrar", + "StatelessRequestSessionMetadata" + + "{clientId=TheRegistrar, failedLoginAttempts=0, serviceExtensionUris=}", + "", + "", // Extra newline at the end of the XML. + "PasswordOnlyTransportCredentials{}", + "UNIT_TEST", + "LIVE") + .inOrder(); + } + + @Test + public void testRun_legacyLoggingStatement_httpSessionMetadata() throws Exception { + flowRunner.sessionMetadata = new HttpSessionMetadata(new FakeHttpSession()); + flowRunner.sessionMetadata.setClientId("TheRegistrar"); + flowRunner.run(); + assertThat(Splitter.on("\n\t").split(findLogMessageByPrefix(handler, "EPP Command\n\t"))) + .contains( + "HttpSessionMetadata" + + "{clientId=TheRegistrar, failedLoginAttempts=0, serviceExtensionUris=}"); + } + + @Test + public void testRun_legacyLoggingStatement_gaeUserCredentials() throws Exception { + flowRunner.credentials = new GaeUserCredentials(new User("user@example.com", "authDomain")); + flowRunner.run(); + assertThat(Splitter.on("\n\t").split(findLogMessageByPrefix(handler, "EPP Command\n\t"))) + .contains("GaeUserCredentials{gaeUser=user@example.com}"); + } + + @Test + public void testRun_legacyLoggingStatement_tlsCredentials() throws Exception { + flowRunner.credentials = new TlsCredentials("abc123def", Optional.of("127.0.0.1"), "sni"); + flowRunner.run(); + assertThat(Splitter.on("\n\t").split(findLogMessageByPrefix(handler, "EPP Command\n\t"))) + .contains( + "TlsCredentials{clientCertificateHash=abc123def, clientAddress=/127.0.0.1, sni=sni}"); + } + + @Test + public void testRun_legacyLoggingStatement_dryRun() throws Exception { + flowRunner.isDryRun = true; + flowRunner.run(); + assertThat(Splitter.on("\n\t").split(findLogMessageByPrefix(handler, "EPP Command\n\t"))) + .contains("DRY_RUN"); + } + + @Test + public void testRun_legacyLoggingStatement_complexEppInput() throws Exception { + String domainCreateXml = loadFileWithSubstitutions( + getClass(), "domain_create_prettyprinted.xml", ImmutableMap.of()); + flowRunner.inputXmlBytes = domainCreateXml.getBytes(UTF_8); + flowRunner.run(); + String logMessage = findLogMessageByPrefix(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); + } + + @SuppressWarnings("unchecked") + 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/testdata/domain_create_prettyprinted.xml b/javatests/google/registry/flows/testdata/domain_create_prettyprinted.xml new file mode 100644 index 000000000..785c293be --- /dev/null +++ b/javatests/google/registry/flows/testdata/domain_create_prettyprinted.xml @@ -0,0 +1,21 @@ + + + + + example.tld + 2 + + ns1.example.net + ns2.example.net + + jd1234 + sh8013 + sh8013 + + 2fooBAR + + + + ABC-12345 + +