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 86b6024560b9d402f97d4fa9e8b7395a92dc0edd..4829bbb40e38ce39823bf06536035aac69a9aac9 100644 (file)
--- 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 649deb274324110d39a1ab9642cb0d1585672f40..26d31373be0d2806142bf76cb12c25279b50176f 100644 (file)
--- 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 0615e00628fb897288bc571de810b08f22e2595f..afadd8014a9b1005fad12fbe5641465c05eb8c06 100644 (file)
--- 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 519a6bab94ba3092f6aa92729210237ea71ecc18..7a5fec1ca603edf42d40fd5b9f142144ba4c383a 100644 (file)
--- 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 29c68037995cbc13e278d62d322afd53ab5fc058..b18b0cc5f9b753eebb7c2aa4375898059a0712d6 100644 (file)
--- 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 c0dff12201d1ed26ef92dfda3f618520582d0034..4b662972fb16af50dd3ea82b594d773f427c1674 100644 (file)
--- 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 c3603e999129f515a022c3cbe42eb41468d0eed9..d62c08974fd971d66b3c8d0a262d44b5e7bd8787 100644 (file)
--- 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 1928a546a537ee2c78b841a524e21b31e6c9d9b2..e0339517b21d2a2d8fedf9cb737e2cbab6312ac6 100644 (file)
--- 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 105b1c6eda2f5a715649df29342100f1f0a0be0d..890ee8bd1827180c9f2076a69f80c785a81a0f10 100644 (file)
--- 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 69c25ae6f2817d69289180f38ec6d85692a687a9..e955d4a8e467286c35b103de19bb4e037d4054f3 100644 (file)
--- 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 9343ab292d6a04febe5f23ea54545455a4a30617..2e515911beec96108ce32461b35eebb759ec999e 100644 (file)
--- 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 ca2f07b06554f3534a8d522576ece891940a966a..beedfd3cd5a2a32e10a2aa0894573358caf3f770 100644 (file)
--- 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 2d775dc2e73859979b0e652c68e67bec15eeaa80..9c22185bb06b2e092c597704331a933488ae2982 100644 (file)
--- 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<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 7cde33cc551911a629d2eb9f4d749d16733f03c5..0647f7422f0980fa54e5f32538897a5c45188cae 100644 (file)
--- a/src/store_rebuild.cc
+++ b/src/store_rebuild.cc
@@ -254,7 +254,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 4bee8096aee2cf1741dd5ed75e340d9dfd96d8a5..f0029730871fab7ca5ae122bc6edb0a0ae0cd180 100644 (file)
--- 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<SwapDir> StoreEntry::store() const STUB_RETVAL(NULL)

diff --git a/src/tests/testStoreController.cc b/src/tests/testStoreController.cc
index c1268ae533d83caa08711f4300b60a4978ad56a0..92a8fa7161eb2cc3154a91f08084587c1e6af14d 100644 (file)
--- 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 108ea74d1f9d95ab0982b219341778f3a3fd8b2f..9d0d9e7b5f8a0b6b14e1852268950e03014d30f2 100644 (file)
--- 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);