Add new JSON logging to FlowRunner for EPP activity reporting

We've been using the very fragile newline-delimited legacy logging
statement in FlowRunner for ICANN reporting for a long time.  While
this is bad in a few ways, the worst is that the parsing of this
logging statement is extremely fragile (e.g. adding/removing fields
can easily break the parsing).  This is in fact part of what broke the
ExportLogsServlet parsing last fall ([] and forced us to
recover by manually parsing the log statement (and its XML) in
BigQuery.  It also broke again in [] where we were relying
on matching the logging classname, since matching on 'EPP Command'
was considered insufficiently narrow.

This introduces a new JSON-format logging statement to FlowRunner
that fixes both of these problems:

 1) it replaces the newline-delimited "format" with a JSON-based
    format, so that we can add new fields much more easily and
    reliably support logging more structured data

 2) it replaces the short 'EPP Command' signature with a much more
    targeted 'EPP-REPORTING-LOG-SIGNATURE' signature so that we can
    use that alone for matching, rather than relying on the class
    name in the log message

What this doesn't fix is the fact that we still need to parse the
XML in BigQuery; we should fix this by logging the parts of the XML
that ICANN reporting needs explicitly, but that'll be a subsequent
change, since while the existing approach is gross, it's actually
much less fragile than just matching the log statement itself.
-------------
Created by MOE: https://github.com/google/moe
MOE_MIGRATED_REVID=125902976

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.
+   *
+   * <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 @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.<String, Object>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<EppOutput>() {
         @Override

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",

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.<Flow>of(
+            new Flow() {
+              @Override
+              protected EppOutput run() {
+                return null;
+              }});
+    flowRunner.inputXmlBytes = "<xml/>".getBytes(UTF_8);
+    flowRunner.isDryRun = false;
+    flowRunner.isSuperuser = false;
+    flowRunner.isTransactional = false;
+    flowRunner.metrics = mock(EppMetrics.class);
+    flowRunner.sessionMetadata =
+        new StatelessRequestSessionMetadata("TheRegistrar", ImmutableSet.<String>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", "<?xml version=\"1.0\" encoding=\"UTF-8\"?><xml/>\n",
+              // Base64-encoding of "<xml/>":
+              "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", "<?xml version=\"1.0\" encoding=\"UTF-8\"?><xml/>\n",
+              // Base64-encoding of "<xml/>":
+              "xmlBytes", "PHhtbC8+");
+  }
+
+  @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();
+    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=}",
+            "<?xml version=\"1.0\" encoding=\"UTF-8\"?><xml/>",
+            "",  // 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.<String, String>of());
+    flowRunner.inputXmlBytes = domainCreateXml.getBytes(UTF_8);
+    flowRunner.run();
+    String logMessage = findLogMessageByPrefix(handler, "EPP Command\n\t");
+    List<String> 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<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/testdata/domain_create_prettyprinted.xml

@@ -0,0 +1,21 @@
+<?xml version="1.0" encoding="UTF-8"?><epp xmlns="urn:ietf:params:xml:ns:epp-1.0">
+  <command>
+    <create>
+      <domain:create xmlns:domain="urn:ietf:params:xml:ns:domain-1.0">
+        <domain:name>example.tld</domain:name>
+        <domain:period unit="y">2</domain:period>
+        <domain:ns>
+          <domain:hostObj>ns1.example.net</domain:hostObj>
+          <domain:hostObj>ns2.example.net</domain:hostObj>
+        </domain:ns>
+        <domain:registrant>jd1234</domain:registrant>
+        <domain:contact type="admin">sh8013</domain:contact>
+        <domain:contact type="tech">sh8013</domain:contact>
+        <domain:authInfo>
+          <domain:pw>2fooBAR</domain:pw>
+        </domain:authInfo>
+      </domain:create>
+    </create>
+    <clTRID>ABC-12345</clTRID>
+  </command>
+</epp>