From f2c6021db0c30a80556601564198531ddfc8c5b4 Mon Sep 17 00:00:00 2001 From: nickfelt Date: Thu, 20 Apr 2017 16:20:34 -0700 Subject: [PATCH] Split FlowReporter logging into two lines for robustness This prevents a possible failure mode of the logging where the logged EPP input XML is very large (which can happen e.g. for domain creates with large SMD values). In those cases, the XML might cause the overall JSON string to be too large to fit within a single log entry [1], in which case it gets split over multiple lines and breaks automatic parsing. This mitigates that case by logging the EPP input (raw and base64-encoded) in a separate log statement so that the more compact metadata (like clientId) and derived values (like ICANN reporting field) will still be in an intact JSON string even in that case, and can still be readily parsed. It's okay if the actual EPP XML is harder to parse, since once we're logging the right metadata fields we shouldn't need to automatically parse the EPP XML in any normal cases. [1] I haven't found this exact limit or splitting algorithm, or whether it's a property of java logging or GAE log ingestion. The GAE logs page does note that a single application log entry (within a request, which can have up to 1000 such entries) maxes out at 8KB, so that might be it: https://cloud.google.com/appengine/docs/standard/java/logs/#writing_application_logs ------------- Created by MOE: https://github.com/google/moe MOE_MIGRATED_REVID=153771335 --- java/google/registry/flows/FlowReporter.java | 27 +++++-- .../registry/flows/FlowReporterTest.java | 72 +++++++++---------- .../registry/flows/ResourceFlowTestCase.java | 2 +- 3 files changed, 58 insertions(+), 43 deletions(-) diff --git a/java/google/registry/flows/FlowReporter.java b/java/google/registry/flows/FlowReporter.java index 5c3817615..b978ec8f4 100644 --- a/java/google/registry/flows/FlowReporter.java +++ b/java/google/registry/flows/FlowReporter.java @@ -28,12 +28,20 @@ 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. + * Log signature for recording flow EPP input data. * *

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 String EPPINPUT_LOG_SIGNATURE = "FLOW-LOG-SIGNATURE-EPPINPUT"; + + /** + * Log signature for recording flow metadata (anything beyond or derived from the raw EPP input). + * + *

WARNING: DO NOT CHANGE this value unless you want to break reporting. + */ + private static final String METADATA_LOG_SIGNATURE = "FLOW-LOG-SIGNATURE-METADATA"; private static final FormattingLogger logger = FormattingLogger.getLoggerForCallerClass(); @@ -45,16 +53,23 @@ public class 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. + // WARNING: These log statements are 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, + EPPINPUT_LOG_SIGNATURE, + JSONValue.toJSONString(ImmutableMap.of( + "xml", prettyPrint(inputXmlBytes), + "xmlBytes", base64().encode(inputXmlBytes)))); + // Explicitly log flow metadata separately from the EPP XML itself so that it stays compact + // enough to be sure to fit in a single log entry (the XML part in rare cases could be long + // enough to overflow into multiple log entries, breaking routine parsing of the JSON format). + logger.infofmt( + "%s: %s", + METADATA_LOG_SIGNATURE, JSONValue.toJSONString(ImmutableMap.of( "trid", trid.getServerTransactionId(), "clientId", clientId, - "xml", prettyPrint(inputXmlBytes), - "xmlBytes", base64().encode(inputXmlBytes), "icannActivityReportField", extractActivityReportField(flowClass)))); } diff --git a/javatests/google/registry/flows/FlowReporterTest.java b/javatests/google/registry/flows/FlowReporterTest.java index db3864d5c..890945b19 100644 --- a/javatests/google/registry/flows/FlowReporterTest.java +++ b/javatests/google/registry/flows/FlowReporterTest.java @@ -71,55 +71,55 @@ public class FlowReporterTest extends ShardableTestCase { } @Test - public void testRecordToLogs_basic() throws Exception { + public void testRecordToLogs_eppInput_basic() throws Exception { flowReporter.recordToLogs(); - assertThat(parseJsonMap(findLogMessageByPrefix(handler, "EPP-REPORTING-LOG-SIGNATURE: "))) + assertThat(parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-EPPINPUT: "))) .containsExactly( - "trid", "server-456", - "clientId", "TheRegistrar", "xml", "\n", - "xmlBytes", "PHhtbC8+", // Base64-encoding of "". - "icannActivityReportField", ""); + "xmlBytes", "PHhtbC8+"); // Base64-encoding of "". } @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 { + public void testRecordToLogs_eppInput_complex() 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: "))) + assertThat(parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-EPPINPUT: "))) + .containsExactly( + "xml", domainCreateXml, + "xmlBytes", base64().encode(domainCreateXml.getBytes(UTF_8))); + } + + @Test + public void testRecordToLogs_metadata_basic() throws Exception { + flowReporter.recordToLogs(); + assertThat(parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: "))) .containsExactly( "trid", "server-456", "clientId", "TheRegistrar", - "xml", domainCreateXml, - "xmlBytes", base64().encode(domainCreateXml.getBytes(UTF_8)), + "icannActivityReportField", ""); + } + + @Test + public void testRecordToLogs_metadata_withReportingSpec() throws Exception { + flowReporter.flowClass = TestReportingSpecCommandFlow.class; + flowReporter.recordToLogs(); + assertThat(parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: "))) + .containsExactly( + "trid", "server-456", + "clientId", "TheRegistrar", + "icannActivityReportField", "srs-cont-check"); + } + + @Test + public void testRecordToLogs_metadata_noClientId() throws Exception { + flowReporter.clientId = ""; + flowReporter.recordToLogs(); + assertThat(parseJsonMap(findLogMessageByPrefix(handler, "FLOW-LOG-SIGNATURE-METADATA: "))) + .containsExactly( + "trid", "server-456", + "clientId", "", "icannActivityReportField", ""); } diff --git a/javatests/google/registry/flows/ResourceFlowTestCase.java b/javatests/google/registry/flows/ResourceFlowTestCase.java index b7d602f2e..1559d1d1d 100644 --- a/javatests/google/registry/flows/ResourceFlowTestCase.java +++ b/javatests/google/registry/flows/ResourceFlowTestCase.java @@ -175,7 +175,7 @@ public abstract class ResourceFlowTestCase