From: Robert Varga Date: Wed, 26 Apr 2017 08:46:15 +0000 (+0200) Subject: BUG-8309: Add message identity information X-Git-Tag: release/nitrogen~303 X-Git-Url: https://git.opendaylight.org/gerrit/gitweb?p=controller.git;a=commitdiff_plain;h=3488960e844918404db473ee684661f98dab3563 BUG-8309: Add message identity information We have encountered an attempt to serialize a local request across a remote connection. Since this is hit by the akka serializer, we have lost the identity of the call site and of the message, because all akka is seeing is the Envelope and the exception's stack trace, which only indicates class hierarchy up to and including AbstractLocalTransactionRequest. This patch enriches the exception message so we know what the actual request was, hopefully pinpointing the offending call site. Since the problem revolves around the reconnect process, bump critical transitions to info instead of debug. Change-Id: I6d6d6e702d4b5baff7b707242583e923708e7637 Signed-off-by: Robert Varga (cherry picked from commit 4ec6c11c03ae92e11a7cea29795e4b7f5547f64e) --- diff --git a/opendaylight/md-sal/cds-access-api/src/main/java/org/opendaylight/controller/cluster/access/commands/AbstractLocalTransactionRequest.java b/opendaylight/md-sal/cds-access-api/src/main/java/org/opendaylight/controller/cluster/access/commands/AbstractLocalTransactionRequest.java index 55225a7442..87f59c5bea 100644 --- a/opendaylight/md-sal/cds-access-api/src/main/java/org/opendaylight/controller/cluster/access/commands/AbstractLocalTransactionRequest.java +++ b/opendaylight/md-sal/cds-access-api/src/main/java/org/opendaylight/controller/cluster/access/commands/AbstractLocalTransactionRequest.java @@ -31,7 +31,7 @@ abstract class AbstractLocalTransactionRequest externalizableProxy(final ABIVersion version) { - throw new UnsupportedOperationException("Local transaction request should never be serialized"); + throw new UnsupportedOperationException("Local transaction request " + this + " should never be serialized"); } @SuppressWarnings("unchecked") diff --git a/opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/AbstractClientConnection.java b/opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/AbstractClientConnection.java index 28d8a1b422..2423473472 100644 --- a/opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/AbstractClientConnection.java +++ b/opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/AbstractClientConnection.java @@ -9,6 +9,8 @@ package org.opendaylight.controller.cluster.access.client; import akka.actor.ActorRef; import com.google.common.annotations.VisibleForTesting; +import com.google.common.base.MoreObjects; +import com.google.common.base.MoreObjects.ToStringHelper; import com.google.common.base.Preconditions; import edu.umd.cs.findbugs.annotations.SuppressFBWarnings; import java.util.Optional; @@ -298,4 +300,13 @@ public abstract class AbstractClientConnection { entry.complete(envelope.getMessage()); } } + + @Override + public final String toString() { + return addToStringAttributes(MoreObjects.toStringHelper(this).omitNullValues()).toString(); + } + + ToStringHelper addToStringAttributes(final ToStringHelper toStringHelper) { + return toStringHelper.add("client", context.getIdentifier()).add("cookie", cookie).add("poisoned", poisoned); + } } diff --git a/opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/AbstractReceivingClientConnection.java b/opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/AbstractReceivingClientConnection.java index 8d9ed24043..a27470db89 100644 --- a/opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/AbstractReceivingClientConnection.java +++ b/opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/AbstractReceivingClientConnection.java @@ -7,6 +7,7 @@ */ package org.opendaylight.controller.cluster.access.client; +import com.google.common.base.MoreObjects.ToStringHelper; import com.google.common.base.Preconditions; import java.util.Optional; @@ -56,4 +57,9 @@ abstract class AbstractReceivingClientConnection extends final T backend() { return backend; } + + @Override + ToStringHelper addToStringAttributes(final ToStringHelper toStringHelper) { + return super.addToStringAttributes(toStringHelper).add("backend", backend); + } } diff --git a/opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/ClientActorBehavior.java b/opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/ClientActorBehavior.java index 5233c0795a..e70fdc9662 100644 --- a/opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/ClientActorBehavior.java +++ b/opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/ClientActorBehavior.java @@ -262,13 +262,13 @@ public abstract class ClientActorBehavior extends return; } - LOG.debug("{}: resolved shard {} to {}", persistenceId(), shard, backend); + LOG.info("{}: resolved shard {} to {}", persistenceId(), shard, backend); final long stamp = connectionsLock.writeLock(); try { // Create a new connected connection final ConnectedClientConnection newConn = new ConnectedClientConnection<>(conn.context(), conn.cookie(), backend); - LOG.debug("{}: resolving connection {} to {}", persistenceId(), conn, newConn); + LOG.info("{}: resolving connection {} to {}", persistenceId(), conn, newConn); // Start reconnecting without the old connection lock held final ConnectionConnectCohort cohort = Verify.verifyNotNull(connectionUp(newConn)); @@ -284,7 +284,7 @@ public abstract class ClientActorBehavior extends // Make sure new lookups pick up the new connection connections.replace(shard, conn, newConn); - LOG.debug("{}: replaced connection {} with {}", persistenceId(), conn, newConn); + LOG.info("{}: replaced connection {} with {}", persistenceId(), conn, newConn); } finally { connectionsLock.unlockWrite(stamp); } @@ -299,10 +299,17 @@ public abstract class ClientActorBehavior extends void reconnectConnection(final ConnectedClientConnection oldConn, final ReconnectingClientConnection newConn) { final ReconnectingClientConnection conn = (ReconnectingClientConnection)newConn; - connections.replace(oldConn.cookie(), (AbstractClientConnection)oldConn, conn); - LOG.debug("{}: connection {} reconnecting as {}", persistenceId(), oldConn, newConn); + LOG.info("{}: connection {} reconnecting as {}", persistenceId(), oldConn, newConn); + + final boolean replaced = connections.replace(oldConn.cookie(), (AbstractClientConnection)oldConn, conn); + if (!replaced) { + final AbstractClientConnection existing = connections.get(oldConn.cookie()); + LOG.warn("{}: old connection {} does not match existing {}, new connection {} in limbo", persistenceId(), + oldConn, existing, newConn); + } final Long shard = oldConn.cookie(); + LOG.info("{}: refreshing backend for shard {}", persistenceId(), shard); resolver().refreshBackendInfo(shard, conn.getBackendInfo().get()).whenComplete( (backend, failure) -> context().executeInActor(behavior -> { backendConnectFinished(shard, conn, backend, failure);