From c884c6d775f316e0c2962472fd9f9e7a7f86ff32 Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Sun, 18 Nov 2018 23:11:54 -0700 Subject: [PATCH] (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 | 1 + src/cf.data.pre | 17 ++++++ src/ipc/ReadWriteLock.cc | 8 +++ src/ipc/ReadWriteLock.h | 3 ++ src/ipc/StoreMap.cc | 114 +++++++++++++++++++++++++++++++++------ src/ipc/StoreMap.h | 6 ++- 6 files changed, 133 insertions(+), 16 deletions(-) diff --git a/src/SquidConfig.h b/src/SquidConfig.h index 8e72ceda3b0..ecdf35d508f 100644 --- a/src/SquidConfig.h +++ b/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; diff --git a/src/cf.data.pre b/src/cf.data.pre index 1422b23ae38..031ed9ae2b8 100644 --- a/src/cf.data.pre +++ b/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 diff --git a/src/ipc/ReadWriteLock.cc b/src/ipc/ReadWriteLock.cc index 4a0a86e298f..d197bd7af30 100644 --- a/src/ipc/ReadWriteLock.cc +++ b/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 +} diff --git a/src/ipc/ReadWriteLock.h b/src/ipc/ReadWriteLock.h index 1266f912ce4..1c18d3a7f76 100644 --- a/src/ipc/ReadWriteLock.h +++ b/src/ipc/ReadWriteLock.h @@ -52,6 +52,9 @@ class ReadWriteLock std::atomic 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 { diff --git a/src/ipc/StoreMap.cc b/src/ipc/StoreMap.cc index f7320d435a8..42d079daacb 100644 --- a/src/ipc/StoreMap.cc +++ b/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(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) { diff --git a/src/ipc/StoreMap.h b/src/ipc/StoreMap.h index b205aad28b2..0f36abe6a3d 100644 --- a/src/ipc/StoreMap.h +++ b/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);