From 139a84bef6176c2da4b51af8562744d4a0291ebb Mon Sep 17 00:00:00 2001 From: Lai Jiang Date: Thu, 9 Jun 2022 16:56:58 -0400 Subject: [PATCH] Add logging for nameserver deletion (#1663) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The main purpose of this PR is to help debug b/234189023, where a registrar reported that in sandbox they observed seemingly successful EPP update responses to delete NS records, which are not actually deleted after the commands executed. To actually load the persisted domain resource after an update would require us to execute another transaction immediately after the update transaction and that can only be achieved outside the flow (i. e. in FlowRunner or EppController) and we need to test for the type of flows before logging, which seems unnecessarily complex. For now we are just adding logs inside the update transaction itself to validate that: 1. The NS records to delete are as expected. 2. The Current NS records are as expected. 3. The new NS records to persist are as expected. The EPP success reply is the default reply when no errors are thrown in a transaction. If we see a success reply (which means that the transaction finished successfully) and expected logs from the transaction, the only explanation could be that somewhere in the ORM layer the java representation of what the entity is is different from what is being presented to the database. I think that signals a much bigger and fundamental problem, which is quite unlikely given how isolated the issue under consideration is. In any case we would like to add the logging functionality in sandbox and ask the registrar to report again when they see similar issues. Also made some typo and linting fixes. --- This change is [Reviewable](https://reviewable.io/reviews/google/nomulus/1663) --- .../flows/domain/DomainUpdateFlow.java | 21 +++++++++++++++++++ .../model/eppinput/ResourceCommand.java | 12 ++++++----- docs/build.gradle | 1 + 3 files changed, 29 insertions(+), 5 deletions(-) diff --git a/core/src/main/java/google/registry/flows/domain/DomainUpdateFlow.java b/core/src/main/java/google/registry/flows/domain/DomainUpdateFlow.java index a124de9cc..882b26e9b 100644 --- a/core/src/main/java/google/registry/flows/domain/DomainUpdateFlow.java +++ b/core/src/main/java/google/registry/flows/domain/DomainUpdateFlow.java @@ -48,7 +48,9 @@ import com.google.common.collect.ImmutableSet; import com.google.common.collect.ImmutableSortedSet; import com.google.common.collect.Ordering; import com.google.common.collect.Sets; +import com.google.common.flogger.FluentLogger; import com.google.common.net.InternetDomainName; +import google.registry.config.RegistryEnvironment; import google.registry.dns.DnsQueue; import google.registry.flows.EppException; import google.registry.flows.ExtensionManager; @@ -146,6 +148,9 @@ public final class DomainUpdateFlow implements TransactionalFlow { private static final ImmutableSet UPDATE_DISALLOWED_STATUSES = ImmutableSet.of(StatusValue.PENDING_DELETE, StatusValue.SERVER_UPDATE_PROHIBITED); + private static final FluentLogger logger = FluentLogger.forEnclosingClass(); + + private boolean isNsDelete; @Inject ResourceCommand resourceCommand; @Inject ExtensionManager extensionManager; @Inject EppInput eppInput; @@ -200,6 +205,16 @@ public final class DomainUpdateFlow implements TransactionalFlow { EntityChanges.newBuilder().setSaves(entitiesToSave.build()).build()) .build()); persistEntityChanges(entityChanges); + // Ideally we would like to reload the persisted entity and show what is actually persisted, but + // reloading in the current session will only give back the cached version in Hibernate. It is + // impossible to see what is actually persisted in the DB because PSQL doesn't support + // READ_UNCOMMITTED. So even if we call flush here and query with another entitymanager at + // READ_UNCOMMITTED isolation level, PSQL won't show us the new data. Therefore, we have to make + // do with trusting that the to-be-persisted entity is persisted as-is by the transaction + // manager. + if (isNsDelete) { + logger.atInfo().log("Nameservers to persist:\n%s", newDomain.getNameservers()); + } return responseBuilder.build(); } @@ -237,6 +252,12 @@ public final class DomainUpdateFlow implements TransactionalFlow { throws EppException { AddRemove add = command.getInnerAdd(); AddRemove remove = command.getInnerRemove(); + if (RegistryEnvironment.get() != RegistryEnvironment.PRODUCTION + && !remove.getNameservers().isEmpty()) { + isNsDelete = true; + logger.atInfo().log("Current nameservers:\n%s", tm().loadByEntity(domain).getNsHosts()); + logger.atInfo().log("Nameservers to remove:\n%s", remove.getNameservers()); + } checkSameValuesNotAddedAndRemoved(add.getNameservers(), remove.getNameservers()); checkSameValuesNotAddedAndRemoved(add.getContacts(), remove.getContacts()); checkSameValuesNotAddedAndRemoved(add.getStatusValues(), remove.getStatusValues()); diff --git a/core/src/main/java/google/registry/model/eppinput/ResourceCommand.java b/core/src/main/java/google/registry/model/eppinput/ResourceCommand.java index f6158f986..75a115292 100644 --- a/core/src/main/java/google/registry/model/eppinput/ResourceCommand.java +++ b/core/src/main/java/google/registry/model/eppinput/ResourceCommand.java @@ -24,6 +24,7 @@ import google.registry.model.EppResource; import google.registry.model.ImmutableObject; import google.registry.model.eppcommon.AuthInfo; import google.registry.model.eppcommon.StatusValue; +import google.registry.model.eppinput.ResourceCommand.ResourceUpdate.AddRemove; import google.registry.util.TypeUtils.TypeInstantiator; import java.util.List; import java.util.Set; @@ -91,10 +92,11 @@ public interface ResourceCommand { * @param the change type */ @XmlTransient - abstract class ResourceUpdate - , - C extends ResourceCreateOrChange> extends AbstractSingleResourceCommand { + abstract class ResourceUpdate< + A extends AddRemove, + B extends EppResource.Builder, + C extends ResourceCreateOrChange> + extends AbstractSingleResourceCommand { /** Part of an update command that specifies set values to add or remove. */ @XmlTransient @@ -113,7 +115,7 @@ public interface ResourceCommand { protected abstract A getNullableInnerRemove(); - // Don't use MoreObjects.firstNonNull in these method because it will result in an unneeded + // Don't use MoreObjects.firstNonNull in these methods because it will result in an unneeded // reflective instantiation when the object isn't null. public C getInnerChange() { diff --git a/docs/build.gradle b/docs/build.gradle index 7e34a7d57..868d75996 100644 --- a/docs/build.gradle +++ b/docs/build.gradle @@ -16,6 +16,7 @@ dependencies { def deps = rootProject.dependencyMap compile deps['com.beust:jcommander'] + compile deps['com.google.appengine:appengine-api-1.0-sdk'] compile deps['com.google.code.findbugs:jsr305'] compile deps['com.google.flogger:flogger'] compile deps['com.google.guava:guava']