- Added -S command line option to double-check store

          consistency with disk files in storeCleanup().
        - Fixed a problem with transactional logging.  In many
          cases we were adding the public cache key and then
          logging a delete for the private key.  This is worthless
          because during rebuild we could not locate the previous
          public-keyed entry.  Now we assert that only public-keyed
          entries can be logged to swap.state.  storeSetPublicKey()
          and storeSetPrivateKey() have been modified to log an
          ADD or DEL when the key changes.
        - Fixed storeDirClean bug.  Needed to call
          storeDirProperFileno() so the "dirn bits" get set.
        - Fixed a storeRebuildFromDirectory bug.  fullpath[] and
          fullfilename[] were static to that function and did
          not change when the "rebuild_dir" arg did.  Moved these
          buffers to the rebuild_dir structure.
        - In storeRebuildFromSwapLog, we were calling storeRelease()
          for cache key collisions.  This only set the RELEASE_REQUEST
          bit and did not clear the swap_file_number in the filemap or
          in the StoreEntry, so the swap file could get unlinked later
          when it was really released.

diff --git a/src/enums.h b/src/enums.h
index 78f7520f5d28f0ca80d63373f5673116bdfab4a5..a709cc3a2f82733229cb55fb939071e393a34910 100644 (file)
--- a/src/enums.h
+++ b/src/enums.h
@@ -470,8 +470,9 @@ enum {
     STORE_LOG_RELEASE
 };
 
-enum {
+typedef enum {
     SWAP_LOG_NOP,
     SWAP_LOG_ADD,
-    SWAP_LOG_DEL
-};
+    SWAP_LOG_DEL,
+    SWAP_LOG_MAX
+} swap_log_op;

diff --git a/src/globals.h b/src/globals.h
index f182a7211119fefae64cc2a9d4a367aebdaac8e8..4fcf4fc6a01636d6fb430d0df73d55de20858e0d 100644 (file)
--- a/src/globals.h
+++ b/src/globals.h
@@ -1,6 +1,6 @@
 
 /*
- * $Id: globals.h,v 1.36 1998/02/10 21:44:33 wessels Exp $
+ * $Id: globals.h,v 1.37 1998/02/12 23:35:58 wessels Exp $
  */
 
 extern FILE *debug_log;                /* NULL */
@@ -60,6 +60,7 @@ extern int opt_reload_hit_only;       /* 0 */
 extern int opt_syslog_enable;  /* 0 */
 extern int opt_udp_hit_obj;    /* 0 */
 extern int opt_create_swap_dirs;       /* 0 */
+extern int opt_store_doublecheck;      /* 0 */
 extern int syslog_enable;      /* 0 */
 extern int theInIcpConnection; /* -1 */
 extern int theOutIcpConnection;        /* -1 */
@@ -92,6 +93,7 @@ extern time_t hit_only_mode_until;    /* 0 */
 extern StatCounters Counter;
 extern char *err_type_str[];
 extern char *icp_opcode_str[];
+extern char *swap_log_op_str[];
 extern struct radix_node_head *AS_tree_head;
 extern double request_failure_ratio;   /* 0.0 */
 extern int store_hash_buckets; /* 0 */

diff --git a/src/main.cc b/src/main.cc
index ecb656c5d95a527eec64d32106c6d72fd342acac..420dd3f2476926834bd6e973bd96441006dafe27 100644 (file)
--- a/src/main.cc
+++ b/src/main.cc
@@ -1,6 +1,6 @@
 
 /*
- * $Id: main.cc,v 1.217 1998/02/10 22:28:57 wessels Exp $
+ * $Id: main.cc,v 1.218 1998/02/12 23:35:59 wessels Exp $
  *
  * DEBUG: section 1     Startup and Main Loop
  * AUTHOR: Harvest Derived
@@ -167,7 +167,7 @@ mainParseOptions(int argc, char *argv[])
     extern char *optarg;
     int c;
 
-    while ((c = getopt(argc, argv, "CDFNRVYXa:df:hk:m:su:vz?")) != -1) {
+    while ((c = getopt(argc, argv, "CDFNRSVYXa:df:hk:m:su:vz?")) != -1) {
        switch (c) {
        case 'C':
            opt_catch_signals = 0;
@@ -184,6 +184,9 @@ mainParseOptions(int argc, char *argv[])
        case 'R':
            opt_reuseaddr = 0;
            break;
+       case 'S':
+           opt_store_doublecheck = 1;
+           break;
        case 'V':
            vhost_mode = 1;
            break;

diff --git a/src/store.cc b/src/store.cc
index 0a6bc43259b15d1e41cb54b86b9c4714e1c3fe29..4249cec2ff8b702462be16b1710a64242ed40aac 100644 (file)
--- a/src/store.cc
+++ b/src/store.cc
@@ -1,6 +1,6 @@
 
 /*
- * $Id: store.cc,v 1.380 1998/02/12 16:36:30 wessels Exp $
+ * $Id: store.cc,v 1.381 1998/02/12 23:36:01 wessels Exp $
  *
  * DEBUG: section 20    Storeage Manager
  * AUTHOR: Harvest Derived
@@ -360,8 +360,11 @@ storeSetPrivateKey(StoreEntry * e)
     MemObject *mem = e->mem_obj;
     if (e->key && EBIT_TEST(e->flag, KEY_PRIVATE))
        return;                 /* is already private */
