------------------------------------------------------------ revno: 14090 revision-id: squid3@treenet.co.nz-20160923204924-28rxvvbloccrma6a parent: squidadm@squid-cache.org-20160923181424-i8cbpi71d8mz4tzo fixes bug: http://bugs.squid-cache.org/show_bug.cgi?id=4471 author: Eduard Bagdasaryan committer: Amos Jeffries branch nick: 3.5 timestamp: Sat 2016-09-24 08:49:24 +1200 message: 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. ------------------------------------------------------------ # Bazaar merge directive format 2 (Bazaar 0.90) # revision_id: squid3@treenet.co.nz-20160923204924-28rxvvbloccrma6a # target_branch: http://bzr.squid-cache.org/bzr/squid3/3.5 # testament_sha1: 6178f67a2e1f914666b59cb8d3126062164e4141 # timestamp: 2016-09-23 20:50:56 +0000 # source_branch: http://bzr.squid-cache.org/bzr/squid3/3.5 # base_revision_id: squidadm@squid-cache.org-20160923181424-\ # i8cbpi71d8mz4tzo # # Begin patch === modified file 'src/MemStore.cc' --- src/MemStore.cc 2016-04-01 06:15:31 +0000 +++ src/MemStore.cc 2016-09-23 20:49:24 +0000 @@ -281,7 +281,7 @@ 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; === modified file 'src/Store.h' --- src/Store.h 2016-09-23 18:14:24 +0000 +++ src/Store.h 2016-09-23 20:49:24 +0000 @@ -143,7 +143,16 @@ 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 @@ 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; === modified file 'src/client_side.cc' --- src/client_side.cc 2016-09-16 11:53:28 +0000 +++ src/client_side.cc 2016-09-23 20:49:24 +0000 @@ -1237,7 +1237,7 @@ /* got modification time? */ if (spec.time >= 0) { - return http->storeEntry()->lastmod <= spec.time; + return !http->storeEntry()->modifiedSince(spec.time); } assert(0); /* should not happen */ === modified file 'src/client_side_reply.cc' --- src/client_side_reply.cc 2016-09-23 18:14:24 +0000 +++ src/client_side_reply.cc 2016-09-23 20:49:24 +0000 @@ -247,7 +247,8 @@ { 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 @@ 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 @@ 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 @@ // 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 @@ */ 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 @@ 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; === modified file 'src/fs/rock/RockSwapDir.cc' --- src/fs/rock/RockSwapDir.cc 2016-01-01 00:14:27 +0000 +++ src/fs/rock/RockSwapDir.cc 2016-09-23 20:49:24 +0000 @@ -134,7 +134,7 @@ 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; === modified file 'src/fs/ufs/RebuildState.cc' --- src/fs/ufs/RebuildState.cc 2016-09-23 12:40:44 +0000 +++ src/fs/ufs/RebuildState.cc 2016-09-23 20:49:24 +0000 @@ -201,7 +201,7 @@ tmpe.expires, tmpe.timestamp, tmpe.lastref, - tmpe.lastmod, + tmpe.lastModified(), tmpe.refcount, /* refcount */ tmpe.flags, /* flags */ (int) flags.clean)); @@ -328,7 +328,7 @@ 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); === modified file 'src/fs/ufs/UFSSwapDir.cc' --- src/fs/ufs/UFSSwapDir.cc 2016-09-23 12:40:44 +0000 +++ src/fs/ufs/UFSSwapDir.cc 2016-09-23 20:49:24 +0000 @@ -87,7 +87,7 @@ 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 @@ 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 @@ 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; === modified file 'src/htcp.cc' --- src/htcp.cc 2016-01-01 00:14:27 +0000 +++ src/htcp.cc 2016-09-23 20:49:24 +0000 @@ -886,8 +886,8 @@ 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); === modified file 'src/ipc/StoreMap.cc' --- src/ipc/StoreMap.cc 2016-01-01 00:14:27 +0000 +++ src/ipc/StoreMap.cc 2016-09-23 20:49:24 +0000 @@ -491,7 +491,7 @@ 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; === modified file 'src/peer_digest.cc' --- src/peer_digest.cc 2016-07-23 07:16:20 +0000 +++ src/peer_digest.cc 2016-09-23 20:49:24 +0000 @@ -359,7 +359,7 @@ /* 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 @@ 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) << ")"); } === modified file 'src/refresh.cc' --- src/refresh.cc 2016-09-07 18:14:33 +0000 +++ src/refresh.cc 2016-09-23 20:49:24 +0000 @@ -186,13 +186,8 @@ } // 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 @@ /* 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) === modified file 'src/stat.cc' --- src/stat.cc 2016-09-07 15:58:59 +0000 +++ src/stat.cc 2016-09-23 20:49:24 +0000 @@ -77,7 +77,6 @@ /* 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 @@ 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 @@ 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), === modified file 'src/store.cc' --- src/store.cc 2016-09-23 15:28:42 +0000 +++ src/store.cc 2016-09-23 20:49:24 +0000 @@ -355,7 +355,7 @@ timestamp(-1), lastref(-1), expires(-1), - lastmod(-1), + lastModified_(-1), swap_file_sz(0), refcount(0), flags(0), @@ -1624,12 +1624,17 @@ 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 @@ 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 @@ mem_obj->reset(); HttpReply *rep = (HttpReply *) getReply(); // bypass const rep->reset(); - expires = lastmod = timestamp = -1; + expires = lastModified_ = timestamp = -1; } /* @@ -2005,13 +2010,10 @@ } 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 @@ 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 @@ 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:"; === modified file 'src/store_rebuild.cc' --- src/store_rebuild.cc 2016-01-01 00:14:27 +0000 +++ src/store_rebuild.cc 2016-09-23 20:49:24 +0000 @@ -254,7 +254,7 @@ 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; === modified file 'src/tests/stub_store.cc' --- src/tests/stub_store.cc 2016-09-23 15:28:42 +0000 +++ src/tests/stub_store.cc 2016-09-23 20:49:24 +0000 @@ -73,7 +73,7 @@ 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) === modified file 'src/tests/testStoreController.cc' --- src/tests/testStoreController.cc 2016-01-01 00:14:27 +0000 +++ src/tests/testStoreController.cc 2016-09-23 20:49:24 +0000 @@ -113,7 +113,7 @@ 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); === modified file 'src/tests/testStoreHashIndex.cc' --- src/tests/testStoreHashIndex.cc 2016-01-01 00:14:27 +0000 +++ src/tests/testStoreHashIndex.cc 2016-09-23 20:49:24 +0000 @@ -94,7 +94,7 @@ 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);