Add a metric to track "Wrong key returned" errors

This change adds "wrongKeyReturned" as a metric and increments it
everytime we see it in action.

This change was added as we noticed some of these error messages in
the logs, and we'd like to track the frequence of these errors.

Note that even prior to this change, we did not return the wrong key
back to the calling application but instead count it as a miss.

Print stack trace when we notice a Wrong Key error

Consolidate duplicate code under checkWrongKeyReturned()

Address review comments for wrong key returned metric

- Better logging to catch if returned key is from a different host
- Make sure stack trace goes to logs instead of stdout
- Naming nits addressed

Author: smukil

evcache-core/src/main/java/com/netflix/evcache/metrics/EVCacheMetricsFactory.java

@@ -390,6 +390,7 @@ public String getStatusCode(StatusCode sc) {
     public static final String CHUNK_DATA_SIZE                  = "dataSize";
     public static final String NOT_AVAILABLE                    = "notAvailable";
     public static final String NOT_ACTIVE                       = "notActive";
+    public static final String WRONG_KEY_RETURNED               = "wrongKeyReturned";
 
     public static final String INITIAL                          = "initial";
     public static final String SECOND                           = "second";

evcache-core/src/main/java/com/netflix/evcache/pool/EVCacheClient.java

@@ -259,6 +259,9 @@ private void incrementFailure(String metric, EVCache.Call call, String host) {
         counter.increment();
     }
 
+    public void reportWrongKeyReturned(String hostName) {
+        incrementFailure(EVCacheMetricsFactory.WRONG_KEY_RETURNED, null, hostName);
+    }
 
     private boolean ensureWriteQueueSize(MemcachedNode node, String key, EVCache.Call call) throws EVCacheException {
         if (node instanceof EVCacheNode) {

evcache-core/src/main/java/net/spy/memcached/EVCacheMemcachedClient.java

@@ -100,6 +100,22 @@ public <T> GetFuture<T> asyncGet(final String key, final Transcoder<T> tc) {
         throw new UnsupportedOperationException("asyncGet");
     }
 
+    // Returns 'true' if keys don't match and logs & reports the error.
+    // Returns 'false' if keys match.
+    // TODO: Consider removing this code once we've fixed the Wrong key bug(s)
+    private boolean isWrongKeyReturned(String original_key, String returned_key) {
+        if (!original_key.equals(returned_key)) {
+            // If they keys don't match, log the error along with the key owning host's information and stack trace.
+            final String original_host = getHostNameByKey(original_key);
+            final String returned_host = getHostNameByKey(returned_key);
+            log.error("Wrong key returned. Key - " + original_key + " (Host: " + original_host + ") ; Returned Key "
+                        + returned_key + " (Host: " + returned_host + ")", new Exception());
+            client.reportWrongKeyReturned(original_host);
+            return true;
+        }
+        return false;
+    }
+
     public <T> EVCacheOperationFuture<T> asyncGet(final String key, final Transcoder<T> tc, EVCacheGetOperationListener<T> listener) {
         final CountDownLatch latch = new CountDownLatch(1);
         final EVCacheOperationFuture<T> rv = new EVCacheOperationFuture<T>(key, latch, new AtomicReference<T>(null), readTimeout.get().intValue(), executorService, client);
@@ -126,10 +142,8 @@ public void receivedStatus(OperationStatus status) {
             @SuppressWarnings("unchecked")
             public void gotData(String k, int flags, byte[] data) {
 
-                if (!key.equals(k)) {
-                    log.error("Wrong key returned. Key - " + key + "; Returned Key " + k);
-                    return;
-                }
+                if (isWrongKeyReturned(key, k)) return;
+
                 if (log.isDebugEnabled() && client.getPool().getEVCacheClientPoolManager().shouldLog(appName)) log.debug("Read data : key " + key + "; flags : " + flags + "; data : " + data);
                 if (data != null)  {
                     if (log.isDebugEnabled() && client.getPool().getEVCacheClientPoolManager().shouldLog(appName)) log.debug("Key : " + key + "; val size : " + data.length);
@@ -255,7 +269,8 @@ public void complete() {
             }
 
             public void gotData(String k, int flags, long cas, byte[] data) {
-                if (!key.equals(k)) log.warn("Wrong key returned. Key - " + key + "; Returned Key " + k);
+                if (isWrongKeyReturned(key, k)) return;
+
                 if (data != null) getDataSizeDistributionSummary(EVCacheMetricsFactory.GET_AND_TOUCH_OPERATION, EVCacheMetricsFactory.READ, EVCacheMetricsFactory.IPC_SIZE_INBOUND).record(data.length);
                 val = new CASValue<T>(cas, tc.decode(new CachedData(flags, data, tc.getMaxSize())));
             }
@@ -602,6 +617,11 @@ public int getReadMetricMaxValue() {
         return maxReadDuration.get().intValue();
     }
 
+    private String getHostNameByKey(String key) {
+        MemcachedNode evcNode = getEVCacheNode(key);
+        return getHostName(evcNode.getSocketAddress());
+    }
+
     private String getHostName(SocketAddress sa) {
         if (sa == null) return null;
         if(sa instanceof InetSocketAddress) {
@@ -722,10 +742,8 @@ public void receivedStatus(OperationStatus status) {
             @Override
             public void gotMetaData(String k, char flag, String fVal) {
                 if (log.isDebugEnabled()) log.debug("key " + k + "; val : " + fVal + "; flag : " + flag);
-                if (!key.equals(k)) {
-                    log.error("Wrong key returned. Expected Key - " + key + "; Returned Key " + k);
-                    return;
-                }
+                if (isWrongKeyReturned(key, k)) return;
+
                 switch (flag) {
                 case 's':
                     evItem.getItemMetaData().setSizeInBytes(Integer.parseInt(fVal));
@@ -765,10 +783,8 @@ public void gotMetaData(String k, char flag, String fVal) {
             @Override
             public void gotData(String k, int flag, byte[] data) {
                 if (log.isDebugEnabled() && client.getPool().getEVCacheClientPoolManager().shouldLog(appName)) log.debug("Read data : key " + k + "; flags : " + flag + "; data : " + data);
-                if (!key.equals(k)) {
-                    log.error("Wrong key returned. Expected Key - " + key + "; Returned Key " + k);
-                    return;
-                }
+                if (isWrongKeyReturned(key, k)) return;
+
                 if (data != null)  {
                     if (log.isDebugEnabled() && client.getPool().getEVCacheClientPoolManager().shouldLog(appName)) log.debug("Key : " + k + "; val size : " + data.length);
                     getDataSizeDistributionSummary(EVCacheMetricsFactory.META_GET_OPERATION, EVCacheMetricsFactory.READ, EVCacheMetricsFactory.IPC_SIZE_INBOUND).record(data.length);