From: Eduard Bagdasaryan Date: Fri, 23 Sep 2016 20:49:24 +0000 (+1200) Subject: Bug 4471: revalidation doesn't work when expired cached object lacks Last-Modified. X-Git-Tag: SQUID_3_5_22~8 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=ca43516e27f7d996be67477bf4568f4cedd5cd24;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 86b6024560..4829bbb40e 100644 --- a/src/MemStore.cc +++ b/src/MemStore.cc @@ -281,7 +281,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 649deb2743..26d31373be 100644 --- a/src/Store.h +++ b/src/Store.h @@ -143,7 +143,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 @@ -160,7 +169,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.cc b/src/client_side.cc index 0615e00628..afadd8014a 100644 --- a/src/client_side.cc +++ b/src/client_side.cc @@ -1237,7 +1237,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 */ diff --git a/src/client_side_reply.cc b/src/client_side_reply.cc index 519a6bab94..7a5fec1ca6 100644 --- a/src/client_side_reply.cc +++ b/src/client_side_reply.cc @@ -247,7 +247,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 @@ -303,7 +304,7 @@ clientReplyContext::processExpired() sc->setDelayId(DelayId::DelayClient(http)); #endif - http->request->lastmod = old_entry->lastmod; + http->request->lastmod = lastmod; if (!http->request->header.has(HDR_IF_NONE_MATCH)) { ETag etag = {NULL, -1}; // TODO: make that a default ETag constructor @@ -311,7 +312,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()); @@ -420,7 +421,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(); @@ -596,11 +597,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(); @@ -789,7 +791,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 29c6803799..b18b0cc5f9 100644 --- a/src/fs/rock/RockSwapDir.cc +++ b/src/fs/rock/RockSwapDir.cc @@ -134,7 +134,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 c0dff12201..4b662972fb 100644 --- a/src/fs/ufs/RebuildState.cc +++ b/src/fs/ufs/RebuildState.cc @@ -201,7 +201,7 @@ Fs::Ufs::RebuildState::rebuildFromDirectory() tmpe.expires, tmpe.timestamp, tmpe.lastref, - tmpe.lastmod, + tmpe.lastModified(), tmpe.refcount, /* refcount */ tmpe.flags, /* flags */ (int) flags.clean)); @@ -328,7 +328,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(), false); diff --git a/src/fs/ufs/UFSSwapDir.cc b/src/fs/ufs/UFSSwapDir.cc index c3603e9991..d62c08974f 100644 --- a/src/fs/ufs/UFSSwapDir.cc +++ b/src/fs/ufs/UFSSwapDir.cc @@ -87,7 +87,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; @@ -805,7 +805,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); @@ -1310,7 +1310,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 1928a546a5..e0339517b2 100644 --- a/src/htcp.cc +++ b/src/htcp.cc @@ -886,8 +886,8 @@ htcpTstReply(htcpDataHeader * dhdr, StoreEntry * e, htcpSpecifier * spec, Ip::Ad if (e && e->expires > -1) hdr.putTime(HDR_EXPIRES, e->expires); - if (e && e->lastmod > -1) - hdr.putTime(HDR_LAST_MODIFIED, e->lastmod); + if (e && e->lastModified() > -1) + hdr.putTime(HDR_LAST_MODIFIED, e->lastModified()); hdr.packInto(&p); diff --git a/src/ipc/StoreMap.cc b/src/ipc/StoreMap.cc index 105b1c6eda..890ee8bd18 100644 --- a/src/ipc/StoreMap.cc +++ b/src/ipc/StoreMap.cc @@ -491,7 +491,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 69c25ae6f2..e955d4a8e4 100644 --- a/src/peer_digest.cc +++ b/src/peer_digest.cc @@ -359,7 +359,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..."); @@ -942,8 +942,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 9343ab292d..2e515911be 100644 --- a/src/refresh.cc +++ b/src/refresh.cc @@ -186,13 +186,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. @@ -553,8 +548,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 ca2f07b065..beedfd3cd5 100644 --- a/src/stat.cc +++ b/src/stat.cc @@ -77,7 +77,6 @@ private: /* 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 @@ -328,18 +327,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) { @@ -347,7 +334,7 @@ statStoreEntry(MemBuf * mb, StoreEntry * e) mb->Printf("KEY %s\n", e->getMD5Text()); mb->Printf("\t%s\n", describeStatuses(e)); mb->Printf("\t%s\n", storeEntryFlags(e)); - mb->Printf("\t%s\n", describeTimestamps(e)); + mb->Printf("\t%s\n", e->describeTimestamps()); mb->Printf("\t%d locks, %d clients, %d refs\n", (int) e->locks(), storePendingNClients(e), diff --git a/src/store.cc b/src/store.cc index 2d775dc2e7..9c22185bb0 100644 --- a/src/store.cc +++ b/src/store.cc @@ -355,7 +355,7 @@ StoreEntry::StoreEntry() : timestamp(-1), lastref(-1), expires(-1), - lastmod(-1), + lastModified_(-1), swap_file_sz(0), refcount(0), flags(0), @@ -1624,12 +1624,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; @@ -1664,7 +1669,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)); @@ -1795,7 +1800,7 @@ StoreEntry::reset() mem_obj->reset(); HttpReply *rep = (HttpReply *) getReply(); // bypass const rep->reset(); - expires = lastmod = timestamp = -1; + expires = lastModified_ = timestamp = -1; } /* @@ -2005,13 +2010,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() << "'"); @@ -2026,16 +2028,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 { @@ -2132,6 +2134,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 7cde33cc55..0647f7422f 100644 --- a/src/store_rebuild.cc +++ b/src/store_rebuild.cc @@ -254,7 +254,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 4bee8096ae..f002973087 100644 --- a/src/tests/stub_store.cc +++ b/src/tests/stub_store.cc @@ -73,7 +73,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 ims, const int imslen) const STUB_RETVAL(false); bool StoreEntry::hasIfMatchEtag(const HttpRequest &request) const STUB_RETVAL(false) bool StoreEntry::hasIfNoneMatchEtag(const HttpRequest &request) const STUB_RETVAL(false) RefCount StoreEntry::store() const STUB_RETVAL(NULL) diff --git a/src/tests/testStoreController.cc b/src/tests/testStoreController.cc index c1268ae533..92a8fa7161 100644 --- a/src/tests/testStoreController.cc +++ b/src/tests/testStoreController.cc @@ -113,7 +113,7 @@ addedEntry(StorePointer hashStore, 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 108ea74d1f..9d0d9e7b5f 100644 --- a/src/tests/testStoreHashIndex.cc +++ b/src/tests/testStoreHashIndex.cc @@ -94,7 +94,7 @@ addedEntry(StorePointer hashStore, 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);