Make FlowRunner log ICANN activity report field name

As part of b/36599833, this makes FlowRunner log the appropriate ICANN activity
report field name for each flow it runs as part of a structured JSON log
statement which can be parsed to generate ICANN activity reports (under the key
"icannActivityReportField").

In order to support this, we introduce an annotation for Flow classes called
@ReportingSpec and a corresponding enum of values for this annotation, which is
IcannReportingTypes.ActivityReportField, that stores the mapping of constant
enum values to field names.

The mapping from flows to fields is fairly obvious, with three exceptions:

 - Application flows are all accounted under domains, since applications are
   technically just deferred domain creates within the EPP protocol
 - ClaimsCheckFlow is counted as a domain check
 - DomainAllocateFlow is counted as a domain create

In addition, I've added tests to all the corresponding flows that we are
indeed logging what we expect.

We'll also need to log the TLD for this to be useful, but I'm doing that in a
follow-up CL.

-------------
Created by MOE: https://github.com/google/moe
MOE_MIGRATED_REVID=151283411
This commit is contained in:
nickfelt
2017-03-27 13:32:57 -04:00
committed by Ben McIlwain
parent b03bd3b525
commit 91c2558feb
72 changed files with 520 additions and 24 deletions
@@ -29,9 +29,11 @@ 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;
@@ -67,6 +69,14 @@ 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);
@@ -85,18 +95,6 @@ public class FlowRunnerTest extends ShardableTestCase {
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_nonTransactionalCommand_incrementsMetricAttempts() throws Exception {
flowRunner.run();
@@ -123,6 +121,31 @@ public class FlowRunnerTest extends ShardableTestCase {
assertThat(flowRunner.metric.build().getCommandName()).hasValue("TestCommand");
}
@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",
"xmlBytes", "PHhtbC8+", // Base64-encoding of "<xml/>".
"icannActivityReportField", "");
}
@Test
public void testRun_reportingLogStatement_withReportingSpec() throws Exception {
flowRunner.flowClass = TestReportingSpecCommandFlow.class;
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",
"xmlBytes", "PHhtbC8+", // Base64-encoding of "<xml/>".
"icannActivityReportField", "srs-cont-check");
}
@Test
public void testRun_reportingLogStatement_noClientId() throws Exception {
flowRunner.clientId = "";
@@ -132,8 +155,8 @@ public class FlowRunnerTest extends ShardableTestCase {
"trid", "server-456",
"clientId", "",
"xml", "<?xml version=\"1.0\" encoding=\"UTF-8\"?><xml/>\n",
// Base64-encoding of "<xml/>":
"xmlBytes", "PHhtbC8+");
"xmlBytes", "PHhtbC8+", // Base64-encoding of "<xml/>".
"icannActivityReportField", "");
}
@Test
@@ -147,7 +170,8 @@ public class FlowRunnerTest extends ShardableTestCase {
"trid", "server-456",
"clientId", "TheRegistrar",
"xml", domainCreateXml,
"xmlBytes", base64().encode(domainCreateXml.getBytes(UTF_8)));
"xmlBytes", base64().encode(domainCreateXml.getBytes(UTF_8)),
"icannActivityReportField", "");
}
@Test
@@ -18,12 +18,14 @@ import static com.google.common.truth.Truth.assertThat;
import static google.registry.model.EppResourceUtils.loadByForeignKey;
import static google.registry.model.ofy.ObjectifyService.ofy;
import static google.registry.model.tmch.ClaimsListShardTest.createTestClaimsListShard;
import static google.registry.testing.LogsSubject.assertAboutLogs;
import static google.registry.testing.TaskQueueHelper.assertTasksEnqueued;
import com.google.common.base.Predicate;
import com.google.common.collect.FluentIterable;
import com.google.common.collect.ImmutableList;
import com.google.common.collect.ImmutableMap;
import com.google.common.testing.TestLogHandler;
import com.googlecode.objectify.Key;
import google.registry.flows.FlowUtils.NotLoggedInException;
import google.registry.model.EppResource;
@@ -38,8 +40,11 @@ import google.registry.model.tmch.ClaimsListShard.ClaimsListRevision;
import google.registry.model.tmch.ClaimsListShard.ClaimsListSingleton;
import google.registry.testing.TaskQueueHelper.TaskMatcher;
import google.registry.util.TypeUtils.TypeInstantiator;
import java.util.logging.Level;
import java.util.logging.Logger;
import org.joda.time.DateTime;
import org.joda.time.Duration;
import org.junit.Before;
import org.junit.Test;
/**
@@ -51,6 +56,16 @@ import org.junit.Test;
public abstract class ResourceFlowTestCase<F extends Flow, R extends EppResource>
extends FlowTestCase<F> {
private final TestLogHandler logHandler = new TestLogHandler();
@Before
public void beforeResourceFlowTestCase() {
// Attach TestLogHandler to the root logger so it has access to all log messages.
// Note that in theory for assertIcannReportingActivityFieldLogged() below it would suffice to
// attach it only to the FlowRunner logger, but for some reason this doesn't work for all flows.
Logger.getLogger("").addHandler(logHandler);
}
protected R reloadResourceByForeignKey(DateTime now) throws Exception {
// Force the session to be cleared so that when we read it back, we read from Datastore and
// not from the transaction cache or memcache.
@@ -151,4 +166,11 @@ public abstract class ResourceFlowTestCase<F extends Flow, R extends EppResource
.etaDelta(Duration.standardSeconds(75), Duration.standardSeconds(105)) // expected: 90
.payload(expectedPayload));
}
protected void assertIcannReportingActivityFieldLogged(String fieldName) {
assertAboutLogs().that(logHandler)
.hasLogAtLevelWithMessage(Level.INFO, "EPP-REPORTING-LOG-SIGNATURE")
.which()
.contains(fieldName);
}
}
@@ -79,4 +79,10 @@ public class ContactCheckFlowTest
thrown.expect(TooManyResourceChecksException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
runFlow();
assertIcannReportingActivityFieldLogged("srs-cont-check");
}
}
@@ -91,4 +91,10 @@ public class ContactCreateFlowTest
thrown.expect(DeclineContactDisclosureFieldDisallowedPolicyException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
runFlow();
assertIcannReportingActivityFieldLogged("srs-cont-create");
}
}
@@ -151,4 +151,12 @@ public class ContactDeleteFlowTest
thrown.expect(ResourceToDeleteIsReferencedException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
persistActiveContact(getUniqueIdFromCommand());
clock.advanceOneMilli();
runFlow();
assertIcannReportingActivityFieldLogged("srs-cont-delete");
}
}
@@ -177,4 +177,11 @@ public class ContactInfoFlowTest extends ResourceFlowTestCase<ContactInfoFlow, C
String.format("(%s)", getUniqueIdFromCommand()));
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
persistContactResource(true);
runFlow();
assertIcannReportingActivityFieldLogged("srs-cont-info");
}
}
@@ -209,4 +209,10 @@ public class ContactTransferApproveFlowTest
String.format("(%s)", getUniqueIdFromCommand()));
doFailingTest("contact_transfer_approve.xml");
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
runFlow();
assertIcannReportingActivityFieldLogged("srs-cont-transfer-approve");
}
}
@@ -195,4 +195,10 @@ public class ContactTransferCancelFlowTest
String.format("(%s)", getUniqueIdFromCommand()));
doFailingTest("contact_transfer_cancel.xml");
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
runFlow();
assertIcannReportingActivityFieldLogged("srs-cont-transfer-cancel");
}
}
@@ -183,4 +183,10 @@ public class ContactTransferQueryFlowTest
String.format("(%s)", getUniqueIdFromCommand()));
doFailingTest("contact_transfer_query.xml");
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
runFlow();
assertIcannReportingActivityFieldLogged("srs-cont-transfer-query");
}
}
@@ -205,4 +205,10 @@ public class ContactTransferRejectFlowTest
String.format("(%s)", getUniqueIdFromCommand()));
doFailingTest("contact_transfer_reject.xml");
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
runFlow();
assertIcannReportingActivityFieldLogged("srs-cont-transfer-reject");
}
}
@@ -213,4 +213,10 @@ public class ContactTransferRequestFlowTest
thrown.expect(ResourceStatusProhibitsOperationException.class, "pendingDelete");
doFailingTest("contact_transfer_request.xml");
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
runFlow();
assertIcannReportingActivityFieldLogged("srs-cont-transfer-request");
}
}
@@ -392,4 +392,12 @@ public class ContactUpdateFlowTest
thrown.expect(AddRemoveSameValueException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
persistActiveContact(getUniqueIdFromCommand());
clock.advanceOneMilli();
runFlow();
assertIcannReportingActivityFieldLogged("srs-cont-update");
}
}
@@ -153,4 +153,10 @@ public class ClaimsCheckFlowTest extends ResourceFlowTestCase<ClaimsCheckFlow, D
thrown.expect(ClaimsPeriodEndedException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-check");
}
}
@@ -701,4 +701,11 @@ public class DomainAllocateFlowTest
thrown.expect(ExceedsMaxRegistrationYearsException.class);
runFlowAsSuperuser();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
setupDomainApplication("tld", TldState.QUIET_PERIOD);
runFlow(CommitMode.LIVE, UserPrivileges.SUPERUSER);
assertIcannReportingActivityFieldLogged("srs-dom-create");
}
}
@@ -1860,4 +1860,12 @@ public class DomainApplicationCreateFlowTest
// ❤☀☆☂☻♞☯.tld
doFailingDomainNameTest("xn--k3hel9n7bxlu1e.tld", InvalidIdnDomainLabelException.class);
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
persistContactsAndHosts();
clock.advanceOneMilli();
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-create");
}
}
@@ -305,4 +305,13 @@ public class DomainApplicationDeleteFlowTest
thrown.expect(ApplicationDomainNameMismatchException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
persistResource(
newDomainApplication("example.tld").asBuilder().setRepoId("1-TLD").build());
clock.advanceOneMilli();
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-delete");
}
}
@@ -357,4 +357,11 @@ public class DomainApplicationInfoFlowTest
.size();
assertThat(numReadsWithContactsOrHosts).isEqualTo(1);
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
persistTestEntities(HostsState.HOSTS_EXIST, MarksState.NO_MARKS_EXIST);
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-info");
}
}
@@ -923,4 +923,13 @@ public class DomainApplicationUpdateFlowTest
thrown.expect(FeesMismatchException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
persistReferencedEntities();
persistApplication();
clock.advanceOneMilli();
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-update");
}
}
@@ -872,4 +872,10 @@ public class DomainCheckFlowTest
// TODO: If at some point we have more than one type of fees that are time dependent, populate
// this test to test if the notAfter date is the earliest of the end points of the ranges.
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-check");
}
}
@@ -1952,4 +1952,11 @@ public class DomainCreateFlowTest extends ResourceFlowTestCase<DomainCreateFlow,
thrown.expect(ExceedsMaxRegistrationYearsException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
persistContactsAndHosts();
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-create");
}
}
@@ -737,4 +737,12 @@ public class DomainDeleteFlowTest extends ResourceFlowTestCase<DomainDeleteFlow,
thrown.expect(OnlyToolCanPassMetadataException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
setupSuccessfulTest();
clock.advanceOneMilli();
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-delete");
}
}
@@ -662,4 +662,11 @@ public class DomainInfoFlowTest extends ResourceFlowTestCase<DomainInfoFlow, Dom
.size();
assertThat(numReadsWithContactsOrHosts).isEqualTo(1);
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
persistTestEntities(false);
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-info");
}
}
@@ -640,4 +640,11 @@ public class DomainRenewFlowTest extends ResourceFlowTestCase<DomainRenewFlow, D
thrown.expect(FeesRequiredForPremiumNameException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
persistDomain();
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-renew");
}
}
@@ -547,4 +547,11 @@ public class DomainRestoreRequestFlowTest extends
thrown.expect(FeesRequiredForPremiumNameException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
persistPendingDeleteDomain();
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-rgp-restore-request");
}
}
@@ -425,4 +425,10 @@ public class DomainTransferApproveFlowTest
// NB: No need to test pending delete status since pending transfers will get cancelled upon
// entering pending delete phase. So it's already handled in that test case.
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-transfer-approve");
}
}
@@ -301,4 +301,11 @@ public class DomainTransferCancelFlowTest
// NB: No need to test pending delete status since pending transfers will get cancelled upon
// entering pending delete phase. So it's already handled in that test case.
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
clock.advanceOneMilli();
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-transfer-cancel");
}
}
@@ -221,4 +221,10 @@ public class DomainTransferQueryFlowTest
String.format("(%s)", getUniqueIdFromCommand()));
doFailingTest("domain_transfer_query.xml");
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-transfer-query");
}
}
@@ -265,4 +265,10 @@ public class DomainTransferRejectFlowTest
// NB: No need to test pending delete status since pending transfers will get cancelled upon
// entering pending delete phase. So it's already handled in that test case.
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-transfer-reject");
}
}
@@ -949,4 +949,12 @@ public class DomainTransferRequestFlowTest
thrown.expect(ResourceStatusProhibitsOperationException.class, "pendingDelete");
doFailingTest("domain_transfer_request.xml");
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
setupDomain("example", "tld");
clock.advanceOneMilli();
runTest("domain_transfer_request.xml", UserPrivileges.NORMAL);
assertIcannReportingActivityFieldLogged("srs-dom-transfer-request");
}
}
@@ -1393,4 +1393,12 @@ public class DomainUpdateFlowTest extends ResourceFlowTestCase<DomainUpdateFlow,
thrown.expect(FeesRequiredForNonFreeOperationException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
persistReferencedEntities();
persistDomain();
runFlow();
assertIcannReportingActivityFieldLogged("srs-dom-update");
}
}
@@ -78,4 +78,10 @@ public class HostCheckFlowTest extends ResourceCheckFlowTestCase<HostCheckFlow,
thrown.expect(TooManyResourceChecksException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
runFlow();
assertIcannReportingActivityFieldLogged("srs-host-check");
}
}
@@ -261,4 +261,10 @@ public class HostCreateFlowTest extends ResourceFlowTestCase<HostCreateFlow, Hos
thrown.expect(HostNameTooShallowException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
runFlow();
assertIcannReportingActivityFieldLogged("srs-host-create");
}
}
@@ -274,4 +274,12 @@ public class HostDeleteFlowTest extends ResourceFlowTestCase<HostDeleteFlow, Hos
thrown.expect(HostNameNotNormalizedException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
persistActiveHost("ns1.example.tld");
clock.advanceOneMilli();
runFlow();
assertIcannReportingActivityFieldLogged("srs-host-delete");
}
}
@@ -179,4 +179,11 @@ public class HostInfoFlowTest extends ResourceFlowTestCase<HostInfoFlow, HostRes
thrown.expect(HostNameNotNormalizedException.class);
runFlow();
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
persistHostResource();
runFlow();
assertIcannReportingActivityFieldLogged("srs-host-info");
}
}
@@ -1224,4 +1224,13 @@ public class HostUpdateFlowTest extends ResourceFlowTestCase<HostUpdateFlow, Hos
.hasMetadataReason("host-update-test").and()
.hasMetadataRequestedByRegistrar(false);
}
@Test
public void testIcannActivityReportField_getsLogged() throws Exception {
createTld("tld");
persistActiveSubordinateHost(oldHostName(), persistActiveDomain("example.tld"));
clock.advanceOneMilli();
runFlow();
assertIcannReportingActivityFieldLogged("srs-host-update");
}
}
@@ -15,16 +15,16 @@
package google.registry.testing;
import static com.google.common.truth.Truth.assertAbout;
import static com.google.common.truth.Truth.assertThat;
import com.google.common.collect.ImmutableList;
import com.google.common.testing.TestLogHandler;
import com.google.common.truth.AbstractVerb.DelegatedVerb;
import com.google.common.truth.Correspondence;
import com.google.common.truth.FailureStrategy;
import com.google.common.truth.StringSubject;
import com.google.common.truth.Subject;
import google.registry.testing.TruthChainer.And;
import google.registry.testing.TruthChainer.Which;
import java.util.List;
import java.util.logging.Handler;
import java.util.logging.Level;
@@ -64,21 +64,27 @@ public class LogsSubject extends Subject<LogsSubject, TestLogHandler> {
return builder.build();
}
public And<LogsSubject> hasNoLogsAtLevel(Level level) {
public void hasNoLogsAtLevel(Level level) {
check()
.withFailureMessage("Logs at level %s", level)
.that(getMessagesAtLevel(level))
.isEmpty();
return new And<>(this);
}
public And<LogsSubject> hasLogAtLevelWithMessage(Level level, String message) {
public Which<StringSubject> hasLogAtLevelWithMessage(Level level, String message) {
List<String> messagesAtLevel = getMessagesAtLevel(level);
check()
.withFailureMessage("Logs at level %s", level)
.that(getMessagesAtLevel(level))
.that(messagesAtLevel)
.comparingElementsUsing(CONTAINS_CORRESPONDENCE)
.contains(message);
return new And<>(this);
for (String messageCandidate : messagesAtLevel) {
if (messageCandidate.contains(message)) {
return new Which<>(assertThat(messageCandidate)
.named(String.format("log message at %s matching '%s'", level, message)));
}
}
throw new AssertionError("Message check passed yet matching message not found");
}
public static DelegatedVerb<LogsSubject, TestLogHandler> assertAboutLogs() {