-    if (e->key)
+    if (e->key) {
+       if (e->swap_file_number > -1)
+           storeDirSwapLog(e, SWAP_LOG_DEL);
        storeHashDelete(e);
+    }
     if (mem != NULL) {
        mem->reqnum = getKeyCounter();
        newkey = storeKeyPrivate(mem->url, mem->method, mem->reqnum);
@@ -393,6 +396,8 @@ storeSetPublicKey(StoreEntry * e)
        storeHashDelete(e);
     storeHashInsert(e, newkey);
     EBIT_CLR(e->flag, KEY_PRIVATE);
+    if (e->swap_file_number > -1)
+       storeDirSwapLog(e, SWAP_LOG_ADD);
 }
 
 StoreEntry *
@@ -665,11 +670,9 @@ storeMaintainSwapSpace(void *datanotused)
        } else if (bigclean) {
            expired++;
            storeRelease(e);
-       } else {
-           if (storeCheckExpired(e, 1)) {
-               expired++;
-               storeRelease(e);
-           }
+       } else if (storeCheckExpired(e, 1)) {
+           expired++;
+           storeRelease(e);
        }
        if (expired > max_remove)
            break;
@@ -727,7 +730,8 @@ storeRelease(StoreEntry * e)
        storeUnlinkFileno(e->swap_file_number);
        if (e->swap_status == SWAPOUT_DONE)
            storeDirUpdateSwapSize(e->swap_file_number, e->swap_file_sz, -1);
-       storeDirSwapLog(e, SWAP_LOG_DEL);
+       if (!EBIT_TEST(e->flag, KEY_PRIVATE))
+           storeDirSwapLog(e, SWAP_LOG_DEL);
     }
     storeSetMemStatus(e, NOT_IN_MEMORY);
     destroy_StoreEntry(e);

diff --git a/src/store_dir.cc b/src/store_dir.cc
index b8d9e8d3aecc272721a0f76dbed4077caf5352ae..b1cd35059d033036674c32da11684cd163e8dd35 100644 (file)
--- a/src/store_dir.cc
+++ b/src/store_dir.cc
@@ -1,6 +1,6 @@
 
 /*
- * $Id: store_dir.cc,v 1.54 1998/02/12 07:03:07 wessels Exp $
+ * $Id: store_dir.cc,v 1.55 1998/02/12 23:36:02 wessels Exp $
  *
  * DEBUG: section 47    Store Directory Routines
  * AUTHOR: Duane Wessels
@@ -100,18 +100,19 @@ storeSwapSubSubDir(int fn, char *fullpath)
  *
  * This is called by storeDirClean(), but placed here because
  * the algorithm needs to match storeSwapSubSubDir().
+ *
+ * Don't check that (fn >> SWAP_DIR_SHIFT) == F0 because
+ * 'fn' may not have the directory bits set.
  */
 int
 storeFilenoBelongsHere(int fn, int F0, int F1, int F2)
 {
-    int D0, D1, D2;
+    int D1, D2;
     int L1, L2;
     int filn = fn & SWAP_FILE_MASK;
-    D0 = (fn >> SWAP_DIR_SHIFT) % Config.cacheSwap.n_configured;
-    if (F0 != D0)
-       return 0;
-    L1 = Config.cacheSwap.swapDirs[D0].l1;
-    L2 = Config.cacheSwap.swapDirs[D0].l2;
+    assert(F0 < Config.cacheSwap.n_configured);
+    L1 = Config.cacheSwap.swapDirs[F0].l1;
+    L2 = Config.cacheSwap.swapDirs[F0].l2;
     D1 = ((filn / L2) / L2) % L1;
     if (F1 != D1)
        return 0;
@@ -298,6 +299,15 @@ storeDirProperFileno(int dirn, int fn)
     return (dirn << SWAP_DIR_SHIFT) | (fn & SWAP_FILE_MASK);
 }
 
