From c385fad37df1f17ba06441744f9a42694169e682 Mon Sep 17 00:00:00 2001 From: Sailesh Mukil Date: Tue, 20 Apr 2021 11:52:45 -0700 Subject: [PATCH] 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 --- .../metrics/EVCacheMetricsFactory.java | 1 + .../netflix/evcache/pool/EVCacheClient.java | 3 ++ .../spy/memcached/EVCacheMemcachedClient.java | 42 +++++++++++++------ 3 files changed, 33 insertions(+), 13 deletions(-) diff --git a/evcache-core/src/main/java/com/netflix/evcache/metrics/EVCacheMetricsFactory.java b/evcache-core/src/main/java/com/netflix/evcache/metrics/EVCacheMetricsFactory.java index 3271a981..d08b6535 100644 --- a/evcache-core/src/main/java/com/netflix/evcache/metrics/EVCacheMetricsFactory.java +++ b/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"; diff --git a/evcache-core/src/main/java/com/netflix/evcache/pool/EVCacheClient.java b/evcache-core/src/main/java/com/netflix/evcache/pool/EVCacheClient.java index 0ab01ebe..34cf52a8 100644 --- a/evcache-core/src/main/java/com/netflix/evcache/pool/EVCacheClient.java +++ b/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) { diff --git a/evcache-core/src/main/java/net/spy/memcached/EVCacheMemcachedClient.java b/evcache-core/src/main/java/net/spy/memcached/EVCacheMemcachedClient.java index 4226ccf0..18c8a0f7 100644 --- a/evcache-core/src/main/java/net/spy/memcached/EVCacheMemcachedClient.java +++ b/evcache-core/src/main/java/net/spy/memcached/EVCacheMemcachedClient.java @@ -100,6 +100,22 @@ public GetFuture asyncGet(final String key, final Transcoder 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 EVCacheOperationFuture asyncGet(final String key, final Transcoder tc, EVCacheGetOperationListener listener) { final CountDownLatch latch = new CountDownLatch(1); final EVCacheOperationFuture rv = new EVCacheOperationFuture(key, latch, new AtomicReference(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(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);