From bebde36ecb19d816edbf7750785f1f5c8fb59922 Mon Sep 17 00:00:00 2001 From: Sailesh Mukil Date: Tue, 20 Apr 2021 11:52:45 -0700 Subject: [PATCH 1/4] 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. --- .../metrics/EVCacheMetricsFactory.java | 1 + .../netflix/evcache/pool/EVCacheClient.java | 3 +++ .../spy/memcached/EVCacheMemcachedClient.java | 27 ++++++++++++++++--- 3 files changed, 27 insertions(+), 4 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..a9b4283a 100644 --- a/evcache-core/src/main/java/net/spy/memcached/EVCacheMemcachedClient.java +++ b/evcache-core/src/main/java/net/spy/memcached/EVCacheMemcachedClient.java @@ -127,7 +127,10 @@ public void receivedStatus(OperationStatus status) { public void gotData(String k, int flags, byte[] data) { if (!key.equals(k)) { - log.error("Wrong key returned. Key - " + key + "; Returned Key " + k); + // If they keys don't match, log the error along with the key owning host information. + final String host = getHostNameByKey(k); + log.error("Wrong key returned. Key - " + key + "; Returned Key " + k + "; Host" + host); + client.reportWrongKeyReturned(host); return; } if (log.isDebugEnabled() && client.getPool().getEVCacheClientPoolManager().shouldLog(appName)) log.debug("Read data : key " + key + "; flags : " + flags + "; data : " + data); @@ -255,7 +258,12 @@ 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 (!key.equals(k)) { + // If they keys don't match, log the error along with the key owning host information. + final String host = getHostNameByKey(k); + log.error("Wrong key returned. Key - " + key + "; Returned Key " + k + "; Host" + host); + client.reportWrongKeyReturned(host); + } 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 +610,11 @@ public int getReadMetricMaxValue() { return maxReadDuration.get().intValue(); } + private String getHostNameByKey(String key) { + EVCacheNode evcNode = (EVCacheNode)getEVCacheNode(key); + return getHostName(evcNode.getSocketAddress()); + } + private String getHostName(SocketAddress sa) { if (sa == null) return null; if(sa instanceof InetSocketAddress) { @@ -723,7 +736,10 @@ public void receivedStatus(OperationStatus status) { 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); + // If they keys don't match, log the error along with the key owning host information. + final String host = getHostNameByKey(k); + log.error("Wrong key returned. Key - " + key + "; Returned Key " + k + "; Host" + host); + client.reportWrongKeyReturned(host); return; } switch (flag) { @@ -766,7 +782,10 @@ public void gotMetaData(String k, char flag, String fVal) { 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); + // If they keys don't match, log the error along with the key owning host information. + final String host = getHostNameByKey(k); + log.error("Wrong key returned. Key - " + key + "; Returned Key " + k + "; Host" + host); + client.reportWrongKeyReturned(host); return; } if (data != null) { From 43dc45f9d821609b7af77326f96e1366da23e589 Mon Sep 17 00:00:00 2001 From: Sailesh Mukil Date: Tue, 20 Apr 2021 12:15:12 -0700 Subject: [PATCH 2/4] Print stack trace when we notice a Wrong Key error --- .../net/spy/memcached/EVCacheMemcachedClient.java | 12 ++++++++++++ 1 file changed, 12 insertions(+) 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 a9b4283a..c798d19b 100644 --- a/evcache-core/src/main/java/net/spy/memcached/EVCacheMemcachedClient.java +++ b/evcache-core/src/main/java/net/spy/memcached/EVCacheMemcachedClient.java @@ -130,6 +130,9 @@ public void gotData(String k, int flags, byte[] data) { // If they keys don't match, log the error along with the key owning host information. final String host = getHostNameByKey(k); log.error("Wrong key returned. Key - " + key + "; Returned Key " + k + "; Host" + host); + // Print stack trace for debugging purposes. + // TODO: Consider removing this code once we've fixed the Wrong key bug(s) + new Throwable().printStackTrace(); client.reportWrongKeyReturned(host); return; } @@ -262,6 +265,9 @@ public void gotData(String k, int flags, long cas, byte[] data) { // If they keys don't match, log the error along with the key owning host information. final String host = getHostNameByKey(k); log.error("Wrong key returned. Key - " + key + "; Returned Key " + k + "; Host" + host); + // Print stack trace for debugging purposes. + // TODO: Consider removing this code once we've fixed the Wrong key bug(s) + new Throwable().printStackTrace(); client.reportWrongKeyReturned(host); } if (data != null) getDataSizeDistributionSummary(EVCacheMetricsFactory.GET_AND_TOUCH_OPERATION, EVCacheMetricsFactory.READ, EVCacheMetricsFactory.IPC_SIZE_INBOUND).record(data.length); @@ -739,6 +745,9 @@ public void gotMetaData(String k, char flag, String fVal) { // If they keys don't match, log the error along with the key owning host information. final String host = getHostNameByKey(k); log.error("Wrong key returned. Key - " + key + "; Returned Key " + k + "; Host" + host); + // Print stack trace for debugging purposes. + // TODO: Consider removing this code once we've fixed the Wrong key bug(s) + new Throwable().printStackTrace(); client.reportWrongKeyReturned(host); return; } @@ -785,6 +794,9 @@ public void gotData(String k, int flag, byte[] data) { // If they keys don't match, log the error along with the key owning host information. final String host = getHostNameByKey(k); log.error("Wrong key returned. Key - " + key + "; Returned Key " + k + "; Host" + host); + // Print stack trace for debugging purposes. + // TODO: Consider removing this code once we've fixed the Wrong key bug(s) + new Throwable().printStackTrace(); client.reportWrongKeyReturned(host); return; } From 81ab1cbf837e0538fbe734d30c9d8764dab760d0 Mon Sep 17 00:00:00 2001 From: Sailesh Mukil Date: Wed, 21 Apr 2021 10:43:41 -0700 Subject: [PATCH 3/4] Consolidate duplicate code under checkWrongKeyReturned() --- .../spy/memcached/EVCacheMemcachedClient.java | 64 ++++++++----------- 1 file changed, 25 insertions(+), 39 deletions(-) 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 c798d19b..21d95613 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. + private boolean checkWrongKeyReturned(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 information. + final String host = getHostNameByKey(returned_key); + log.error("Wrong key returned. Key - " + original_key + "; Returned Key " + returned_key + "; Host" + host); + // Print stack trace for debugging purposes. + // TODO: Consider removing this code once we've fixed the Wrong key bug(s) + new Throwable().printStackTrace(); + client.reportWrongKeyReturned(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,16 +142,8 @@ public void receivedStatus(OperationStatus status) { @SuppressWarnings("unchecked") public void gotData(String k, int flags, byte[] data) { - if (!key.equals(k)) { - // If they keys don't match, log the error along with the key owning host information. - final String host = getHostNameByKey(k); - log.error("Wrong key returned. Key - " + key + "; Returned Key " + k + "; Host" + host); - // Print stack trace for debugging purposes. - // TODO: Consider removing this code once we've fixed the Wrong key bug(s) - new Throwable().printStackTrace(); - client.reportWrongKeyReturned(host); - return; - } + if (checkWrongKeyReturned(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); @@ -261,15 +269,9 @@ public void complete() { } public void gotData(String k, int flags, long cas, byte[] data) { - if (!key.equals(k)) { - // If they keys don't match, log the error along with the key owning host information. - final String host = getHostNameByKey(k); - log.error("Wrong key returned. Key - " + key + "; Returned Key " + k + "; Host" + host); - // Print stack trace for debugging purposes. - // TODO: Consider removing this code once we've fixed the Wrong key bug(s) - new Throwable().printStackTrace(); - client.reportWrongKeyReturned(host); - } + // TODO: Should we return here if wrong key is returned? We seem to do so everywhere else except here. + checkWrongKeyReturned(key, k); + 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()))); } @@ -741,16 +743,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)) { - // If they keys don't match, log the error along with the key owning host information. - final String host = getHostNameByKey(k); - log.error("Wrong key returned. Key - " + key + "; Returned Key " + k + "; Host" + host); - // Print stack trace for debugging purposes. - // TODO: Consider removing this code once we've fixed the Wrong key bug(s) - new Throwable().printStackTrace(); - client.reportWrongKeyReturned(host); - return; - } + if (checkWrongKeyReturned(key, k)) return; + switch (flag) { case 's': evItem.getItemMetaData().setSizeInBytes(Integer.parseInt(fVal)); @@ -790,16 +784,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)) { - // If they keys don't match, log the error along with the key owning host information. - final String host = getHostNameByKey(k); - log.error("Wrong key returned. Key - " + key + "; Returned Key " + k + "; Host" + host); - // Print stack trace for debugging purposes. - // TODO: Consider removing this code once we've fixed the Wrong key bug(s) - new Throwable().printStackTrace(); - client.reportWrongKeyReturned(host); - return; - } + if (checkWrongKeyReturned(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); From 7706be4d833ab3ea954ac2f889ae2ea8e5b8e4b0 Mon Sep 17 00:00:00 2001 From: Sailesh Mukil Date: Fri, 23 Apr 2021 15:13:48 -0700 Subject: [PATCH 4/4] 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 --- .../spy/memcached/EVCacheMemcachedClient.java | 27 +++++++++---------- 1 file changed, 13 insertions(+), 14 deletions(-) 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 21d95613..18c8a0f7 100644 --- a/evcache-core/src/main/java/net/spy/memcached/EVCacheMemcachedClient.java +++ b/evcache-core/src/main/java/net/spy/memcached/EVCacheMemcachedClient.java @@ -102,15 +102,15 @@ public GetFuture asyncGet(final String key, final Transcoder tc) { // Returns 'true' if keys don't match and logs & reports the error. // Returns 'false' if keys match. - private boolean checkWrongKeyReturned(String original_key, String returned_key) { + // 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 information. - final String host = getHostNameByKey(returned_key); - log.error("Wrong key returned. Key - " + original_key + "; Returned Key " + returned_key + "; Host" + host); - // Print stack trace for debugging purposes. - // TODO: Consider removing this code once we've fixed the Wrong key bug(s) - new Throwable().printStackTrace(); - client.reportWrongKeyReturned(host); + // 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; @@ -142,7 +142,7 @@ public void receivedStatus(OperationStatus status) { @SuppressWarnings("unchecked") public void gotData(String k, int flags, byte[] data) { - if (checkWrongKeyReturned(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) { @@ -269,8 +269,7 @@ public void complete() { } public void gotData(String k, int flags, long cas, byte[] data) { - // TODO: Should we return here if wrong key is returned? We seem to do so everywhere else except here. - checkWrongKeyReturned(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()))); @@ -619,7 +618,7 @@ public int getReadMetricMaxValue() { } private String getHostNameByKey(String key) { - EVCacheNode evcNode = (EVCacheNode)getEVCacheNode(key); + MemcachedNode evcNode = getEVCacheNode(key); return getHostName(evcNode.getSocketAddress()); } @@ -743,7 +742,7 @@ 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 (checkWrongKeyReturned(key, k)) return; + if (isWrongKeyReturned(key, k)) return; switch (flag) { case 's': @@ -784,7 +783,7 @@ 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 (checkWrongKeyReturned(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);