+/*
+ * An entry written to the swap log MUST have the following
+ * properties.
+ *   1.  It MUST be a public key.  It does no good to log
+ *       a public ADD, change the key, then log a private
+ *       DEL.  So we need to log a DEL before we change a
+ *       key from public to private.
+ *   2.  It MUST have a valid (> -1) swap_file_number.
+ */
 void
 storeDirSwapLog(const StoreEntry * e, int op)
 {
@@ -305,21 +315,16 @@ storeDirSwapLog(const StoreEntry * e, int op)
     int dirn;
     dirn = e->swap_file_number >> SWAP_DIR_SHIFT;
     assert(dirn < Config.cacheSwap.n_configured);
-    if (op == SWAP_LOG_ADD) {
-       assert(!EBIT_TEST(e->flag, KEY_PRIVATE));
-       assert(e->swap_file_number >= 0);
-    }
-    if (op == SWAP_LOG_DEL) {
-       if (e->swap_file_number < 0)    /* was never swapped out */
-           return;
-    }
+    assert(!EBIT_TEST(e->flag, KEY_PRIVATE));
+    assert(e->swap_file_number >= 0);
     /*
      * icons and such; don't write them to the swap log
      */
     if (EBIT_TEST(e->flag, ENTRY_SPECIAL))
        return;
+    assert(op > SWAP_LOG_NOP && op < SWAP_LOG_MAX);
     debug(20, 3) ("storeDirSwapLog: %s %s %08X\n",
-       op == SWAP_LOG_DEL ? "SWAP_LOG_DEL" : "SWAP_LOG_ADD",
+       swap_log_op_str[op],
        storeKeyText(e->key),
        e->swap_file_number);
     s->op = (char) op;

diff --git a/src/store_rebuild.cc b/src/store_rebuild.cc
index d092e102a3cf387d2b24dda473a8159bcfc99535..304d32c388ada3d16b41c7cf6bc5a0753c2b56df 100644 (file)
--- a/src/store_rebuild.cc
+++ b/src/store_rebuild.cc
@@ -22,6 +22,8 @@ struct _rebuild_dir {
     DIR *td;
     RBHD *rebuild_func;
     rebuild_dir *next;
+    char fullpath[SQUID_MAXPATHLEN];
+    char fullfilename[SQUID_MAXPATHLEN];
 };
 
 struct storeRebuildState {
@@ -75,7 +77,7 @@ storeRebuildFromDirectory(rebuild_dir * d)
     int sfileno = 0;
     int count;
     int size;
-    struct stat fst;
+    struct stat sb;
     int swap_hdr_len;
     int fd = -1;
     tlv *tlv_list;
@@ -95,7 +97,7 @@ storeRebuildFromDirectory(rebuild_dir * d)
        }
        assert(fd > -1);
        /* lets get file stats here */
-       if (fstat(fd, &fst) < 0) {
+       if (fstat(fd, &sb) < 0) {
            debug(20, 1) ("storeRebuildFromDirectory: fstat(FD %d): %s\n",
                fd, xstrerror());
            file_close(fd);
@@ -105,7 +107,7 @@ storeRebuildFromDirectory(rebuild_dir * d)
        if ((++RebuildState.statcount & 0x3FFF) == 0)
            debug(20, 1) ("  %7d files opened so far.\n",
                RebuildState.statcount);
-       debug(20, 9) ("file_in: fd=%d %08x\n", fd, sfileno);
+       debug(20, 9) ("file_in: fd=%d %08X\n", fd, sfileno);
        if (read(fd, hdr_buf, DISK_PAGE_SIZE) < 0) {
            debug(20, 1) ("storeRebuildFromDirectory: read(FD %d): %s\n",
                fd, xstrerror());
@@ -160,10 +162,10 @@ storeRebuildFromDirectory(rebuild_dir * d)
 #endif
        /* check sizes */
        if (tmpe.swap_file_sz == 0) {
-           tmpe.swap_file_sz = fst.st_size;
-       } else if (tmpe.swap_file_sz != fst.st_size) {
+           tmpe.swap_file_sz = sb.st_size;
+       } else if (tmpe.swap_file_sz != sb.st_size) {
            debug(20, 1) ("storeRebuildFromDirectory: SIZE MISMATCH %d!=%d\n",
-               tmpe.swap_file_sz, fst.st_size);
+               tmpe.swap_file_sz, sb.st_size);
            storeUnlinkFileno(sfileno);
            continue;
        }
@@ -216,6 +218,14 @@ storeRebuildFromSwapLog(rebuild_dir * d)
            return -1;
        }
        d->n_read++;
+       if (s.op <= SWAP_LOG_NOP)
+           continue;
+       if (s.op >= SWAP_LOG_MAX)
+           continue;
+       debug(20, 3) ("storeRebuildFromSwapLog: %s %s %08X\n",
+           swap_log_op_str[(int) s.op],
+           storeKeyText(s.key),
+           s.swap_file_number);
        if (s.op == SWAP_LOG_ADD) {
            (void) 0;
        } else if (s.op == SWAP_LOG_DEL) {
@@ -227,7 +237,6 @@ storeRebuildFromSwapLog(rebuild_dir * d)
                 * because adding to store_swap_size happens in
                 * the cleanup procedure.
                 */
-
                storeExpireNow(e);
                storeSetPrivateKey(e);
                EBIT_SET(e->flag, RELEASE_REQUEST);
@@ -298,9 +307,15 @@ storeRebuildFromSwapLog(rebuild_dir * d)
            RebuildState.clashcount++;
            continue;
        } else if (e) {
-           /* URL already exists, this swapfile not being used */
+           /* key already exists, this swapfile not being used */
            /* junk old, load new */
-           storeRelease(e);    /* release old entry */
+           storeExpireNow(e);
+           storeSetPrivateKey(e);
+           EBIT_SET(e->flag, RELEASE_REQUEST);
+           if (e->swap_file_number > -1) {
+               storeDirMapBitReset(e->swap_file_number);
+               e->swap_file_number = -1;
+           }
            RebuildState.dupcount++;
        } else {
            /* URL doesnt exist, swapfile not in use */
@@ -398,8 +413,6 @@ storeGetNextFile(rebuild_dir * d, int *sfileno, int *size)
 {
     int fd = -1;
     int used = 0;
-    LOCAL_ARRAY(char, fullfilename, SQUID_MAXPATHLEN);
-    LOCAL_ARRAY(char, fullpath, SQUID_MAXPATHLEN);
     debug(20, 3) ("storeGetNextFile: flag=%d, %d: /%02X/%02X\n",
        d->flag,
        d->dirn,
@@ -418,44 +431,47 @@ storeGetNextFile(rebuild_dir * d, int *sfileno, int *size)
            assert(Config.cacheSwap.n_configured > 0);
        }
        if (0 == d->in_dir) {   /* we need to read in a new directory */
-           snprintf(fullpath, SQUID_MAXPATHLEN, "%s/%02X/%02X",
+           snprintf(d->fullpath, SQUID_MAXPATHLEN, "%s/%02X/%02X",
                Config.cacheSwap.swapDirs[d->dirn].path,
                d->curlvl1, d->curlvl2);
            if (d->flag && d->td != NULL)
                closedir(d->td);
-           d->td = opendir(fullpath);
+           d->td = opendir(d->fullpath);
            if (d->td == NULL) {
                debug(50, 1) ("storeGetNextFile: opendir: %s: %s\n",
-                   fullpath, xstrerror());
+                   d->fullpath, xstrerror());
                break;
            }
            d->entry = readdir(d->td);  /* skip . and .. */
            d->entry = readdir(d->td);
            if (errno == ENOENT)
                debug(20, 1) ("storeGetNextFile: directory does not exist!.\n");
-           debug(20, 3) ("storeGetNextFile: Directory %s\n", fullpath);
+           debug(20, 3) ("storeGetNextFile: Directory %s\n", d->fullpath);
        }
        if (d->td != NULL && (d->entry = readdir(d->td)) != NULL) {
            d->in_dir++;
-           if (sscanf(d->entry->d_name, "%x", sfileno) != 1) {
+           if (sscanf(d->entry->d_name, "%x", &d->fn) != 1) {
                debug(20, 3) ("storeGetNextFile: invalid %s\n",
                    d->entry->d_name);
                continue;
            }
-           d->fn = *sfileno;
-           if (!storeFilenoBelongsHere(d->fn, d->dirn, d->curlvl1, d->curlvl2))
+           if (!storeFilenoBelongsHere(d->fn, d->dirn, d->curlvl1, d->curlvl2)) {
+               debug(20, 3) ("storeGetNextFile: %08X does not belong in %d/%d/%d\n",
+                   d->fn, d->dirn, d->curlvl1, d->curlvl2);
                continue;
+           }
            d->fn = storeDirProperFileno(d->dirn, d->fn);
-           *sfileno = d->fn;
            used = storeDirMapBitTest(d->fn);
            if (used) {
                debug(20, 3) ("storeGetNextFile: Locked, continuing with next.\n");
                continue;
            }
-           snprintf(fullfilename, SQUID_MAXPATHLEN, "%s/%s",
-               fullpath, d->entry->d_name);
-           debug(20, 3) ("storeGetNextFile: Opening %s\n", fullfilename);
-           fd = file_open(fullfilename, O_RDONLY, NULL, NULL, NULL);
+           snprintf(d->fullfilename, SQUID_MAXPATHLEN, "%s/%s",
+               d->fullpath, d->entry->d_name);
+           debug(20, 3) ("storeGetNextFile: Opening %s\n", d->fullfilename);
+           fd = file_open(d->fullfilename, O_RDONLY, NULL, NULL, NULL);
+           if (fd < 0)
+               debug(50, 1) ("storeGetNextFile: %s: %s\n", d->fullfilename, xstrerror());
            continue;
        }
        d->in_dir = 0;
@@ -467,6 +483,7 @@ storeGetNextFile(rebuild_dir * d, int *sfileno, int *size)
        d->curlvl1 = 0;
        d->done = 1;
     }
+    *sfileno = d->fn;
     return fd;
 }
 
@@ -517,6 +534,7 @@ storeCleanup(void *datanotused)
 {
     static int bucketnum = -1;
     static int validnum = 0;
+    static int store_errors = 0;
     StoreEntry *e;
     hash_link *link_ptr = NULL;
     if (++bucketnum >= store_hash_buckets) {
@@ -524,6 +542,8 @@ storeCleanup(void *datanotused)
        debug(20, 1) ("  Validated %d Entries\n", validnum);
        debug(20, 1) ("  store_swap_size = %dk\n", store_swap_size);
        store_rebuilding = 0;
+       if (opt_store_doublecheck)
+           assert(store_errors == 0);
        return;
     }
     link_ptr = hash_get_bucket(store_table, bucketnum);
@@ -533,26 +553,43 @@ storeCleanup(void *datanotused)
            continue;
        if (e->swap_file_number < 0)
            continue;
-#if STORE_DOUBLECHECK
-       {
+       if (EBIT_TEST(e->flag, RELEASE_REQUEST)) {
+           assert(!storeDirMapBitTest(e->swap_file_number));
+           /*
+            * I don't think it safe to call storeRelease()
+            * from inside this loop using link_ptr.
+            */
+           continue;
+       }
+       if (opt_store_doublecheck) {
            struct stat sb;
            if (stat(storeSwapFullPath(e->swap_file_number, NULL), &sb) < 0) {
+               store_errors++;
                debug(0, 0) ("storeCleanup: MISSING SWAP FILE\n");
                debug(0, 0) ("storeCleanup: FILENO %08X\n", e->swap_file_number);
                debug(0, 0) ("storeCleanup: PATH %s\n",
                    storeSwapFullPath(e->swap_file_number, NULL));
                storeEntryDump(e, 0);
-               assert(0);
+               continue;
+           }
+           if (e->swap_file_sz != sb.st_size) {
+               store_errors++;
+               debug(0, 0) ("storeCleanup: SIZE MISMATCH\n");
+               debug(0, 0) ("storeCleanup: FILENO %08X\n", e->swap_file_number);
+               debug(0, 0) ("storeCleanup: PATH %s\n",
+                   storeSwapFullPath(e->swap_file_number, NULL));
+               debug(0, 0) ("storeCleanup: ENTRY SIZE: %d, FILE SIZE: %d\n",
+                   e->swap_file_sz, sb.st_size);
+               storeEntryDump(e, 0);
+               continue;
            }
        }
-#endif
        EBIT_SET(e->flag, ENTRY_VALIDATED);
        /* Only set the file bit if we know its a valid entry */
        /* otherwise, set it in the validation procedure */
        storeDirUpdateSwapSize(e->swap_file_number, e->swap_file_sz, 1);
        if ((++validnum & 0xFFFF) == 0)
            debug(20, 1) ("  %7d Entries Validated so far.\n", validnum);
-       assert(validnum <= memInUse(MEM_STOREENTRY));
     }
     eventAdd("storeCleanup", storeCleanup, NULL, 0);
 }