(Temporary?) added paranoid_hit_validation directive

Collects information about cache hits that would otherwise deliver
corrupted content and prevents such hits from reaching clients. The
client transaction experiences a cache miss instead.

This feature does not protect from corruption that happens while the hit
is being delivered because the validation runs once per client request,
when that client request discovers a cache hit. Future versions may add
more checkpoints.

TODO: Move statistics reporting to cache manager, especially if this
feature becomes permanent.

src/SquidConfig.h

@@ -324,6 +324,7 @@ class SquidConfig
         int httpd_suppress_version_string;
         int global_internal_static;
         int collapsed_forwarding;
+        int paranoid_hit_validation;
 
 #if FOLLOW_X_FORWARDED_FOR
         int acl_uses_indirect_client;

src/cf.data.pre

@@ -4006,6 +4006,23 @@ DOC_START
 		cache_dir rock /ssd3 ... max-size=99999
 DOC_END
 
+NAME: paranoid_hit_validation
+COMMENT: on|off
+TYPE: onoff
+DEFAULT: off
+LOC: Config.onoff.paranoid_hit_validation
+DOC_START
+	Controls whether Squid should perform paranoid validation of
+	cache entry metadata integrity every time a cache entry is hit.
+	Squid bugs notwithstanding, this low-level validation should
+	always succeed. Each failed validation results in a cache miss,
+	a BUG line reported to cache.log, and the invalid entry marked
+	as unusable (and eventually purged from the cache).
+
+	Enabling this feature also results in periodic reports of
+	validation statistics dumped to cache.log.
+DOC_END
+
 NAME: max_open_disk_fds
 TYPE: int
 LOC: Config.max_open_disk_fds

src/ipc/ReadWriteLock.cc

@@ -147,3 +147,11 @@ Ipc::ReadWriteLockStats::dump(StoreEntry &e) const
     }
 }
 
+std::ostream &
+Ipc::operator <<(std::ostream &os, const Ipc::ReadWriteLock &lock)
+{
+	return os << lock.readers << 'R' <<
+		(lock.writing ? "W" : "") <<
+		(lock.appending ? "A" : "");
+	// impossible to report lock.updating without setting/clearing that flag
+}

src/ipc/ReadWriteLock.h

@@ -52,6 +52,9 @@ class ReadWriteLock
     std::atomic<uint32_t> writeLevel; ///< number of users writing (or trying to write)
 };
 
+/// dumps approximate lock state (for debugging)
+std::ostream &operator <<(std::ostream &os, const Ipc::ReadWriteLock &);
+
 /// approximate stats of a set of ReadWriteLocks
 class ReadWriteLockStats
 {

src/ipc/StoreMap.cc

@@ -11,6 +11,7 @@
 #include "squid.h"
 #include "ipc/StoreMap.h"
 #include "sbuf/SBuf.h"
+#include "SquidConfig.h"
 #include "Store.h"
 #include "store_key_md5.h"
 #include "tools.h"
@@ -355,19 +356,15 @@ Ipc::StoreMap::openForReading(const cache_key *const key, sfileno &fileno)
     debugs(54, 5, "opening entry with key " << storeKeyText(key)
            << " for reading " << path);
     const int idx = fileNoByKey(key);
-    if (const Anchor *slot = openForReadingAt(idx)) {
-        if (slot->sameKey(key)) {
-            fileno = idx;
-            return slot; // locked for reading
-        }
-        slot->lock.unlockShared();
-        debugs(54, 7, "closed wrong-key entry " << idx << " for reading " << path);
+    if (const Anchor *slot = openForReadingAt(idx, key)) {
+        fileno = idx;
+        return slot; // locked for reading
     }
     return NULL;
 }
 
 const Ipc::StoreMap::Anchor *
-Ipc::StoreMap::openForReadingAt(const sfileno fileno)
+Ipc::StoreMap::openForReadingAt(const sfileno fileno, const cache_key *const key)
 {
     debugs(54, 5, "opening entry " << fileno << " for reading " << path);
     Anchor &s = anchorAt(fileno);
@@ -392,6 +389,20 @@ Ipc::StoreMap::openForReadingAt(const sfileno fileno)
         return NULL;
     }
 
+    if (!s.sameKey(key)) {
+        s.lock.unlockShared();
+        debugs(54, 5, "cannot open wrong-key entry " << fileno <<
+               " for reading " << path);
+        return nullptr;
+    }
+
+    if (Config.onoff.paranoid_hit_validation && !validateHit(fileno)) {
+        s.lock.unlockShared();
+        debugs(54, 5, "cannot open corrupted entry " << fileno <<
+               " for reading " << path);
+        return nullptr;
+    }
+
     debugs(54, 5, "opened entry " << fileno << " for reading " << path);
     return &s;
 }
@@ -425,13 +436,7 @@ Ipc::StoreMap::openForUpdating(Update &update, const sfileno fileNoHint)
 
     // Unreadable entries cannot (e.g., empty and otherwise problematic entries)
     // or should not (e.g., entries still forming their metadata) be updated.
