Move FlowRunner ICANN reporting logging to new FlowReporter

Since this reporting is getting more complicated (see b/36599833), it'll
be better to have a dedicated class to encapsulate it, which also lets us
keep the tests separate and focus FlowRunner more on its core purpose of
actually running the flow.

Note that this doesn't move the legacy log statement logging because that
specifically must be logged from the FlowRunner.run() method to preserve
the existing log signature matching in our ICANN activity reporting query.
(The new statement is designed to be robust to moves like this since it
doesn't use the logging callsite to match log lines, and it's not in use
yet anyway.)

-------------
Created by MOE: https://github.com/google/moe
MOE_MIGRATED_REVID=153762008

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.
+   *
+   * <p><b>WARNING:<b/> 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<? extends Flow> 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.<String, Object>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<? extends Flow> flowClass) {
+    ReportingSpec reportingSpec = flowClass.getAnnotation(ReportingSpec.class);
+    if (reportingSpec != null) {
+      return reportingSpec.value().getFieldName();
+    }
+    return "";
+  }
+}

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.
-   *
-   * <p><b>WARNING:<b/> 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.
+    // Record information about this flow to the GAE request logs for reporting purposes.
-    // It should be safe to add new keys, but be very cautious in changing existing keys.
+    flowReporter.recordToLogs();
-    logger.infofmt(
-        "%s: %s",
-        REPORTING_LOG_SIGNATURE,
-        JSONValue.toJSONString(ImmutableMap.<String, Object>of(
-            "trid", trid.getServerTransactionId(),
-            "clientId", clientId,
-            "xml", prettyXml,
-            "xmlBytes", xmlBase64,
-            "icannActivityReportField", extractActivityReportField(flowClass))));
     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<? extends Flow> flowClass) {
-    ReportingSpec reportingSpec = flowClass.getAnnotation(ReportingSpec.class);
-    if (reportingSpec != null) {
-      return reportingSpec.value().getFieldName();
-    }
-    return "";
-  }
 }

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 = "<xml/>".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", "<?xml version=\"1.0\" encoding=\"UTF-8\"?><xml/>\n",
+              "xmlBytes", "PHhtbC8+", // Base64-encoding of "<xml/>".
+              "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", "<?xml version=\"1.0\" encoding=\"UTF-8\"?><xml/>\n",
+              "xmlBytes", "PHhtbC8+", // Base64-encoding of "<xml/>".
+              "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", "<?xml version=\"1.0\" encoding=\"UTF-8\"?><xml/>\n",
+              "xmlBytes", "PHhtbC8+",  // Base64-encoding of "<xml/>".
+              "icannActivityReportField", "");
+  }
+
+  @Test
+  public void testRecordToLogs_complexEppInput() throws Exception {
+    String domainCreateXml = loadFileWithSubstitutions(
+        getClass(), "domain_create_prettyprinted.xml", ImmutableMap.<String, String>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<String, Object> parseJsonMap(String json) throws Exception {
+    return (Map<String, Object>) 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<LogRecord>() {
+              @Override
+              public boolean apply(LogRecord logRecord) {
+                return logRecord.getMessage().startsWith(prefix);
+              }
+            })
+        .getMessage()
+        .replaceFirst("^" + prefix, "");
+  }
+}

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.<String>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: ")))
+    verify(flowRunner.flowReporter).recordToLogs();
-        .containsExactly(
-              "trid", "server-456",
-              "clientId", "TheRegistrar",
-              "xml", "<?xml version=\"1.0\" encoding=\"UTF-8\"?><xml/>\n",
-              "xmlBytes", "PHhtbC8+", // Base64-encoding of "<xml/>".
-              "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", "<?xml version=\"1.0\" encoding=\"UTF-8\"?><xml/>\n",
-              "xmlBytes", "PHhtbC8+", // Base64-encoding of "<xml/>".
-              "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", "<?xml version=\"1.0\" encoding=\"UTF-8\"?><xml/>\n",
-              "xmlBytes", "PHhtbC8+",  // Base64-encoding of "<xml/>".
-              "icannActivityReportField", "");
-  }
-
-  @Test
-  public void testRun_reportingLogStatement_complexEppInput() throws Exception {
-    String domainCreateXml = loadFileWithSubstitutions(
-        getClass(), "domain_create_prettyprinted.xml", ImmutableMap.<String, String>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", "");
   }
 
   @Test
@@ -242,11 +186,6 @@ public class FlowRunnerTest extends ShardableTestCase {
     assertThat(xml).isEqualTo(domainCreateXml);
   }
 
-  @SuppressWarnings("unchecked")
-  private static Map<String, Object> parseJsonMap(String json) throws Exception {
-    return (Map<String, Object>) 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.