diff --git a/java/google/registry/flows/FlowReporter.java b/java/google/registry/flows/FlowReporter.java new file mode 100644 index 000000000..5c3817615 --- /dev/null +++ b/java/google/registry/flows/FlowReporter.java @@ -0,0 +1,72 @@ +// 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.flows; + +import static com.google.common.io.BaseEncoding.base64; +import static google.registry.xml.XmlTransformer.prettyPrint; + +import com.google.common.collect.ImmutableMap; +import google.registry.flows.FlowModule.ClientId; +import google.registry.flows.FlowModule.InputXml; +import google.registry.flows.annotations.ReportingSpec; +import google.registry.model.eppcommon.Trid; +import google.registry.util.FormattingLogger; +import javax.inject.Inject; +import org.json.simple.JSONValue; + +/** Reporter used by {@link FlowRunner} to record flow execution data for reporting. */ +public class FlowReporter { + /** + * 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 Trid trid; + @Inject @ClientId String clientId; + @Inject @InputXml byte[] inputXmlBytes; + @Inject Class flowClass; + @Inject FlowReporter() {} + + /** Records information about the current flow execution in the GAE request logs. */ + public void recordToLogs() { + // 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", clientId, + "xml", prettyPrint(inputXmlBytes), + "xmlBytes", base64().encode(inputXmlBytes), + "icannActivityReportField", extractActivityReportField(flowClass)))); + } + + /** + * Returns the ICANN activity report field for the given flow class, or the empty string if no + * activity report field specification is found. + */ + private static final String extractActivityReportField(Class flowClass) { + ReportingSpec reportingSpec = flowClass.getAnnotation(ReportingSpec.class); + if (reportingSpec != null) { + return reportingSpec.value().getFieldName(); + } + return ""; + } +} diff --git a/java/google/registry/flows/FlowRunner.java b/java/google/registry/flows/FlowRunner.java index 4733e90a1..9e683562b 100644 --- a/java/google/registry/flows/FlowRunner.java +++ b/java/google/registry/flows/FlowRunner.java @@ -15,26 +15,22 @@ package google.registry.flows; 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; import google.registry.flows.FlowModule.ClientId; import google.registry.flows.FlowModule.DryRun; import google.registry.flows.FlowModule.InputXml; import google.registry.flows.FlowModule.Superuser; import google.registry.flows.FlowModule.Transactional; -import google.registry.flows.annotations.ReportingSpec; import google.registry.model.eppcommon.Trid; import google.registry.model.eppoutput.EppOutput; import google.registry.monitoring.whitebox.EppMetric; import google.registry.util.FormattingLogger; import javax.inject.Inject; import javax.inject.Provider; -import org.json.simple.JSONValue; /** Run a flow, either transactionally or not, with logging and retrying as needed. */ public class FlowRunner { @@ -44,13 +40,6 @@ public class FlowRunner { // 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 @ClientId String clientId; @@ -64,12 +53,12 @@ public class FlowRunner { @Inject @Transactional boolean isTransactional; @Inject SessionMetadata sessionMetadata; @Inject Trid trid; + @Inject FlowReporter flowReporter; @Inject FlowRunner() {} /** Runs the EPP flow, and records metrics on the given builder. */ public EppOutput run(final EppMetric.Builder eppMetricBuilder) throws EppException { 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 @@ -84,17 +73,8 @@ public class FlowRunner { 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", clientId, - "xml", prettyXml, - "xmlBytes", xmlBase64, - "icannActivityReportField", extractActivityReportField(flowClass)))); + // Record information about this flow to the GAE request logs for reporting purposes. + flowReporter.recordToLogs(); eppMetricBuilder.setCommandNameFromFlow(flowClass.getSimpleName()); if (!isTransactional) { eppMetricBuilder.incrementAttempts(); @@ -134,16 +114,4 @@ public class FlowRunner { this.output = output; } } - - /** - * Returns the ICANN activity report field for the given flow class, or the empty string if no - * activity report field specification is found. - */ - private static final String extractActivityReportField(Class flowClass) { - ReportingSpec reportingSpec = flowClass.getAnnotation(ReportingSpec.class); - if (reportingSpec != null) { - return reportingSpec.value().getFieldName(); - } - return ""; - } } diff --git a/javatests/google/registry/flows/FlowReporterTest.java b/javatests/google/registry/flows/FlowReporterTest.java new file mode 100644 index 000000000..db3864d5c --- /dev/null +++ b/javatests/google/registry/flows/FlowReporterTest.java @@ -0,0 +1,147 @@ +// 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.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.common.base.Predicate; +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; +import google.registry.model.eppoutput.EppOutput.ResponseOrGreeting; +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; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.junit.runners.JUnit4; + +/** Unit tests for {@link FlowReporter}. */ +@RunWith(JUnit4.class) +public class FlowReporterTest extends ShardableTestCase { + + static class TestCommandFlow implements Flow { + @Override + public ResponseOrGreeting run() throws EppException { + return mock(EppResponse.class); + } + } + + @ReportingSpec(ActivityReportField.CONTACT_CHECK) + static class TestReportingSpecCommandFlow implements Flow { + @Override + public ResponseOrGreeting run() throws EppException { + return mock(EppResponse.class); + } + } + + private final FlowReporter flowReporter = new FlowReporter(); + private final TestLogHandler handler = new TestLogHandler(); + + @Before + public void before() { + Logger.getLogger(FlowReporter.class.getCanonicalName()).addHandler(handler); + flowReporter.trid = Trid.create("client-123", "server-456"); + flowReporter.clientId = "TheRegistrar"; + flowReporter.inputXmlBytes = "".getBytes(UTF_8); + flowReporter.flowClass = TestCommandFlow.class; + } + + @Test + public void testRecordToLogs_basic() throws Exception { + flowReporter.recordToLogs(); + assertThat(parseJsonMap(findLogMessageByPrefix(handler, "EPP-REPORTING-LOG-SIGNATURE: "))) + .containsExactly( + "trid", "server-456", + "clientId", "TheRegistrar", + "xml", "\n", + "xmlBytes", "PHhtbC8+", // Base64-encoding of "". + "icannActivityReportField", ""); + } + + @Test + public void testRecordToLogs_withReportingSpec() throws Exception { + flowReporter.flowClass = TestReportingSpecCommandFlow.class; + flowReporter.recordToLogs(); + assertThat(parseJsonMap(findLogMessageByPrefix(handler, "EPP-REPORTING-LOG-SIGNATURE: "))) + .containsExactly( + "trid", "server-456", + "clientId", "TheRegistrar", + "xml", "\n", + "xmlBytes", "PHhtbC8+", // Base64-encoding of "". + "icannActivityReportField", "srs-cont-check"); + } + + @Test + public void testRecordToLogs_noClientId() throws Exception { + flowReporter.clientId = ""; + flowReporter.recordToLogs(); + assertThat(parseJsonMap(findLogMessageByPrefix(handler, "EPP-REPORTING-LOG-SIGNATURE: "))) + .containsExactly( + "trid", "server-456", + "clientId", "", + "xml", "\n", + "xmlBytes", "PHhtbC8+", // Base64-encoding of "". + "icannActivityReportField", ""); + } + + @Test + public void testRecordToLogs_complexEppInput() throws Exception { + String domainCreateXml = loadFileWithSubstitutions( + getClass(), "domain_create_prettyprinted.xml", ImmutableMap.of()); + flowReporter.inputXmlBytes = domainCreateXml.getBytes(UTF_8); + flowReporter.recordToLogs(); + assertThat(parseJsonMap(findLogMessageByPrefix(handler, "EPP-REPORTING-LOG-SIGNATURE: "))) + .containsExactly( + "trid", "server-456", + "clientId", "TheRegistrar", + "xml", domainCreateXml, + "xmlBytes", base64().encode(domainCreateXml.getBytes(UTF_8)), + "icannActivityReportField", ""); + } + + @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/FlowRunnerTest.java b/javatests/google/registry/flows/FlowRunnerTest.java index 95f1e1efd..7ab5e1fb8 100644 --- a/javatests/google/registry/flows/FlowRunnerTest.java +++ b/javatests/google/registry/flows/FlowRunnerTest.java @@ -14,11 +14,11 @@ 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 static org.mockito.Mockito.verify; import com.google.appengine.api.users.User; import com.google.common.base.Joiner; @@ -29,11 +29,9 @@ 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.flows.annotations.ReportingSpec; import google.registry.model.eppcommon.Trid; import google.registry.model.eppoutput.EppOutput.ResponseOrGreeting; import google.registry.model.eppoutput.EppResponse; -import google.registry.model.reporting.IcannReportingTypes.ActivityReportField; import google.registry.monitoring.whitebox.EppMetric; import google.registry.testing.AppEngineRule; import google.registry.testing.FakeClock; @@ -41,15 +39,14 @@ import google.registry.testing.FakeHttpSession; import google.registry.testing.Providers; import google.registry.testing.ShardableTestCase; import java.util.List; -import java.util.Map; import java.util.logging.LogRecord; import java.util.logging.Logger; -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 org.mockito.Mockito; /** Unit tests for {@link FlowRunner}. */ @RunWith(JUnit4.class) @@ -71,17 +68,10 @@ public class FlowRunnerTest extends ShardableTestCase { } } - @ReportingSpec(ActivityReportField.CONTACT_CHECK) - static class TestReportingSpecCommandFlow implements Flow { - @Override - public ResponseOrGreeting run() throws EppException { - return mock(EppResponse.class); - } - } - @Before public void before() { Logger.getLogger(FlowRunner.class.getCanonicalName()).addHandler(handler); + Logger.getLogger(FlowReporter.class.getCanonicalName()).addHandler(handler); flowRunner.clientId = "TheRegistrar"; flowRunner.credentials = new PasswordOnlyTransportCredentials(); flowRunner.eppRequestSource = EppRequestSource.UNIT_TEST; @@ -94,6 +84,7 @@ public class FlowRunnerTest extends ShardableTestCase { flowRunner.sessionMetadata = new StatelessRequestSessionMetadata("TheRegistrar", ImmutableSet.of()); flowRunner.trid = Trid.create("client-123", "server-456"); + flowRunner.flowReporter = Mockito.mock(FlowReporter.class); } @Test @@ -123,56 +114,9 @@ public class FlowRunnerTest extends ShardableTestCase { } @Test - public void testRun_reportingLogStatement_basic() throws Exception { + public void testRun_callsFlowReporterOnce() throws Exception { flowRunner.run(eppMetricBuilder); - assertThat(parseJsonMap(findLogMessageByPrefix(handler, "EPP-REPORTING-LOG-SIGNATURE: "))) - .containsExactly( - "trid", "server-456", - "clientId", "TheRegistrar", - "xml", "\n", - "xmlBytes", "PHhtbC8+", // Base64-encoding of "". - "icannActivityReportField", ""); - } - - @Test - public void testRun_reportingLogStatement_withReportingSpec() throws Exception { - flowRunner.flowClass = TestReportingSpecCommandFlow.class; - flowRunner.run(eppMetricBuilder); - assertThat(parseJsonMap(findLogMessageByPrefix(handler, "EPP-REPORTING-LOG-SIGNATURE: "))) - .containsExactly( - "trid", "server-456", - "clientId", "TheRegistrar", - "xml", "\n", - "xmlBytes", "PHhtbC8+", // Base64-encoding of "". - "icannActivityReportField", "srs-cont-check"); - } - - @Test - public void testRun_reportingLogStatement_noClientId() throws Exception { - flowRunner.clientId = ""; - flowRunner.run(eppMetricBuilder); - assertThat(parseJsonMap(findLogMessageByPrefix(handler, "EPP-REPORTING-LOG-SIGNATURE: "))) - .containsExactly( - "trid", "server-456", - "clientId", "", - "xml", "\n", - "xmlBytes", "PHhtbC8+", // Base64-encoding of "". - "icannActivityReportField", ""); - } - - @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(eppMetricBuilder); - assertThat(parseJsonMap(findLogMessageByPrefix(handler, "EPP-REPORTING-LOG-SIGNATURE: "))) - .containsExactly( - "trid", "server-456", - "clientId", "TheRegistrar", - "xml", domainCreateXml, - "xmlBytes", base64().encode(domainCreateXml.getBytes(UTF_8)), - "icannActivityReportField", ""); + verify(flowRunner.flowReporter).recordToLogs(); } @Test @@ -242,11 +186,6 @@ public class FlowRunnerTest extends ShardableTestCase { 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.