From: Eduard Bagdasaryan Date: Sat, 17 Sep 2016 16:50:30 +0000 (+1200) Subject: Bug 4471: revalidation doesn't work when expired cached object lacks Last-Modified. X-Git-Tag: SQUID_4_0_15~36 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=438b41ba09cac14b3b9758f0bfd50e98711fcc8c;p=thirdparty%2Fsquid.git Bug 4471: revalidation doesn't work when expired cached object lacks Last-Modified. The bug was caused by the fact that Squid used only Last-Modified header value for evaluating entry's last modification time while making an internal revalidation request. So, without Last-Modified it was not possible to correctly fill If-Modified-Since header value. As a result, the revalidation request was not initiated when it should be. To fix this problem, we should generate If-Modified-Since based on other data, showing how "old" the cached response is, such as Date and Age header values. Both Date and Age header values are utilized while calculating entry's timestamp. Therefore, we should use the timestamp if Last-Modified is unavailable. TODO: HttpRequest::imslen support looks broken/deprecated. Using this field inside StoreEntry::modifiedSince() leads to several useless checks and probably may cause other [hidden] problems. --- diff --git a/src/MemStore.cc b/src/MemStore.cc index ffece9beba..4c23124d4e 100644 --- a/src/MemStore.cc +++ b/src/MemStore.cc @@ -456,7 +456,7 @@ MemStore::anchorEntry(StoreEntry &e, const sfileno index, const Ipc::StoreMapAnc e.lastref = basics.lastref; e.timestamp = basics.timestamp; e.expires = basics.expires; - e.lastmod = basics.lastmod; + e.lastModified(basics.lastmod); e.refcount = basics.refcount; e.flags = basics.flags; diff --git a/src/Store.h b/src/Store.h index f0b107236b..a156199bc0 100644 --- a/src/Store.h +++ b/src/Store.h @@ -131,7 +131,16 @@ public: void delayAwareRead(const Comm::ConnectionPointer &conn, char *buf, int len, AsyncCall::Pointer callback); void setNoDelay (bool const); - bool modifiedSince(HttpRequest * request) const; + void lastModified(const time_t when) { lastModified_ = when; } + /// \returns entry's 'effective' modification time + time_t lastModified() const { + // may still return -1 if timestamp is not set + return lastModified_ < 0 ? timestamp : lastModified_; + } + /// \returns a formatted string with entry's timestamps + const char *describeTimestamps() const; + // TODO: consider removing currently unsupported imslen parameter + bool modifiedSince(const time_t ims, const int imslen = -1) const; /// has ETag matching at least one of the If-Match etags bool hasIfMatchEtag(const HttpRequest &request) const; /// has ETag matching at least one of the If-None-Match etags @@ -148,7 +157,9 @@ public: time_t timestamp; time_t lastref; time_t expires; - time_t lastmod; +private: + time_t lastModified_; ///< received Last-Modified value or -1; use lastModified() +public: uint64_t swap_file_sz; uint16_t refcount; uint16_t flags; diff --git a/src/client_side_reply.cc b/src/client_side_reply.cc index 550a207f74..c6edf10422 100644 --- a/src/client_side_reply.cc +++ b/src/client_side_reply.cc @@ -266,7 +266,8 @@ clientReplyContext::processExpired() { const char *url = storeId(); debugs(88, 3, "clientReplyContext::processExpired: '" << http->uri << "'"); - assert(http->storeEntry()->lastmod >= 0); + const time_t lastmod = http->storeEntry()->lastModified(); + assert(lastmod >= 0); /* * check if we are allowed to contact other servers * @?@: Instead of a 504 (Gateway Timeout) reply, we may want to return @@ -323,7 +324,7 @@ clientReplyContext::processExpired() sc->setDelayId(DelayId::DelayClient(http)); #endif - http->request->lastmod = old_entry->lastmod; + http->request->lastmod = lastmod; if (!http->request->header.has(Http::HdrType::IF_NONE_MATCH)) { ETag etag = {NULL, -1}; // TODO: make that a default ETag constructor @@ -331,7 +332,7 @@ clientReplyContext::processExpired() http->request->etag = etag.str; } - debugs(88, 5, "clientReplyContext::processExpired : lastmod " << entry->lastmod ); + debugs(88, 5, "lastmod " << entry->lastModified()); http->storeEntry(entry); assert(http->out.offset == 0); assert(http->request->clientConnectionManager == http->getConn()); @@ -438,7 +439,7 @@ clientReplyContext::handleIMSReply(StoreIOBuffer result) // if client sent IMS - if (http->request->flags.ims && !old_entry->modifiedSince(http->request)) { + if (http->request->flags.ims && !old_entry->modifiedSince(http->request->ims, http->request->imslen)) { // forward the 304 from origin debugs(88, 3, "handleIMSReply: origin replied 304, revalidating existing entry and forwarding 304 to client"); sendClientUpstreamResponse(); @@ -614,11 +615,12 @@ clientReplyContext::cacheHit(StoreIOBuffer result) */ r->flags.needValidation = true; - if (e->lastmod < 0) { - debugs(88, 3, "validate HIT object? NO. Missing Last-Modified header. Do MISS."); + if (e->lastModified() < 0) { + debugs(88, 3, "validate HIT object? NO. Can't calculate entry modification time. Do MISS."); /* - * Previous reply didn't have a Last-Modified header, - * we cannot revalidate it. + * We cannot revalidate entries without knowing their + * modification time. + * XXX: BUG 1890 objects without Date do not get one added. */ http->logType = LOG_TCP_MISS; processMiss(); @@ -807,7 +809,7 @@ clientReplyContext::processConditional(StoreIOBuffer &result) if (r.flags.ims) { // handle If-Modified-Since requests from the client - if (e->modifiedSince(&r)) { + if (e->modifiedSince(r.ims, r.imslen)) { http->logType = LOG_TCP_IMS_HIT; sendMoreData(result); return; diff --git a/src/fs/rock/RockSwapDir.cc b/src/fs/rock/RockSwapDir.cc index cbcc70b392..7f434ebba6 100644 --- a/src/fs/rock/RockSwapDir.cc +++ b/src/fs/rock/RockSwapDir.cc @@ -122,7 +122,7 @@ Rock::SwapDir::anchorEntry(StoreEntry &e, const sfileno filen, const Ipc::StoreM e.lastref = basics.lastref; e.timestamp = basics.timestamp; e.expires = basics.expires; - e.lastmod = basics.lastmod; + e.lastModified(basics.lastmod); e.refcount = basics.refcount; e.flags = basics.flags; diff --git a/src/fs/ufs/RebuildState.cc b/src/fs/ufs/RebuildState.cc index c0c5acf6b6..b69de3740e 100644 --- a/src/fs/ufs/RebuildState.cc +++ b/src/fs/ufs/RebuildState.cc @@ -217,7 +217,7 @@ Fs::Ufs::RebuildState::rebuildFromDirectory() tmpe.expires, tmpe.timestamp, tmpe.lastref, - tmpe.lastmod, + tmpe.lastModified(), tmpe.refcount, /* refcount */ tmpe.flags, /* flags */ (int) flags.clean)); @@ -344,7 +344,7 @@ Fs::Ufs::RebuildState::rebuildFromSwapLog() currentEntry()->lastref = swapData.timestamp; currentEntry()->timestamp = swapData.timestamp; currentEntry()->expires = swapData.expires; - currentEntry()->lastmod = swapData.lastmod; + currentEntry()->lastModified(swapData.lastmod); currentEntry()->flags = swapData.flags; currentEntry()->refcount += swapData.refcount; sd->dereference(*currentEntry()); diff --git a/src/fs/ufs/UFSSwapDir.cc b/src/fs/ufs/UFSSwapDir.cc index 3ea475878c..260c67a4a5 100644 --- a/src/fs/ufs/UFSSwapDir.cc +++ b/src/fs/ufs/UFSSwapDir.cc @@ -88,7 +88,7 @@ UFSCleanLog::write(StoreEntry const &e) s.timestamp = e.timestamp; s.lastref = e.lastref; s.expires = e.expires; - s.lastmod = e.lastmod; + s.lastmod = e.lastModified(); s.swap_file_sz = e.swap_file_sz; s.refcount = e.refcount; s.flags = e.flags; @@ -804,7 +804,7 @@ Fs::Ufs::UFSSwapDir::addDiskRestore(const cache_key * key, e->lastref = lastref; e->timestamp = timestamp; e->expires = expires; - e->lastmod = lastmod; + e->lastModified(lastmod); e->refcount = refcount; e->flags = newFlags; EBIT_CLR(e->flags, RELEASE_REQUEST); @@ -1290,7 +1290,7 @@ Fs::Ufs::UFSSwapDir::logEntry(const StoreEntry & e, int op) const s->timestamp = e.timestamp; s->lastref = e.lastref; s->expires = e.expires; - s->lastmod = e.lastmod; + s->lastmod = e.lastModified(); s->swap_file_sz = e.swap_file_sz; s->refcount = e.refcount; s->flags = e.flags; diff --git a/src/htcp.cc b/src/htcp.cc index 205264daa8..4c4dc913ed 100644 --- a/src/htcp.cc +++ b/src/htcp.cc @@ -848,8 +848,8 @@ htcpTstReply(htcpDataHeader * dhdr, StoreEntry * e, htcpSpecifier * spec, Ip::Ad if (e && e->expires > -1) hdr.putTime(Http::HdrType::EXPIRES, e->expires); - if (e && e->lastmod > -1) - hdr.putTime(Http::HdrType::LAST_MODIFIED, e->lastmod); + if (e && e->lastModified() > -1) + hdr.putTime(Http::HdrType::LAST_MODIFIED, e->lastModified()); hdr.packInto(&mb); diff --git a/src/http/Stream.cc b/src/http/Stream.cc index ed6088f4e7..471d83f66a 100644 --- a/src/http/Stream.cc +++ b/src/http/Stream.cc @@ -382,7 +382,7 @@ clientIfRangeMatch(ClientHttpRequest * http, HttpReply * rep) /* got modification time? */ if (spec.time >= 0) - return http->storeEntry()->lastmod <= spec.time; + return !http->storeEntry()->modifiedSince(spec.time); assert(0); /* should not happen */ return false; diff --git a/src/ipc/StoreMap.cc b/src/ipc/StoreMap.cc index 124c07261a..c2f7bea7ec 100644 --- a/src/ipc/StoreMap.cc +++ b/src/ipc/StoreMap.cc @@ -751,7 +751,7 @@ Ipc::StoreMapAnchor::set(const StoreEntry &from) basics.timestamp = from.timestamp; basics.lastref = from.lastref; basics.expires = from.expires; - basics.lastmod = from.lastmod; + basics.lastmod = from.lastModified(); basics.swap_file_sz = from.swap_file_sz; basics.refcount = from.refcount; basics.flags = from.flags; diff --git a/src/peer_digest.cc b/src/peer_digest.cc index 1ac908cd5f..24f1266c8c 100644 --- a/src/peer_digest.cc +++ b/src/peer_digest.cc @@ -370,7 +370,7 @@ peerDigestRequest(PeerDigest * pd) /* set lastmod to trigger IMS request if possible */ if (old_e) - e->lastmod = old_e->lastmod; + e->lastModified(old_e->lastModified()); /* push towards peer cache */ debugs(72, 3, "peerDigestRequest: forwarding to fwdStart..."); @@ -918,8 +918,8 @@ peerDigestFetchSetStats(DigestFetchState * fetch) debugs(72, 3, "peerDigestFetchFinish: expires: " << (long int) fetch->expires << " (" << std::showpos << (int) (fetch->expires - squid_curtime) << "), lmt: " << - std::noshowpos << (long int) fetch->entry->lastmod << " (" << - std::showpos << (int) (fetch->entry->lastmod - squid_curtime) << + std::noshowpos << (long int) fetch->entry->lastModified() << " (" << + std::showpos << (int) (fetch->entry->lastModified() - squid_curtime) << ")"); } diff --git a/src/refresh.cc b/src/refresh.cc index db76489604..e82a912031 100644 --- a/src/refresh.cc +++ b/src/refresh.cc @@ -174,13 +174,8 @@ refreshStaleness(const StoreEntry * entry, time_t check_time, const time_t age, } // 3. If there is a Last-Modified header, try the last-modified factor algorithm. - if (entry->lastmod > -1 && entry->timestamp > entry->lastmod) { - - /* lastmod_delta is the difference between the last-modified date of the response - * and the time we cached it. It's how "old" the response was when we got it. - */ - time_t lastmod_delta = entry->timestamp - entry->lastmod; - + const time_t lastmod_delta = entry->timestamp - entry->lastModified(); + if (lastmod_delta > 0) { /* stale_age is the age of the response when it became/becomes stale according to * the last-modified factor algorithm. It's how long we can consider the response * fresh from the time we cached it. @@ -540,8 +535,8 @@ refreshIsCachable(const StoreEntry * entry) /* Does not need refresh. This is certainly cachable */ return true; - if (entry->lastmod < 0) - /* Last modified is needed to do a refresh */ + if (entry->lastModified() < 0) + /* We should know entry's modification time to do a refresh */ return false; if (entry->mem_obj == NULL) diff --git a/src/stat.cc b/src/stat.cc index 5ece07850d..dd69284e0d 100644 --- a/src/stat.cc +++ b/src/stat.cc @@ -79,7 +79,6 @@ public: /* LOCALS */ static const char *describeStatuses(const StoreEntry *); -static const char *describeTimestamps(const StoreEntry *); static void statAvgTick(void *notused); static void statAvgDump(StoreEntry *, int minutes, int hours); #if STAT_GRAPHS @@ -330,18 +329,6 @@ storeEntryFlags(const StoreEntry * entry) return buf; } -static const char * -describeTimestamps(const StoreEntry * entry) -{ - LOCAL_ARRAY(char, buf, 256); - snprintf(buf, 256, "LV:%-9d LU:%-9d LM:%-9d EX:%-9d", - (int) entry->timestamp, - (int) entry->lastref, - (int) entry->lastmod, - (int) entry->expires); - return buf; -} - static void statStoreEntry(MemBuf * mb, StoreEntry * e) { @@ -349,7 +336,7 @@ statStoreEntry(MemBuf * mb, StoreEntry * e) mb->appendf("KEY %s\n", e->getMD5Text()); mb->appendf("\t%s\n", describeStatuses(e)); mb->appendf("\t%s\n", storeEntryFlags(e)); - mb->appendf("\t%s\n", describeTimestamps(e)); + mb->appendf("\t%s\n", e->describeTimestamps()); mb->appendf("\t%d locks, %d clients, %d refs\n", (int) e->locks(), storePendingNClients(e), (int) e->refcount); mb->appendf("\tSwap Dir %d, File %#08X\n", e->swap_dirn, e->swap_filen); diff --git a/src/store.cc b/src/store.cc index b77d5562e5..758767a708 100644 --- a/src/store.cc +++ b/src/store.cc @@ -331,7 +331,7 @@ StoreEntry::StoreEntry() : timestamp(-1), lastref(-1), expires(-1), - lastmod(-1), + lastModified_(-1), swap_file_sz(0), refcount(0), flags(0), @@ -1564,12 +1564,17 @@ StoreEntry::timestampsSet() else exp = reply->expires; - if (lastmod == reply->last_modified && timestamp == served_date && expires == exp) - return false; + if (timestamp == served_date && expires == exp) { + // if the reply lacks LMT, then we now know that our effective + // LMT (i.e., timestamp) will stay the same, otherwise, old and + // new modification times must match + if (reply->last_modified < 0 || reply->last_modified == lastModified()) + return false; // nothing has changed + } expires = exp; - lastmod = reply->last_modified; + lastModified_ = reply->last_modified; timestamp = served_date; @@ -1604,7 +1609,7 @@ StoreEntry::dump(int l) const debugs(20, l, "StoreEntry->timestamp: " << timestamp); debugs(20, l, "StoreEntry->lastref: " << lastref); debugs(20, l, "StoreEntry->expires: " << expires); - debugs(20, l, "StoreEntry->lastmod: " << lastmod); + debugs(20, l, "StoreEntry->lastModified_: " << lastModified_); debugs(20, l, "StoreEntry->swap_file_sz: " << swap_file_sz); debugs(20, l, "StoreEntry->refcount: " << refcount); debugs(20, l, "StoreEntry->flags: " << storeEntryFlags(this)); @@ -1742,7 +1747,7 @@ StoreEntry::reset() mem_obj->reset(); HttpReply *rep = (HttpReply *) getReply(); // bypass const rep->reset(); - expires = lastmod = timestamp = -1; + expires = lastModified_ = timestamp = -1; } /* @@ -1949,13 +1954,10 @@ StoreEntry::trimMemory(const bool preserveSwappable) } bool -StoreEntry::modifiedSince(HttpRequest * request) const +StoreEntry::modifiedSince(const time_t ims, const int imslen) const { int object_length; - time_t mod_time = lastmod; - - if (mod_time < 0) - mod_time = timestamp; + const time_t mod_time = lastModified(); debugs(88, 3, "modifiedSince: '" << url() << "'"); @@ -1970,16 +1972,16 @@ StoreEntry::modifiedSince(HttpRequest * request) const if (object_length < 0) object_length = contentLen(); - if (mod_time > request->ims) { + if (mod_time > ims) { debugs(88, 3, "--> YES: entry newer than client"); return true; - } else if (mod_time < request->ims) { + } else if (mod_time < ims) { debugs(88, 3, "--> NO: entry older than client"); return false; - } else if (request->imslen < 0) { + } else if (imslen < 0) { debugs(88, 3, "--> NO: same LMT, no client length"); return false; - } else if (request->imslen == object_length) { + } else if (imslen == object_length) { debugs(88, 3, "--> NO: same LMT, same length"); return false; } else { @@ -2069,6 +2071,18 @@ StoreEntry::isAccepting() const return true; } +const char * +StoreEntry::describeTimestamps() const +{ + LOCAL_ARRAY(char, buf, 256); + snprintf(buf, 256, "LV:%-9d LU:%-9d LM:%-9d EX:%-9d", + static_cast(timestamp), + static_cast(lastref), + static_cast(lastModified_), + static_cast(expires)); + return buf; +} + std::ostream &operator <<(std::ostream &os, const StoreEntry &e) { os << "e:"; diff --git a/src/store_rebuild.cc b/src/store_rebuild.cc index 6ff0bd5474..6e03947692 100644 --- a/src/store_rebuild.cc +++ b/src/store_rebuild.cc @@ -256,7 +256,7 @@ struct InitStoreEntry : public unary_function { what->timestamp = tmp->timestamp; what->lastref = tmp->lastref; what->expires = tmp->expires; - what->lastmod = tmp->lastmod; + what->lastModified(tmp->lastmod); what->swap_file_sz = tmp->swap_file_sz; what->refcount = tmp->refcount; what->flags = tmp->flags; diff --git a/src/tests/stub_store.cc b/src/tests/stub_store.cc index 61219ff76c..3d07df9964 100644 --- a/src/tests/stub_store.cc +++ b/src/tests/stub_store.cc @@ -68,7 +68,7 @@ void StoreEntry::destroyMemObject() STUB int StoreEntry::checkTooSmall() STUB_RETVAL(0) void StoreEntry::delayAwareRead(const Comm::ConnectionPointer&, char *buf, int len, AsyncCall::Pointer callback) STUB void StoreEntry::setNoDelay (bool const) STUB -bool StoreEntry::modifiedSince(HttpRequest * request) const STUB_RETVAL(false) +bool StoreEntry::modifiedSince(const time_t, const int) const STUB_RETVAL(false) bool StoreEntry::hasIfMatchEtag(const HttpRequest &request) const STUB_RETVAL(false) bool StoreEntry::hasIfNoneMatchEtag(const HttpRequest &request) const STUB_RETVAL(false) Store::Disk &StoreEntry::disk() const STUB_RETREF(Store::Disk) diff --git a/src/tests/testStoreController.cc b/src/tests/testStoreController.cc index 26f5f3307a..c928c914f9 100644 --- a/src/tests/testStoreController.cc +++ b/src/tests/testStoreController.cc @@ -111,7 +111,7 @@ addedEntry(Store::Disk *aStore, e->lastref = squid_curtime; e->timestamp = squid_curtime; e->expires = squid_curtime; - e->lastmod = squid_curtime; + e->lastModified(squid_curtime); e->refcount = 1; EBIT_CLR(e->flags, RELEASE_REQUEST); EBIT_CLR(e->flags, KEY_PRIVATE); diff --git a/src/tests/testStoreHashIndex.cc b/src/tests/testStoreHashIndex.cc index b78dea4b73..1ecc529663 100644 --- a/src/tests/testStoreHashIndex.cc +++ b/src/tests/testStoreHashIndex.cc @@ -89,7 +89,7 @@ addedEntry(Store::Disk *aStore, e->lastref = squid_curtime; e->timestamp = squid_curtime; e->expires = squid_curtime; - e->lastmod = squid_curtime; + e->lastModified(squid_curtime); e->refcount = 1; EBIT_CLR(e->flags, RELEASE_REQUEST); EBIT_CLR(e->flags, KEY_PRIVATE);