From b2aca62a222cafc8cffd4b1d09a5e1fd104d7612 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Mon, 9 Mar 2020 19:29:04 +0000 Subject: [PATCH] paranoid_hit_validation directive (#559) This directive controls whether Squid should perform paranoid validation of cache entry metadata integrity every time a cache entry is hit. The client transaction experiences a cache miss instead. This feature does not protect from the 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. The paranoid hit validation statistics are available by means of several new cache manager counters, available by mgr:counters, mgr:5min and mgr:60min requests. The statistics are reported only when paranoid_hit_validation is enabled. --- src/SquidConfig.h | 4 ++ src/StatCounters.h | 9 +++ src/Transients.cc | 1 + src/cache_cf.cc | 3 - src/cf.data.depend | 1 + src/cf.data.pre | 39 +++++++++++ src/ipc/ReadWriteLock.cc | 9 +++ src/ipc/ReadWriteLock.h | 4 ++ src/ipc/StoreMap.cc | 142 +++++++++++++++++++++++++++++++++----- src/ipc/StoreMap.h | 11 ++- src/mgr/CountersAction.cc | 5 ++ src/mgr/CountersAction.h | 5 ++ src/mgr/IntervalAction.cc | 5 ++ src/mgr/IntervalAction.h | 5 ++ src/stat.cc | 34 +++++++++ 15 files changed, 257 insertions(+), 20 deletions(-) diff --git a/src/SquidConfig.h b/src/SquidConfig.h index bb96f3320d..91bb22f7b6 100644 --- a/src/SquidConfig.h +++ b/src/SquidConfig.h @@ -31,6 +31,8 @@ #include "store/Disk.h" #include "store/forward.h" +#include + #if USE_OPENSSL class sslproxy_cert_sign; class sslproxy_cert_adapt; @@ -352,6 +354,8 @@ public: int forward_max_tries; int connect_retries; + std::chrono::nanoseconds paranoid_hit_validation; + class ACL *aclList; struct { diff --git a/src/StatCounters.h b/src/StatCounters.h index 01bf36dcc3..efc53a0578 100644 --- a/src/StatCounters.h +++ b/src/StatCounters.h @@ -156,6 +156,15 @@ public: int outs = 0; int ins = 0; } swap; + + struct { + uint64_t attempts = 0; + uint64_t refusalsDueToLocking = 0; + uint64_t refusalsDueToZeroSize = 0; + uint64_t refusalsDueToTimeLimit = 0; + uint64_t failures = 0; + } hitValidation; + }; extern StatCounters statCounter; diff --git a/src/Transients.cc b/src/Transients.cc index 652cdc1dd4..4394ae9892 100644 --- a/src/Transients.cc +++ b/src/Transients.cc @@ -47,6 +47,7 @@ Transients::init() Must(!map); map = new TransientsMap(MapLabel); map->cleaner = this; + map->disableHitValidation(); // Transients lacks slices to validate locals = new Locals(entryLimit, 0); } diff --git a/src/cache_cf.cc b/src/cache_cf.cc index ff90b9f55b..fe6b5822c2 100644 --- a/src/cache_cf.cc +++ b/src/cache_cf.cc @@ -3069,8 +3069,6 @@ free_time_msec(time_msec_t * var) *var = 0; } -#if UNUSED_CODE -// TODO: add a parameter with 'time_nanoseconds' TYPE and uncomment static void dump_time_nanoseconds(StoreEntry *entry, const char *name, const std::chrono::nanoseconds &var) { @@ -3088,7 +3086,6 @@ free_time_nanoseconds(std::chrono::nanoseconds *var) { *var = std::chrono::nanoseconds::zero(); } -#endif #if UNUSED_CODE static void diff --git a/src/cf.data.depend b/src/cf.data.depend index 2dc12a1377..f768a7a7bd 100644 --- a/src/cf.data.depend +++ b/src/cf.data.depend @@ -79,6 +79,7 @@ string string time_msec time_t +time_nanoseconds tristate uri_whitespace UrlHelperTimeout acl diff --git a/src/cf.data.pre b/src/cf.data.pre index cbff8af34e..ebd7015819 100644 --- a/src/cf.data.pre +++ b/src/cf.data.pre @@ -4413,6 +4413,45 @@ DOC_START cache_dir rock /ssd3 ... max-size=99999 DOC_END +NAME: paranoid_hit_validation +COMMENT: time-units-small +TYPE: time_nanoseconds +DEFAULT: 0 +DEFAULT_DOC: validation disabled +LOC: Config.paranoid_hit_validation +DOC_START + Controls whether Squid should perform paranoid validation of cache entry + metadata integrity every time a cache entry is hit. 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). + + Squid can only validate shared cache memory and rock cache_dir entries. + + * Zero (default) value means that the validation is disabled. + + * Positive values enable validation: + - values less than 1 day approximate the maximum time that Squid is allowed + to spend validating a single cache hit. + - values greater or equal to 1 day are considered as no limitation: + in this case all checks will be performed, regardless of how much time + they take. + + Hits are usually stored using 16KB slots (for rock, the size is + configurable via cache_dir slot-size). Larger hits require scanning more + slots and, hence, take more time. When validation is enabled, at least one + slot is always validated, regardless of the configured time limit. + + A worker process validating an entry cannot do anything else (i.e. the + validation is blocking). The validation overhead is environment dependent, + but developers have observed Squid spending 3-10 microseconds to check each + slot of a Rock or shared memory hit entry. If Squid cuts validation short + because it runs out of configured time, it treats the entry as valid. + + When hit validation is enabled, its statistics is included in Cache + Manager mgr:counters, mgr:5min, and mgr:60min reports. +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 dbeabad69c..efda6d8d7d 100644 --- a/src/ipc/ReadWriteLock.cc +++ b/src/ipc/ReadWriteLock.cc @@ -167,3 +167,12 @@ 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 75cddee3e8..3233882255 100644 --- a/src/ipc/ReadWriteLock.h +++ b/src/ipc/ReadWriteLock.h @@ -10,6 +10,7 @@ #define SQUID_IPC_READ_WRITE_LOCK_H #include +#include class StoreEntry; @@ -55,6 +56,9 @@ private: 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 184ece5510..73254d1e11 100644 --- a/src/ipc/StoreMap.cc +++ b/src/ipc/StoreMap.cc @@ -11,11 +11,15 @@ #include "squid.h" #include "ipc/StoreMap.h" #include "sbuf/SBuf.h" +#include "SquidConfig.h" +#include "StatCounters.h" #include "Store.h" #include "store/Controller.h" #include "store_key_md5.h" #include "tools.h" +#include + static SBuf StoreMapSlicesId(const SBuf &path) { @@ -50,7 +54,8 @@ Ipc::StoreMap::Init(const SBuf &path, const int sliceLimit) Ipc::StoreMap::StoreMap(const SBuf &aPath): cleaner(NULL), path(aPath), fileNos(shm_old(FileNos)(StoreMapFileNosId(path).c_str())), anchors(shm_old(Anchors)(StoreMapAnchorsId(path).c_str())), - slices(shm_old(Slices)(StoreMapSlicesId(path).c_str())) + slices(shm_old(Slices)(StoreMapSlicesId(path).c_str())), + hitValidation(true) { debugs(54, 5, "attached " << path << " with " << fileNos->capacity << '+' << @@ -400,19 +405,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 auto anchor = openForReadingAt(idx, key)) { + fileno = idx; + return anchor; // 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); @@ -437,6 +438,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.paranoid_hit_validation.count() && hitValidation && !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; } @@ -487,13 +502,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; } @@ -720,6 +729,107 @@ Ipc::StoreMap::validSlice(const int pos) const return 0 <= pos && pos < sliceLimit(); } +/// Checks whether the object lifetime has exceeded the specified maximum. +/// The lifetime is considered to exceed the maximum if the time goes backwards. +/// Uses the highest precision provided by the C++ implementation. +class ConservativeTimer +{ +public: + typedef std::chrono::high_resolution_clock Clock; + + explicit ConservativeTimer(const Clock::duration max): + startTime(Clock::now()), + lastTime(startTime), + maxTime(startTime + max) {} + + /// whether the current time reached the provided maximum time + bool expired() { + const auto currentTime = Clock::now(); + if (currentTime < lastTime) // time went backwards + return true; + lastTime = currentTime; + return lastTime > maxTime; + } + +private: + /// the object creation time + Clock::time_point startTime; + /// the time of the last expired() call, initially equals to startTime + Clock::time_point lastTime; + /// after going past this point in time, expired() becomes true + const Clock::time_point maxTime; +}; + +bool +Ipc::StoreMap::validateHit(const sfileno fileno) +{ + ConservativeTimer timer(Config.paranoid_hit_validation); + const auto timeIsLimited = Config.paranoid_hit_validation < std::chrono::hours(24); + + const auto &anchor = anchorAt(fileno); + + ++statCounter.hitValidation.attempts; + + if (!anchor.basics.swap_file_sz) { + ++statCounter.hitValidation.refusalsDueToZeroSize; + return true; // presume valid; cannot validate w/o known swap_file_sz + } + + if (!anchor.lock.lockHeaders()) { + ++statCounter.hitValidation.refusalsDueToLocking; + 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; + if (timeIsLimited && timer.expired()) { + anchor.lock.unlockHeaders(); + ++statCounter.hitValidation.refusalsDueToTimeLimit; + return true; + } + } + + anchor.lock.unlockHeaders(); + + if (actualByteCount == expectedByteCount && lastSeenSlice < 0) + return true; + + ++statCounter.hitValidation.failures; + + 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 c4224f2842..b499fff0b0 100644 --- a/src/ipc/StoreMap.h +++ b/src/ipc/StoreMap.h @@ -288,7 +288,7 @@ public: /// 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); /// same as closeForReading() but also frees the entry if it is unlocked @@ -317,6 +317,12 @@ public: /// 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); + + void disableHitValidation() { hitValidation = false; } + /// copies slice to its designated position void importSlice(const SliceId sliceId, const Slice &slice); @@ -360,6 +366,9 @@ private: void freeChain(const sfileno fileno, Anchor &inode, const bool keepLock); void freeChainAt(SliceId sliceId, const SliceId splicingPoint); + + /// whether paranoid_hit_validation should be performed + bool hitValidation; }; /// API for adjusting external state when dirty map slice is being freed diff --git a/src/mgr/CountersAction.cc b/src/mgr/CountersAction.cc index ffc3ee6613..2d13848581 100644 --- a/src/mgr/CountersAction.cc +++ b/src/mgr/CountersAction.cc @@ -85,6 +85,11 @@ Mgr::CountersActionData::operator += (const CountersActionData& stats) swap_ins += stats.swap_ins; swap_files_cleaned += stats.swap_files_cleaned; aborted_requests += stats.aborted_requests; + hitValidationAttempts += stats.hitValidationAttempts; + hitValidationRefusalsDueToLocking += stats.hitValidationRefusalsDueToLocking; + hitValidationRefusalsDueToZeroSize += stats.hitValidationRefusalsDueToZeroSize; + hitValidationRefusalsDueToTimeLimit += stats.hitValidationRefusalsDueToTimeLimit; + hitValidationFailures += stats.hitValidationFailures; return *this; } diff --git a/src/mgr/CountersAction.h b/src/mgr/CountersAction.h index b961824571..db2224498a 100644 --- a/src/mgr/CountersAction.h +++ b/src/mgr/CountersAction.h @@ -80,6 +80,11 @@ public: double swap_ins; double swap_files_cleaned; double aborted_requests; + double hitValidationAttempts; + double hitValidationRefusalsDueToLocking; + double hitValidationRefusalsDueToZeroSize; + double hitValidationRefusalsDueToTimeLimit; + double hitValidationFailures; }; /// implement aggregated 'counters' action diff --git a/src/mgr/IntervalAction.cc b/src/mgr/IntervalAction.cc index ce6ec8b749..13bfc4b862 100644 --- a/src/mgr/IntervalAction.cc +++ b/src/mgr/IntervalAction.cc @@ -85,6 +85,11 @@ Mgr::IntervalActionData::operator += (const IntervalActionData& stats) swap_ins += stats.swap_ins; swap_files_cleaned += stats.swap_files_cleaned; aborted_requests += stats.aborted_requests; + hitValidationAttempts += stats.hitValidationAttempts; + hitValidationRefusalsDueToLocking += stats.hitValidationRefusalsDueToLocking; + hitValidationRefusalsDueToZeroSize += stats.hitValidationRefusalsDueToZeroSize; + hitValidationRefusalsDueToTimeLimit += stats.hitValidationRefusalsDueToTimeLimit; + hitValidationFailures += stats.hitValidationFailures; syscalls_disk_opens += stats.syscalls_disk_opens; syscalls_disk_closes += stats.syscalls_disk_closes; syscalls_disk_reads += stats.syscalls_disk_reads; diff --git a/src/mgr/IntervalAction.h b/src/mgr/IntervalAction.h index 7b642aed6a..67a60369c7 100644 --- a/src/mgr/IntervalAction.h +++ b/src/mgr/IntervalAction.h @@ -80,6 +80,11 @@ public: double swap_ins; double swap_files_cleaned; double aborted_requests; + double hitValidationAttempts; + double hitValidationRefusalsDueToLocking; + double hitValidationRefusalsDueToZeroSize; + double hitValidationRefusalsDueToTimeLimit; + double hitValidationFailures; double syscalls_disk_opens; double syscalls_disk_closes; double syscalls_disk_reads; diff --git a/src/stat.cc b/src/stat.cc index fa1114d069..ca803396a9 100644 --- a/src/stat.cc +++ b/src/stat.cc @@ -995,6 +995,12 @@ GetAvgStat(Mgr::IntervalActionData& stats, int minutes, int hours) stats.swap_files_cleaned = XAVG(swap.files_cleaned); stats.aborted_requests = XAVG(aborted_requests); + stats.hitValidationAttempts = XAVG(hitValidation.attempts); + stats.hitValidationRefusalsDueToLocking = XAVG(hitValidation.refusalsDueToLocking); + stats.hitValidationRefusalsDueToZeroSize = XAVG(hitValidation.refusalsDueToZeroSize); + stats.hitValidationRefusalsDueToTimeLimit = XAVG(hitValidation.refusalsDueToTimeLimit); + stats.hitValidationFailures = XAVG(hitValidation.failures); + stats.syscalls_disk_opens = XAVG(syscalls.disk.opens); stats.syscalls_disk_closes = XAVG(syscalls.disk.closes); stats.syscalls_disk_reads = XAVG(syscalls.disk.reads); @@ -1142,6 +1148,17 @@ DumpAvgStat(Mgr::IntervalActionData& stats, StoreEntry* sentry) storeAppendPrintf(sentry, "aborted_requests = %f/sec\n", stats.aborted_requests); + storeAppendPrintf(sentry, "hit_validation.attempts = %f/sec\n", + stats.hitValidationAttempts); + storeAppendPrintf(sentry, "hit_validation.refusals.due_to_locking = %f/sec\n", + stats.hitValidationRefusalsDueToLocking); + storeAppendPrintf(sentry, "hit_validation.refusals.due_to_zeroSize = %f/sec\n", + stats.hitValidationRefusalsDueToZeroSize); + storeAppendPrintf(sentry, "hit_validation.refusals.due_to_timeLimit = %f/sec\n", + stats.hitValidationRefusalsDueToTimeLimit); + storeAppendPrintf(sentry, "hit_validation.failures = %f/sec\n", + stats.hitValidationFailures); + #if USE_POLL storeAppendPrintf(sentry, "syscalls.polls = %f/sec\n", stats.syscalls_selects); #elif defined(USE_SELECT) || defined(USE_SELECT_WIN32) @@ -1436,6 +1453,12 @@ GetCountersStats(Mgr::CountersActionData& stats) stats.swap_ins = f->swap.ins; stats.swap_files_cleaned = f->swap.files_cleaned; stats.aborted_requests = f->aborted_requests; + + stats.hitValidationAttempts = f->hitValidation.attempts; + stats.hitValidationRefusalsDueToLocking = f->hitValidation.refusalsDueToLocking; + stats.hitValidationRefusalsDueToZeroSize = f->hitValidation.refusalsDueToZeroSize; + stats.hitValidationRefusalsDueToTimeLimit = f->hitValidation.refusalsDueToTimeLimit; + stats.hitValidationFailures = f->hitValidation.failures; } void @@ -1561,6 +1584,17 @@ DumpCountersStats(Mgr::CountersActionData& stats, StoreEntry* sentry) stats.swap_files_cleaned); storeAppendPrintf(sentry, "aborted_requests = %.0f\n", stats.aborted_requests); + + storeAppendPrintf(sentry, "hit_validation.attempts = %.0f\n", + stats.hitValidationAttempts); + storeAppendPrintf(sentry, "hit_validation.refusals.due_to_locking = %.0f\n", + stats.hitValidationRefusalsDueToLocking); + storeAppendPrintf(sentry, "hit_validation.refusals.due_to_zeroSize = %.0f\n", + stats.hitValidationRefusalsDueToZeroSize); + storeAppendPrintf(sentry, "hit_validation.refusals.due_to_timeLimit = %.0f\n", + stats.hitValidationRefusalsDueToTimeLimit); + storeAppendPrintf(sentry, "hit_validation.failures = %.0f\n", + stats.hitValidationFailures); } void -- 2.39.2