mirror of
https://github.com/google/nomulus.git
synced 2025-05-14 08:27:14 +02:00
Log EppExceptions in EppController at INFO (vs FlowRunner at WARNING)
The logging for exceptions in FlowRunner - always at WARNING - has long been sub-optimal. For EppExceptions it's too aggressive/spammy to log at WARNING because it's generally not actionable - EppException gets properly thrown for all kinds of ordinary reasons (trying to create a resource when one already exists with that foreign key) and/or for client misbehavior that we can't control (sending bad parameter values, etc.). For non-EppException RuntimeExceptions, it's redundant with existing logging in EppController. This CL resolves this by removing that logging in FlowRunner entirely in favor of the EppController logging, where we're now logging EppExceptions at INFO in parallel with the existing logging of RuntimeExceptions at SEVERE. This has the benefit that we're now logging EppExceptions that come from FlowPicker (by way of EppExceptionInProviderException), which previously were unlogged. Note however that this does mean that in places where we run FlowRunner without EppController - exclusively test code as it stands today - we'd no longer be logging EppExceptions. If that seems like a loss, we could either reinstate logging there (at INFO) and just deal with redundant messages for most EppExceptions, or we could add it manually to places where we call FlowRunner.run() in tests and avoid the redundancy that way. ------------- Created by MOE: https://github.com/google/moe MOE_MIGRATED_REVID=154733365
This commit is contained in:
nickfelt
Ben McIlwain
parent
11e7374c0f
commit
f640d765e8
6 changed files with 196 additions and 76 deletions
|
|
@ -14,15 +14,24 @@
|
|||
|
||||
package google.registry.flows;
|
||||
|
||||
import static com.google.common.io.BaseEncoding.base64;
|
||||
import static com.google.common.truth.Truth.assertThat;
|
||||
import static google.registry.flows.EppXmlTransformer.marshal;
|
||||
import static google.registry.testing.LogsSubject.assertAboutLogs;
|
||||
import static google.registry.testing.TestDataHelper.loadFileWithSubstitutions;
|
||||
import static google.registry.testing.TestLogHandlerUtils.findFirstLogRecordWithMessagePrefix;
|
||||
import static java.nio.charset.StandardCharsets.UTF_8;
|
||||
import static java.util.logging.Level.INFO;
|
||||
import static java.util.logging.Level.SEVERE;
|
||||
import static org.mockito.Mockito.verify;
|
||||
import static org.mockito.Mockito.when;
|
||||
|
||||
import com.google.common.base.Splitter;
|
||||
import com.google.common.collect.ImmutableMap;
|
||||
import com.google.common.testing.TestLogHandler;
|
||||
import google.registry.flows.EppException.UnimplementedExtensionException;
|
||||
import google.registry.flows.EppTestComponent.FakeServerTridProvider;
|
||||
import google.registry.flows.FlowModule.EppExceptionInProviderException;
|
||||
import google.registry.model.eppcommon.Trid;
|
||||
import google.registry.model.eppoutput.EppOutput;
|
||||
import google.registry.model.eppoutput.EppResponse;
|
||||
|
|
@ -35,7 +44,12 @@ import google.registry.testing.FakeClock;
|
|||
import google.registry.testing.ShardableTestCase;
|
||||
import google.registry.util.Clock;
|
||||
import google.registry.xml.ValidationMode;
|
||||
import java.util.List;
|
||||
import java.util.Map;
|
||||
import java.util.logging.LogRecord;
|
||||
import java.util.logging.Logger;
|
||||
import org.joda.time.DateTime;
|
||||
import org.json.simple.JSONValue;
|
||||
import org.junit.Before;
|
||||
import org.junit.Rule;
|
||||
import org.junit.Test;
|
||||
|
|
@ -66,11 +80,18 @@ public class EppControllerTest extends ShardableTestCase {
|
|||
private static final DateTime startTime = DateTime.parse("2016-09-01T00:00:00Z");
|
||||
|
||||
private final Clock clock = new FakeClock(startTime);
|
||||
private final TestLogHandler logHandler = new TestLogHandler();
|
||||
|
||||
private final String domainCreateXml =
|
||||
loadFileWithSubstitutions(
|
||||
getClass(), "domain_create_prettyprinted.xml", ImmutableMap.<String, String>of());
|
||||
|
||||
private EppController eppController;
|
||||
|
||||
@Before
|
||||
public void setUp() throws Exception {
|
||||
Logger.getLogger(EppController.class.getCanonicalName()).addHandler(logHandler);
|
||||
|
||||
when(sessionMetadata.getClientId()).thenReturn("some-client");
|
||||
when(flowComponentBuilder.flowModule(Matchers.<FlowModule>any()))
|
||||
.thenReturn(flowComponentBuilder);
|
||||
|
|
@ -99,8 +120,7 @@ public class EppControllerTest extends ShardableTestCase {
|
|||
}
|
||||
|
||||
@Test
|
||||
public void testHandleEppCommand_unmarshallableData_exportsMetric() {
|
||||
ArgumentCaptor<EppMetric> metricCaptor = ArgumentCaptor.forClass(EppMetric.class);
|
||||
public void testHandleEppCommand_unmarshallableData_exportsMetric() throws Exception {
|
||||
eppController.handleEppCommand(
|
||||
sessionMetadata,
|
||||
transportCredentials,
|
||||
|
|
@ -109,6 +129,7 @@ public class EppControllerTest extends ShardableTestCase {
|
|||
false,
|
||||
new byte[0]);
|
||||
|
||||
ArgumentCaptor<EppMetric> metricCaptor = ArgumentCaptor.forClass(EppMetric.class);
|
||||
verify(metricsEnqueuer).export(metricCaptor.capture());
|
||||
EppMetric metric = metricCaptor.getValue();
|
||||
assertThat(metric.getRequestId()).isEqualTo("request-id-1");
|
||||
|
|
@ -120,11 +141,7 @@ public class EppControllerTest extends ShardableTestCase {
|
|||
}
|
||||
|
||||
@Test
|
||||
public void testHandleEppCommand_regularEppCommand_exportsMetric() {
|
||||
ArgumentCaptor<EppMetric> metricCaptor = ArgumentCaptor.forClass(EppMetric.class);
|
||||
String domainCreateXml =
|
||||
loadFileWithSubstitutions(
|
||||
getClass(), "domain_create_prettyprinted.xml", ImmutableMap.<String, String>of());
|
||||
public void testHandleEppCommand_regularEppCommand_exportsMetric() throws Exception {
|
||||
eppController.handleEppCommand(
|
||||
sessionMetadata,
|
||||
transportCredentials,
|
||||
|
|
@ -133,6 +150,7 @@ public class EppControllerTest extends ShardableTestCase {
|
|||
true,
|
||||
domainCreateXml.getBytes(UTF_8));
|
||||
|
||||
ArgumentCaptor<EppMetric> metricCaptor = ArgumentCaptor.forClass(EppMetric.class);
|
||||
verify(metricsEnqueuer).export(metricCaptor.capture());
|
||||
EppMetric metric = metricCaptor.getValue();
|
||||
assertThat(metric.getRequestId()).isEqualTo("request-id-1");
|
||||
|
|
@ -143,4 +161,87 @@ public class EppControllerTest extends ShardableTestCase {
|
|||
assertThat(metric.getStatus()).hasValue(Code.SUCCESS_WITH_NO_MESSAGES);
|
||||
assertThat(metric.getEppTarget()).hasValue("example.tld");
|
||||
}
|
||||
|
||||
@Test
|
||||
public void testHandleEppCommand_unmarshallableData_loggedAtInfo_withJsonData() throws Exception {
|
||||
eppController.handleEppCommand(
|
||||
sessionMetadata,
|
||||
transportCredentials,
|
||||
EppRequestSource.UNIT_TEST,
|
||||
false,
|
||||
false,
|
||||
"GET / HTTP/1.1\n\n".getBytes(UTF_8));
|
||||
|
||||
assertAboutLogs().that(logHandler)
|
||||
.hasLogAtLevelWithMessage(INFO, "EPP request XML unmarshalling failed");
|
||||
LogRecord logRecord =
|
||||
findFirstLogRecordWithMessagePrefix(logHandler, "EPP request XML unmarshalling failed");
|
||||
List<String> messageParts = Splitter.on('\n').splitToList(logRecord.getMessage());
|
||||
assertThat(messageParts.size()).isAtLeast(2);
|
||||
Map<String, Object> json = parseJsonMap(messageParts.get(1));
|
||||
assertThat(json).containsEntry("clientId", "some-client");
|
||||
assertThat(json).containsEntry("resultCode", 2001L); // Must be Long to compare equal.
|
||||
assertThat(json).containsEntry("resultMessage", "Command syntax error");
|
||||
assertThat(json)
|
||||
.containsEntry("xmlBytes", base64().encode("GET / HTTP/1.1\n\n".getBytes(UTF_8)));
|
||||
}
|
||||
|
||||
@Test
|
||||
public void testHandleEppCommand_throwsEppException_loggedAtInfo() throws Exception {
|
||||
when(flowRunner.run(eppController.eppMetricBuilder))
|
||||
.thenThrow(new UnimplementedExtensionException());
|
||||
eppController.handleEppCommand(
|
||||
sessionMetadata,
|
||||
transportCredentials,
|
||||
EppRequestSource.UNIT_TEST,
|
||||
false,
|
||||
true,
|
||||
domainCreateXml.getBytes(UTF_8));
|
||||
assertAboutLogs().that(logHandler)
|
||||
.hasLogAtLevelWithMessage(INFO, "Flow returned failure response");
|
||||
LogRecord logRecord =
|
||||
findFirstLogRecordWithMessagePrefix(logHandler, "Flow returned failure response");
|
||||
assertThat(logRecord.getThrown()).isInstanceOf(UnimplementedExtensionException.class);
|
||||
}
|
||||
|
||||
@Test
|
||||
public void testHandleEppCommand_throwsEppExceptionInProviderException_loggedAtInfo()
|
||||
throws Exception {
|
||||
when(flowRunner.run(eppController.eppMetricBuilder))
|
||||
.thenThrow(new EppExceptionInProviderException(new UnimplementedExtensionException()));
|
||||
eppController.handleEppCommand(
|
||||
sessionMetadata,
|
||||
transportCredentials,
|
||||
EppRequestSource.UNIT_TEST,
|
||||
false,
|
||||
true,
|
||||
domainCreateXml.getBytes(UTF_8));
|
||||
assertAboutLogs().that(logHandler)
|
||||
.hasLogAtLevelWithMessage(INFO, "Flow returned failure response");
|
||||
LogRecord logRecord =
|
||||
findFirstLogRecordWithMessagePrefix(logHandler, "Flow returned failure response");
|
||||
assertThat(logRecord.getThrown()).isInstanceOf(EppExceptionInProviderException.class);
|
||||
}
|
||||
|
||||
@Test
|
||||
public void testHandleEppCommand_throwsRuntimeException_loggedAtSevere() throws Exception {
|
||||
when(flowRunner.run(eppController.eppMetricBuilder)).thenThrow(new IllegalStateException());
|
||||
eppController.handleEppCommand(
|
||||
sessionMetadata,
|
||||
transportCredentials,
|
||||
EppRequestSource.UNIT_TEST,
|
||||
false,
|
||||
true,
|
||||
domainCreateXml.getBytes(UTF_8));
|
||||
assertAboutLogs().that(logHandler)
|
||||
.hasLogAtLevelWithMessage(SEVERE, "Unexpected failure in flow execution");
|
||||
LogRecord logRecord =
|
||||
findFirstLogRecordWithMessagePrefix(logHandler, "Unexpected failure in flow execution");
|
||||
assertThat(logRecord.getThrown()).isInstanceOf(IllegalStateException.class);
|
||||
}
|
||||
|
||||
@SuppressWarnings("unchecked")
|
||||
private static Map<String, Object> parseJsonMap(String json) throws Exception {
|
||||
return (Map<String, Object>) JSONValue.parseWithException(json);
|
||||
}
|
||||
}
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue