src/store_rebuild.cc

   1 /*
   2  * Copyright (C) 1996-2020 The Squid Software Foundation and contributors
   3  *
   4  * Squid software is distributed under GPLv2+ license and includes
   5  * contributions from numerous individuals and organizations.
   6  * Please see the COPYING and CONTRIBUTORS files for details.
   7  */
   8
   9 /* DEBUG: section 20    Store Rebuild Routines */
  10
  11 #include "squid.h"
  12 #include "event.h"
  13 #include "globals.h"
  14 #include "md5.h"
  15 #include "SquidConfig.h"
  16 #include "SquidTime.h"
  17 #include "StatCounters.h"
  18 #include "Store.h"
  19 #include "store/Disk.h"
  20 #include "store_digest.h"
  21 #include "store_key_md5.h"
  22 #include "store_rebuild.h"
  23 #include "StoreSearch.h"
  24 // for tvSubDsec() which should be in SquidTime.h
  25 #include "util.h"
  26
  27 #include <cerrno>
  28
  29 static StoreRebuildData counts;
  30
  31 static void storeCleanup(void *);
  32
  33 // TODO: Either convert to Progress or replace with StoreRebuildData.
  34 // TODO: Handle unknown totals (UFS cache_dir that lost swap.state) correctly.
  35 typedef struct {
  36     /* total number of "swap.state" entries that will be read */
  37     int total;
  38     /* number of entries read so far */
  39     int scanned;
  40 } store_rebuild_progress;
  41
  42 static store_rebuild_progress *RebuildProgress = NULL;
  43
  44 void
  45 StoreRebuildData::updateStartTime(const timeval &dirStartTime)
  46 {
  47     startTime = started() ? std::min(startTime, dirStartTime) : dirStartTime;
  48 }
  49
  50 static void
  51 storeCleanup(void *)
  52 {
  53     static int store_errors = 0;
  54     static StoreSearchPointer currentSearch;
  55     static int validated = 0;
  56     static int seen = 0;
  57
  58     if (currentSearch == NULL || currentSearch->isDone())
  59         currentSearch = Store::Root().search();
  60
  61     size_t statCount = 500;
  62
  63     // TODO: Avoid the loop (and ENTRY_VALIDATED) unless opt_store_doublecheck.
  64     while (statCount-- && !currentSearch->isDone() && currentSearch->next()) {
  65         StoreEntry *e;
  66
  67         e = currentSearch->currentItem();
  68
  69         ++seen;
  70
  71         if (EBIT_TEST(e->flags, ENTRY_VALIDATED))
  72             continue;
  73
  74         /*
  75          * Calling StoreEntry->release() has no effect because we're
  76          * still in 'store_rebuilding' state
  77          */
  78         if (!e->hasDisk())
  79             continue;
  80
  81         if (opt_store_doublecheck)
  82             if (e->disk().doubleCheck(*e))
  83                 ++store_errors;
  84
  85         EBIT_SET(e->flags, ENTRY_VALIDATED);
  86
  87         /*
  88          * Only set the file bit if we know its a valid entry
  89          * otherwise, set it in the validation procedure
  90          */
  91
  92         if ((++validated & 0x3FFFF) == 0)
  93             /* TODO format the int with with a stream operator */
  94             debugs(20, DBG_IMPORTANT, "  " << validated << " Entries Validated so far.");
  95     }
  96
  97     if (currentSearch->isDone()) {
  98         debugs(20, 2, "Seen: " << seen << " entries");
  99         debugs(20, DBG_IMPORTANT, "  Completed Validation Procedure");
 100         debugs(20, DBG_IMPORTANT, "  Validated " << validated << " Entries");
 101         debugs(20, DBG_IMPORTANT, "  store_swap_size = " << Store::Root().currentSize() / 1024.0 << " KB");
 102         --StoreController::store_dirs_rebuilding;
 103         assert(0 == StoreController::store_dirs_rebuilding);
 104
 105         if (opt_store_doublecheck && store_errors) {
 106             fatalf("Quitting after finding %d cache index inconsistencies. " \
 107                    "Removing cache index will force its slow rebuild. " \
 108                    "Removing -S will let Squid start with an inconsistent " \
 109                    "cache index (at your own risk).\n", store_errors);
 110         }
 111
 112         if (store_digest)
 113             storeDigestNoteStoreReady();
 114
 115         currentSearch = NULL;
 116     } else
 117         eventAdd("storeCleanup", storeCleanup, NULL, 0.0, 1);
 118 }
 119
 120 /* meta data recreated from disk image in swap directory */
 121 void
 122
 123 storeRebuildComplete(StoreRebuildData *dc)
 124 {
 125     if (dc) {
 126         counts.objcount += dc->objcount;
 127         counts.expcount += dc->expcount;
 128         counts.scancount += dc->scancount;
 129         counts.clashcount += dc->clashcount;
 130         counts.dupcount += dc->dupcount;
 131         counts.cancelcount += dc->cancelcount;
 132         counts.invalid += dc->invalid;
 133         counts.badflags += dc->badflags;
 134         counts.bad_log_op += dc->bad_log_op;
 135         counts.zero_object_sz += dc->zero_object_sz;
 136         counts.validations += dc->validations;
 137         counts.updateStartTime(dc->startTime);
 138     }
 139     // else the caller was not responsible for indexing its cache_dir
 140
 141     assert(StoreController::store_dirs_rebuilding > 1);
 142     --StoreController::store_dirs_rebuilding;
 143
 144     /*
 145      * When store_dirs_rebuilding == 1, it means we are done reading
 146      * or scanning all cache_dirs.  Now report the stats and start
 147      * the validation (storeCleanup()) thread.
 148      */
 149
 150     if (StoreController::store_dirs_rebuilding > 1)
 151         return;
 152
 153     const auto dt = tvSubDsec(counts.startTime, current_time);
 154
 155     debugs(20, DBG_IMPORTANT, "Finished rebuilding storage from disk.");
 156     debugs(20, DBG_IMPORTANT, "  " << std::setw(7) << counts.scancount  << " Entries scanned");
 157     debugs(20, DBG_IMPORTANT, "  " << std::setw(7) << counts.invalid  << " Invalid entries.");
 158     debugs(20, DBG_IMPORTANT, "  " << std::setw(7) << counts.badflags  << " With invalid flags.");
 159     debugs(20, DBG_IMPORTANT, "  " << std::setw(7) << counts.objcount  << " Objects loaded.");
 160     debugs(20, DBG_IMPORTANT, "  " << std::setw(7) << counts.expcount  << " Objects expired.");
 161     debugs(20, DBG_IMPORTANT, "  " << std::setw(7) << counts.cancelcount  << " Objects cancelled.");
 162     debugs(20, DBG_IMPORTANT, "  " << std::setw(7) << counts.dupcount  << " Duplicate URLs purged.");
 163     debugs(20, DBG_IMPORTANT, "  " << std::setw(7) << counts.clashcount  << " Swapfile clashes avoided.");
 164     debugs(20, DBG_IMPORTANT, "  Took "<< std::setw(3)<< std::setprecision(2) << dt << " seconds ("<< std::setw(6) <<
 165            ((double) counts.objcount / (dt > 0.0 ? dt : 1.0)) << " objects/sec).");
 166     debugs(20, DBG_IMPORTANT, "Beginning Validation Procedure");
 167
 168     eventAdd("storeCleanup", storeCleanup, NULL, 0.0, 1);
 169
 170     xfree(RebuildProgress);
 171
 172     RebuildProgress = NULL;
 173 }
 174
 175 /*
 176  * this is ugly.  We don't actually start any rebuild threads here,
 177  * but only initialize counters, etc.  The rebuild threads are
 178  * actually started by the filesystem "fooDirInit" function.
 179  */
 180 void
 181 storeRebuildStart(void)
 182 {
 183     counts = StoreRebuildData(); // reset counters
 184     /*
 185      * Note: store_dirs_rebuilding is initialized to 1.
 186      *
 187      * When we parse the configuration and construct each swap dir,
 188      * the construction of that raises the rebuild count.
 189      *
 190      * This prevents us from trying to write clean logs until we
 191      * finished rebuilding - including after a reconfiguration that opens an
 192      * existing swapdir.  The corresponding decrement * occurs in
 193      * storeCleanup(), when it is finished.
 194      */
 195     RebuildProgress = (store_rebuild_progress *)xcalloc(Config.cacheSwap.n_configured,
 196                       sizeof(store_rebuild_progress));
 197 }
 198
 199 /*
 200  * A fs-specific rebuild procedure periodically reports its
 201  * progress.
 202  */
 203 void
 204 storeRebuildProgress(int sd_index, int total, int sofar)
 205 {
 206     static time_t last_report = 0;
 207     // TODO: Switch to int64_t and fix handling of unknown totals.
 208     double n = 0.0;
 209     double d = 0.0;
 210
 211     if (sd_index < 0)
 212         return;
 213
 214     if (sd_index >= Config.cacheSwap.n_configured)
 215         return;
 216
 217     if (NULL == RebuildProgress)
 218         return;
 219
 220     RebuildProgress[sd_index].total = total;
 221
 222     RebuildProgress[sd_index].scanned = sofar;
 223
 224     if (squid_curtime - last_report < 15)
 225         return;
 226
 227     for (sd_index = 0; sd_index < Config.cacheSwap.n_configured; ++sd_index) {
 228         n += (double) RebuildProgress[sd_index].scanned;
 229         d += (double) RebuildProgress[sd_index].total;
 230     }
 231
 232     debugs(20, DBG_IMPORTANT, "Indexing cache entries: " << Progress(n, d));
 233     last_report = squid_curtime;
 234 }
 235
 236 void
 237 Progress::print(std::ostream &os) const
 238 {
 239     if (goal > 0) {
 240         const auto savedPrecision = os.precision(2);
 241         const auto percent = 100.0 * completed / goal;
 242         os << percent << "% (" << completed << " out of " << goal << ")";
 243         (void)os.precision(savedPrecision);
 244     } else if (!completed && !goal) {
 245         os << "nothing to do";
 246     } else {
 247         // unknown (i.e. negative) or buggy (i.e. zero when completed != 0) goal
 248         os << completed;
 249     }
 250 }
 251
 252 #include "fde.h"
 253 #include "Generic.h"
 254 #include "StoreMeta.h"
 255 #include "StoreMetaUnpacker.h"
 256
 257 struct InitStoreEntry : public unary_function<StoreMeta, void> {
 258     InitStoreEntry(StoreEntry *anEntry, cache_key *aKey):what(anEntry),index(aKey) {}
 259
 260     void operator()(StoreMeta const &x) {
 261         switch (x.getType()) {
 262
 263         case STORE_META_KEY:
 264             assert(x.length == SQUID_MD5_DIGEST_LENGTH);
 265             memcpy(index, x.value, SQUID_MD5_DIGEST_LENGTH);
 266             break;
 267
 268         case STORE_META_STD:
 269             struct old_metahdr {
 270                 time_t timestamp;
 271                 time_t lastref;
 272                 time_t expires;
 273                 time_t lastmod;
 274                 size_t swap_file_sz;
 275                 uint16_t refcount;
 276                 uint16_t flags;
 277             } *tmp;
 278             tmp = (struct old_metahdr *)x.value;
 279             assert(x.length == STORE_HDR_METASIZE_OLD);
 280             what->timestamp = tmp->timestamp;
 281             what->lastref = tmp->lastref;
 282             what->expires = tmp->expires;
 283             what->lastModified(tmp->lastmod);
 284             what->swap_file_sz = tmp->swap_file_sz;
 285             what->refcount = tmp->refcount;
 286             what->flags = tmp->flags;
 287             break;
 288
 289         case STORE_META_STD_LFS:
 290             assert(x.length == STORE_HDR_METASIZE);
 291             memcpy(&what->timestamp, x.value, STORE_HDR_METASIZE);
 292             break;
 293
 294         default:
 295             break;
 296         }
 297     }
 298
 299     StoreEntry *what;
 300     cache_key *index;
 301 };
 302
 303 bool
 304 storeRebuildLoadEntry(int fd, int diskIndex, MemBuf &buf, StoreRebuildData &)
 305 {
 306     if (fd < 0)
 307         return false;
 308
 309     assert(buf.hasSpace()); // caller must allocate
 310
 311     const int len = FD_READ_METHOD(fd, buf.space(), buf.spaceSize());
 312     ++ statCounter.syscalls.disk.reads;
 313     if (len < 0) {
 314         const int xerrno = errno;
 315         debugs(47, DBG_IMPORTANT, "WARNING: cache_dir[" << diskIndex << "]: " <<
 316                "Ignoring cached entry after meta data read failure: " << xstrerr(xerrno));
 317         return false;
 318     }
 319
 320     buf.appended(len);
 321     return true;
 322 }
 323
 324 bool
 325 storeRebuildParseEntry(MemBuf &buf, StoreEntry &tmpe, cache_key *key,
 326                        StoreRebuildData &stats,
 327                        uint64_t expectedSize)
 328 {
 329     int swap_hdr_len = 0;
 330     StoreMetaUnpacker aBuilder(buf.content(), buf.contentSize(), &swap_hdr_len);
 331     if (aBuilder.isBufferZero()) {
 332         debugs(47,5, HERE << "skipping empty record.");
 333         return false;
 334     }
 335
 336     StoreMeta *tlv_list = nullptr;
 337     try {
 338         tlv_list = aBuilder.createStoreMeta();
 339     } catch (const std::exception &e) {
 340         debugs(47, DBG_IMPORTANT, "WARNING: Ignoring store entry because " << e.what());
 341         return false;
 342     }
 343     assert(tlv_list);
 344
 345     // TODO: consume parsed metadata?
 346
 347     debugs(47,7, "successful swap meta unpacking; swap_file_sz=" << tmpe.swap_file_sz);
 348     memset(key, '\0', SQUID_MD5_DIGEST_LENGTH);
 349
 350     InitStoreEntry visitor(&tmpe, key);
 351     for_each(*tlv_list, visitor);
 352     storeSwapTLVFree(tlv_list);
 353     tlv_list = NULL;
 354
 355     if (storeKeyNull(key)) {
 356         debugs(47, DBG_IMPORTANT, "WARNING: Ignoring keyless cache entry");
 357         return false;
 358     }
 359
 360     tmpe.key = key;
 361     /* check sizes */
 362
 363     if (expectedSize > 0) {
 364         if (tmpe.swap_file_sz == 0) {
 365             tmpe.swap_file_sz = expectedSize;
 366         } else if (tmpe.swap_file_sz == (uint64_t)(expectedSize - swap_hdr_len)) {
 367             tmpe.swap_file_sz = expectedSize;
 368         } else if (tmpe.swap_file_sz != expectedSize) {
 369             debugs(47, DBG_IMPORTANT, "WARNING: Ignoring cache entry due to a " <<
 370                    "SIZE MISMATCH " << tmpe.swap_file_sz << "!=" << expectedSize);
 371             return false;
 372         }
 373     } else if (tmpe.swap_file_sz <= 0) {
 374         // if caller cannot handle unknown sizes, it must check after the call.
 375         debugs(47, 7, "unknown size: " << tmpe);
 376     }
 377
 378     if (EBIT_TEST(tmpe.flags, KEY_PRIVATE)) {
 379         ++ stats.badflags;
 380         return false;
 381     }
 382
 383     return true;
 384 }
 385