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 ffece9beba85a6e0eb37e8a0984f16c84e93ebcd..4c23124d4e6e39c60606321efc7e29ced8c8a6a8 100644 (file)
--- 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 f0b107236b519e67a0f3ca2c477fe307ba913d1e..a156199bc036627e01373dae83485786324f7b94 100644 (file)
--- 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 550a207f740471b96f123b765ecd7be34331e976..c6edf1042223185943ce6c69b6d69e124c3628a4 100644 (file)
--- 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 cbcc70b392b7a26a76d33bcd3e7486784746481f..7f434ebba6b94034c844707a0d4c6ff2ade489ad 100644 (file)
--- 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 c0c5acf6b675287794a2d0e967ad7329ff3caf3b..b69de3740e4922ff1818bcd7a7411957ea789455 100644 (file)
--- 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 3ea475878c5f5d416f6f8508eef11ad538f16ad0..260c67a4a5772b342c868e36abdacaa2a9dd96df 100644 (file)
--- 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 205264daa8faeaffc5206d984df654f7af6db12b..4c4dc913ede2b2510071d8bce11fbbf198e1db98 100644 (file)
--- 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 ed6088f4e7673ae98b476d8527f21928557d6e8d..471d83f66aa0f84b68f3644a8ab64e250d475317 100644 (file)
--- 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 124c07261abf1713b2dd6cd3d79edfafa5ac07ea..c2f7bea7ec8f208b7e00c3489c9f4205e95021ab 100644 (file)
--- 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 1ac908cd5f8fe18e372d803f76f4c8935339ba9d..24f1266c8c549cc2d11726b0f8ae17c515bfa117 100644 (file)
--- 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 db76489604891c72551c951efd5eb5d0ec6347d3..e82a912031bbab379cdd1312f31aff89a3a27d14 100644 (file)
--- 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 5ece07850da5e3525349ca53796c2b1f29349582..dd69284e0d8b74bda59515edd3efd7c984bade87 100644 (file)
--- 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 b77d5562e5250a557ee63dcb996bea5f168c6164..758767a70851401843f452904851acbf39cbb60b 100644 (file)
--- 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<int>(timestamp),
+             static_cast<int>(lastref),
+             static_cast<int>(lastModified_),
+             static_cast<int>(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 6ff0bd5474f2d0333e731793f5c7b131c98ad5f5..6e03947692eedf0595cd11bb027c23318e22d802 100644 (file)
--- a/src/store_rebuild.cc
+++ b/src/store_rebuild.cc
@@ -256,7 +256,7 @@ struct InitStoreEntry : public unary_function<StoreMeta, void> {
             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 61219ff76c781d6987943a9c4e100bd20206c0db..3d07df996465010a4fb55bb2df093c8ce4d73678 100644 (file)
--- 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 26f5f3307a5bd61fa676709df3a8e00cc7c0ff85..c928c914f9e255fe29e9b3f5a55d658f4f93d558 100644 (file)
--- 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 b78dea4b736a1fea53000c53bd40c660802279f0..1ecc529663a9b66b6cfe3beac3a67bc43472d1f2 100644 (file)
--- 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);