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 <robert.varga@pantheon.tech>
(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 55225a74424c6ea74b0dc0f4ae3c329efcc437c3..87f59c5beabaf57c11afef2d0dccb17b7cdf2191 100644 (file)
--- 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<T extends AbstractLocalTransactio
 
     @Override
     protected final AbstractTransactionRequestProxy<T> 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 28d8a1b42228690177ae9498e7c77dcf518558ce..2423473472301b8b50a77b4758cc3b7eee138f03 100644 (file)
--- 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<T extends BackendInfo> {
             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 8d9ed24043f41758ef461dc29fb74aefe0008373..a27470db8959455182c8705699464e142ff2315d 100644 (file)
--- 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<T extends BackendInfo> 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 5233c0795aee29c8c858c1cb0fd4be44d5ac13ca..e70fdc9662c6232dcc81bda50d95795cca02dbde 100644 (file)
--- 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<T extends BackendInfo> 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<T> 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<T extends BackendInfo> 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<T extends BackendInfo> extends
     void reconnectConnection(final ConnectedClientConnection<?> oldConn,
             final ReconnectingClientConnection<?> newConn) {
         final ReconnectingClientConnection<T> conn = (ReconnectingClientConnection<T>)newConn;
-        connections.replace(oldConn.cookie(), (AbstractClientConnection<T>)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<T>)oldConn, conn);
+        if (!replaced) {
+            final AbstractClientConnection<T> 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);