BUG-8309: Add message identity information 56/56156/2
authorRobert Varga <robert.varga@pantheon.tech>
Wed, 26 Apr 2017 08:46:15 +0000 (10:46 +0200)
committerTom Pantelis <tompantelis@gmail.com>
Sat, 29 Apr 2017 13:06:01 +0000 (13:06 +0000)
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)

opendaylight/md-sal/cds-access-api/src/main/java/org/opendaylight/controller/cluster/access/commands/AbstractLocalTransactionRequest.java
opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/AbstractClientConnection.java
opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/AbstractReceivingClientConnection.java
opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/ClientActorBehavior.java

index 55225a7..87f59c5 100644 (file)
@@ -31,7 +31,7 @@ abstract class AbstractLocalTransactionRequest<T extends AbstractLocalTransactio
 
     @Override
     protected final AbstractTransactionRequestProxy<T> externalizableProxy(final ABIVersion version) {
 
     @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")
     }
 
     @SuppressWarnings("unchecked")
index 28d8a1b..2423473 100644 (file)
@@ -9,6 +9,8 @@ package org.opendaylight.controller.cluster.access.client;
 
 import akka.actor.ActorRef;
 import com.google.common.annotations.VisibleForTesting;
 
 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;
 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());
         }
     }
             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);
+    }
 }
 }
index 8d9ed24..a27470d 100644 (file)
@@ -7,6 +7,7 @@
  */
 package org.opendaylight.controller.cluster.access.client;
 
  */
 package org.opendaylight.controller.cluster.access.client;
 
+import com.google.common.base.MoreObjects.ToStringHelper;
 import com.google.common.base.Preconditions;
 import java.util.Optional;
 
 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;
     }
     final T backend() {
         return backend;
     }
+
+    @Override
+    ToStringHelper addToStringAttributes(final ToStringHelper toStringHelper) {
+        return super.addToStringAttributes(toStringHelper).add("backend", backend);
+    }
 }
 }
index 5233c07..e70fdc9 100644 (file)
@@ -262,13 +262,13 @@ public abstract class ClientActorBehavior<T extends BackendInfo> extends
             return;
         }
 
             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);
         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));
 
             // 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);
 
             // 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);
         }
         } 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;
     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();
 
         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);
         resolver().refreshBackendInfo(shard, conn.getBackendInfo().get()).whenComplete(
             (backend, failure) -> context().executeInActor(behavior -> {
                 backendConnectFinished(shard, conn, backend, failure);

©2013 OpenDaylight, A Linux Foundation Collaborative Project. All Rights Reserved.
OpenDaylight is a registered trademark of The OpenDaylight Project, Inc.
Linux Foundation and OpenDaylight are registered trademarks of the Linux Foundation.
Linux is a registered trademark of Linus Torvalds.