-    if (const Anchor *anchor = openForReadingAt(update.stale.fileNo)) {
-        if (!anchor->sameKey(key)) {
-            closeForReading(update.stale.fileNo);
-            debugs(54, 5, "cannot open wrong-key entry " << update.stale.fileNo << " for updating " << path);
-            return false;
-        }
-    } else {
+    if (!openForReadingAt(update.stale.fileNo, key)) {
         debugs(54, 5, "cannot open unreadable entry " << update.stale.fileNo << " for updating " << path);
         return false;
     }
@@ -655,6 +660,85 @@ Ipc::StoreMap::validSlice(const int pos) const
     return 0 <= pos && pos < sliceLimit();
 }
 
+bool
+Ipc::StoreMap::validateHit(const sfileno fileno)
+{
+    static uint64_t validationAttempts = 0;
+    static uint64_t validationRefusalsDueToLocking = 0;
+    static uint64_t validationRefusalsDueToZeroSize = 0;
+    static uint64_t validationFailures = 0;
+
+    static time_t reportingGap = 1*60*60; // 1 hour
+    static time_t reportingDeadline = squid_curtime + reportingGap;
+    if (squid_curtime >= reportingDeadline) {
+        reportingDeadline = squid_curtime + reportingGap; // sliding OK
+
+        debugs(54, DBG_IMPORTANT, "FYI: paranoid_hit_validation stats:\n" <<
+               "    attempts=" << validationAttempts << "\n" <<
+               "    refusalsDueToLocking=" << validationRefusalsDueToLocking << "\n" <<
+               "    refusalsDueToZeroSize=" << validationRefusalsDueToZeroSize << "\n" <<
+               "    failures=" << validationFailures << "\n");
+    }
+
+    const auto &anchor = anchorAt(fileno);
+
+    ++validationAttempts;
+
+    if (!anchor.lock.lockHeaders()) {
+        ++validationRefusalsDueToLocking;
+        return true; // presume valid; cannot validate changing entry
+    }
+
+    const uint64_t expectedByteCount = anchor.basics.swap_file_sz;
+
+    size_t actualSliceCount = 0;
+    uint64_t actualByteCount = 0;
+    SliceId lastSeenSlice = anchor.start;
+    while (lastSeenSlice >= 0) {
+        ++actualSliceCount;
+        if (!validSlice(lastSeenSlice))
+            break;
+        const auto &slice = sliceAt(lastSeenSlice);
+        actualByteCount += slice.size;
+        if (actualByteCount > expectedByteCount)
+            break;
+        lastSeenSlice = slice.next;
+    }
+
+    anchor.lock.unlockHeaders();
+
+    if (actualByteCount == expectedByteCount && lastSeenSlice < 0)
+        return true;
+
+    if (!anchor.basics.swap_file_sz) {
+        ++validationRefusalsDueToZeroSize;
+        return true; // presume valid; cannot validate w/o known swap_file_sz
+    }
+
+    ++validationFailures;
+
+    debugs(54, DBG_IMPORTANT, "BUG: purging corrupted cache entry " << fileno <<
+           " from " << path <<
+           " expected swap_file_sz=" << expectedByteCount <<
+           " actual swap_file_sz=" << actualByteCount <<
+           " actual slices=" << actualSliceCount <<
+           " last slice seen=" << lastSeenSlice << "\n" <<
+           "    key=" << storeKeyText(reinterpret_cast<const cache_key*>(anchor.key)) << "\n" <<
+           "    tmestmp=" << anchor.basics.timestamp << "\n" <<
+           "    lastref=" << anchor.basics.lastref << "\n" <<
+           "    expires=" << anchor.basics.expires << "\n" <<
+           "    lastmod=" << anchor.basics.lastmod << "\n" <<
+           "    refcount=" << anchor.basics.refcount << "\n" <<
+           "    flags=0x" << std::hex << anchor.basics.flags << std::dec << "\n" <<
+           "    start=" << anchor.start << "\n" <<
+           "    splicingPoint=" << anchor.splicingPoint << "\n" <<
+           "    lock=" << anchor.lock << "\n" <<
+           "    waitingToBeFreed=" << (anchor.waitingToBeFreed ? 1 : 0) << "\n"
+          );
+    freeEntry(fileno);
+    return false;
+}
+
 Ipc::StoreMap::Anchor&
 Ipc::StoreMap::anchorAt(const sfileno fileno)
 {

src/ipc/StoreMap.h

@@ -256,7 +256,7 @@ class StoreMap
     /// opens entry (identified by key) for reading, increments read level
     const Anchor *openForReading(const cache_key *const key, sfileno &fileno);
     /// opens entry (identified by sfileno) for reading, increments read level
-    const Anchor *openForReadingAt(const sfileno fileno);
+    const Anchor *openForReadingAt(const sfileno, const cache_key *const);
     /// closes open entry after reading, decrements read level
     void closeForReading(const sfileno fileno);
 
@@ -280,6 +280,10 @@ class StoreMap
     /// either finds and frees an entry with at least 1 slice or returns false
     bool purgeOne();
 
+    /// validates locked hit metadata and calls freeEntry() for invalid entries
+    /// \returns whether hit metadata is correct
+    bool validateHit(const sfileno);
+
     /// copies slice to its designated position
     void importSlice(const SliceId sliceId, const Slice &slice);