print why a key was not found when extra verbose

simple logs for simple people. Patch inspired by a bug hunting session with
evan weaver. It's been useful a few times since.

1 files changed, 26 insertions, 0 deletions

diff --git a/items.c b/items.c
index 2cfbae9..1e89f50 100644
--- a/items.c
+++ b/items.c
@@ -496,20 +496,46 @@ char *do_item_stats_sizes(uint32_t (*add_stats)(char *buf,
 /** wrapper around assoc_find which does the lazy expiration logic */
 item *do_item_get(const char *key, const size_t nkey) {
     item *it = assoc_find(key, nkey);
+    int was_found = 0;
+
+    if (settings.verbose > 2) {
+        if (it == NULL) {
+            fprintf(stderr, "> NOT FOUND %s", key);
+        } else {
+            fprintf(stderr, "> FOUND KEY %s", ITEM_key(it));
+            was_found++;
+        }
+    }
+
     if (it != NULL && settings.oldest_live != 0 && settings.oldest_live <= current_time &&
         it->time <= settings.oldest_live) {
         do_item_unlink(it);           /* MTSAFE - cache_lock held */
         it = NULL;
     }
+
+    if (it == NULL && was_found) {
+        fprintf(stderr, " -nuked by flush");
+        was_found--;
+    }
+
     if (it != NULL && it->exptime != 0 && it->exptime <= current_time) {
         do_item_unlink(it);           /* MTSAFE - cache_lock held */
         it = NULL;
     }
 
+    if (it == NULL && was_found) {
+        fprintf(stderr, " -nuked by expire");
+        was_found--;
+    }
+
     if (it != NULL) {
         it->refcount++;
         DEBUG_REFCNT(it, '+');
     }
+
+    if (settings.verbose > 2)
+        fprintf(stderr, "\n");
+
     return it;
 }