src/store_rebuild.cc

   1 /*
   2  * Copyright (C) 1996-2023 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 "debug/Messages.h"
  13 #include "event.h"
  14 #include "fde.h"
  15 #include "globals.h"
  16 #include "md5.h"
  17 #include "SquidConfig.h"
  18 #include "StatCounters.h"
  19 #include "Store.h"
  20 #include "store/Disk.h"
  21 #include "store/SwapMetaIn.h"
  22 #include "store_digest.h"
  23 #include "store_key_md5.h"
  24 #include "store_rebuild.h"
  25 #include "StoreSearch.h"
  26 #include "time/gadgets.h"
  27
  28 #include <cerrno>
  29
  30 static StoreRebuildData counts;
  31
  32 static void storeCleanup(void *);
  33
  34 // TODO: Either convert to Progress or replace with StoreRebuildData.
  35 // TODO: Handle unknown totals (UFS cache_dir that lost swap.state) correctly.
  36 typedef struct {
  37     /* total number of "swap.state" entries that will be read */
  38     int total;
  39     /* number of entries read so far */
  40     int scanned;
  41 } store_rebuild_progress;
  42
  43 static store_rebuild_progress *RebuildProgress = nullptr;
  44
  45 void
  46 StoreRebuildData::updateStartTime(const timeval &dirStartTime)
  47 {
  48     startTime = started() ? std::min(startTime, dirStartTime) : dirStartTime;
  49 }
  50
  51 /// handles the completion of zero or more post-rebuild storeCleanup() steps
  52 static void
  53 storeCleanupComplete()
  54 {
  55     assert(StoreController::store_dirs_rebuilding == 1); // we are the last act
  56     --StoreController::store_dirs_rebuilding;
  57
  58     if (store_digest)
  59         storeDigestNoteStoreReady();
  60 }
  61
  62 static void
  63 storeCleanup(void *)
  64 {
  65     static int store_errors = 0;
  66     static StoreSearchPointer currentSearch;
  67     static int validated = 0;
  68     static int seen = 0;
  69
  70     if (currentSearch == nullptr || currentSearch->isDone())
  71         currentSearch = Store::Root().search();
  72
  73     size_t statCount = 500;
  74
  75     // TODO: Avoid the loop (and ENTRY_VALIDATED) unless opt_store_doublecheck.
  76     while (statCount-- && !currentSearch->isDone() && currentSearch->next()) {
  77         StoreEntry *e;
  78
  79         e = currentSearch->currentItem();
  80
  81         ++seen;
  82
  83         if (EBIT_TEST(e->flags, ENTRY_VALIDATED))
  84             continue;
  85
  86         /*
  87          * Calling StoreEntry->release() has no effect because we're
  88          * still in 'store_rebuilding' state
  89          */
  90         if (!e->hasDisk())
  91             continue;
  92
  93         if (opt_store_doublecheck)
  94             if (e->disk().doubleCheck(*e))
  95                 ++store_errors;
  96
  97         EBIT_SET(e->flags, ENTRY_VALIDATED);
  98
  99         /*
 100          * Only set the file bit if we know its a valid entry
 101          * otherwise, set it in the validation procedure
 102          */
 103
 104         if ((++validated & 0x3FFFF) == 0)
 105             /* TODO format the int with with a stream operator */
 106             debugs(20, DBG_IMPORTANT, "  " << validated << " Entries Validated so far.");
 107     }
 108
 109     if (currentSearch->isDone()) {
 110         debugs(20, 2, "Seen: " << seen << " entries");
 111         debugs(20, Important(43), "Completed Validation Procedure" <<
 112                Debug::Extra << "Validated " << validated << " Entries" <<
 113                Debug::Extra << "store_swap_size = " << (Store::Root().currentSize()/1024.0) << " KB");
 114
 115         if (opt_store_doublecheck && store_errors) {
 116             fatalf("Quitting after finding %d cache index inconsistencies. " \
 117                    "Removing cache index will force its slow rebuild. " \
 118                    "Removing -S will let Squid start with an inconsistent " \
 119                    "cache index (at your own risk).\n", store_errors);
 120         }
 121
 122         storeCleanupComplete();
 123
 124         currentSearch = nullptr;
 125     } else
 126         eventAdd("storeCleanup", storeCleanup, nullptr, 0.0, 1);
 127 }
 128
 129 /* meta data recreated from disk image in swap directory */
 130 void
 131
 132 storeRebuildComplete(StoreRebuildData *dc)
 133 {
 134     if (dc) {
 135         counts.objcount += dc->objcount;
 136         counts.expcount += dc->expcount;
 137         counts.scancount += dc->scancount;
 138         counts.clashcount += dc->clashcount;
 139         counts.dupcount += dc->dupcount;
 140         counts.cancelcount += dc->cancelcount;
 141         counts.invalid += dc->invalid;
 142         counts.badflags += dc->badflags;
 143         counts.bad_log_op += dc->bad_log_op;
 144         counts.zero_object_sz += dc->zero_object_sz;
 145         counts.validations += dc->validations;
 146         counts.updateStartTime(dc->startTime);
 147     }
 148     // else the caller was not responsible for indexing its cache_dir
 149
 150     assert(StoreController::store_dirs_rebuilding > 1);
 151     --StoreController::store_dirs_rebuilding;
 152     if (StoreController::store_dirs_rebuilding > 1)
 153         return; // wait for more rebuilding cache_dirs to call us
 154
 155     // rebuilt all cache_dirs (if any)
 156
 157     safe_free(RebuildProgress);
 158
 159     if (!counts.started()) {
 160         assert(!counts.scancount);
 161         debugs(20, 5, "not responsible for rebuilding any cache_dirs: " << Config.cacheSwap.n_configured);
 162         // we did not even try to load any entries so we skip storeCleanup()'s
 163         // entry validation reports
 164         storeCleanupComplete();
 165         return;
 166     }
 167
 168     const auto dt = tvSubDsec(counts.startTime, current_time);
 169
 170     debugs(20, Important(46), "Finished rebuilding storage from disk." <<
 171            Debug::Extra << std::setw(7) << counts.scancount << " Entries scanned" <<
 172            Debug::Extra << std::setw(7) << counts.invalid << " Invalid entries" <<
 173            Debug::Extra << std::setw(7) << counts.badflags << " With invalid flags" <<
 174            Debug::Extra << std::setw(7) << counts.objcount << " Objects loaded" <<
 175            Debug::Extra << std::setw(7) << counts.expcount << " Objects expired" <<
 176            Debug::Extra << std::setw(7) << counts.cancelcount << " Objects canceled" <<
 177            Debug::Extra << std::setw(7) << counts.dupcount << " Duplicate URLs purged" <<
 178            Debug::Extra << std::setw(7) << counts.clashcount << " Swapfile clashes avoided" <<
 179            Debug::Extra << "Took " << std::setprecision(2) << dt << " seconds (" <<
 180            ((double) counts.objcount / (dt > 0.0 ? dt : 1.0)) << " objects/sec).");
 181     debugs(20, Important(56), "Beginning Validation Procedure");
 182
 183     eventAdd("storeCleanup", storeCleanup, nullptr, 0.0, 1);
 184 }
 185
 186 /*
 187  * this is ugly.  We don't actually start any rebuild threads here,
 188  * but only initialize counters, etc.  The rebuild threads are
 189  * actually started by the filesystem "fooDirInit" function.
 190  */
 191 void
 192 storeRebuildStart(void)
 193 {
 194     counts = StoreRebuildData(); // reset counters
 195     /*
 196      * Note: store_dirs_rebuilding is initialized to 1.
 197      *
 198      * When we parse the configuration and construct each swap dir,
 199      * the construction of that raises the rebuild count.
 200      *
 201      * This prevents us from trying to write clean logs until we finished
 202      * rebuilding - including after a reconfiguration that opens an existing
 203      * swapdir.  The corresponding decrement occurs in storeCleanupComplete().
 204      */
 205     RebuildProgress = (store_rebuild_progress *)xcalloc(Config.cacheSwap.n_configured,
 206                       sizeof(store_rebuild_progress));
 207 }
 208
 209 /*
 210  * A fs-specific rebuild procedure periodically reports its
 211  * progress.
 212  */
 213 void
 214 storeRebuildProgress(int sd_index, int total, int sofar)
 215 {
 216     static time_t last_report = 0;
 217     // TODO: Switch to int64_t and fix handling of unknown totals.
 218     double n = 0.0;
 219     double d = 0.0;
 220
 221     if (sd_index < 0)
 222         return;
 223
 224     if (sd_index >= Config.cacheSwap.n_configured)
 225         return;
 226
 227     if (nullptr == RebuildProgress)
 228         return;
 229
 230     RebuildProgress[sd_index].total = total;
 231
 232     RebuildProgress[sd_index].scanned = sofar;
 233
 234     if (squid_curtime - last_report < 15)
 235         return;
 236
 237     for (sd_index = 0; sd_index < Config.cacheSwap.n_configured; ++sd_index) {
 238         n += (double) RebuildProgress[sd_index].scanned;
 239         d += (double) RebuildProgress[sd_index].total;
 240     }
 241
 242     debugs(20, Important(57), "Indexing cache entries: " << Progress(n, d));
 243     last_report = squid_curtime;
 244 }
 245
 246 void
 247 Progress::print(std::ostream &os) const
 248 {
 249     if (goal > 0) {
 250         const auto savedPrecision = os.precision(2);
 251         const auto percent = 100.0 * completed / goal;
 252         os << percent << "% (" << completed << " out of " << goal << ")";
 253         (void)os.precision(savedPrecision);
 254     } else if (!completed && !goal) {
 255         os << "nothing to do";
 256     } else {
 257         // unknown (i.e. negative) or buggy (i.e. zero when completed != 0) goal
 258         os << completed;
 259     }
 260 }
 261
 262 bool
 263 storeRebuildLoadEntry(int fd, int diskIndex, MemBuf &buf, StoreRebuildData &)
 264 {
 265     if (fd < 0)
 266         return false;
 267
 268     assert(buf.hasSpace()); // caller must allocate
 269
 270     const int len = FD_READ_METHOD(fd, buf.space(), buf.spaceSize());
 271     ++ statCounter.syscalls.disk.reads;
 272     if (len < 0) {
 273         const int xerrno = errno;
 274         debugs(47, DBG_IMPORTANT, "WARNING: cache_dir[" << diskIndex << "]: " <<
 275                "Ignoring cached entry after meta data read failure: " << xstrerr(xerrno));
 276         return false;
 277     }
 278
 279     buf.appended(len);
 280     return true;
 281 }
 282
 283 bool
 284 storeRebuildParseEntry(MemBuf &buf, StoreEntry &tmpe, cache_key *key,
 285                        StoreRebuildData &stats,
 286                        uint64_t expectedSize)
 287 {
 288     uint64_t swap_hdr_len = 0;
 289
 290     tmpe.key = nullptr;
 291
 292     try {
 293         swap_hdr_len = Store::UnpackIndexSwapMeta(buf, tmpe, key);
 294     } catch (...) {
 295         debugs(47, Important(65), "WARNING: Indexer ignores a cache_dir entry: " << CurrentException);
 296         return false;
 297     }
 298
 299     // TODO: consume parsed metadata?
 300
 301     debugs(47,7, "successful swap meta unpacking; swap_file_sz=" << tmpe.swap_file_sz);
 302
 303     if (!tmpe.key) {
 304         debugs(47, DBG_IMPORTANT, "WARNING: Ignoring keyless cache entry");
 305         return false;
 306     }
 307
 308     /* check sizes */
 309
 310     if (expectedSize > 0) {
 311         if (tmpe.swap_file_sz == 0) {
 312             tmpe.swap_file_sz = expectedSize;
 313         } else if (tmpe.swap_file_sz == (uint64_t)(expectedSize - swap_hdr_len)) {
 314             tmpe.swap_file_sz = expectedSize;
 315         } else if (tmpe.swap_file_sz != expectedSize) {
 316             debugs(47, DBG_IMPORTANT, "WARNING: Ignoring cache entry due to a " <<
 317                    "SIZE MISMATCH " << tmpe.swap_file_sz << "!=" << expectedSize);
 318             return false;
 319         }
 320     } else if (tmpe.swap_file_sz <= 0) {
 321         // if caller cannot handle unknown sizes, it must check after the call.
 322         debugs(47, 7, "unknown size: " << tmpe);
 323     }
 324
 325     if (EBIT_TEST(tmpe.flags, KEY_PRIVATE)) {
 326         ++ stats.badflags;
 327         return false;
 328     }
 329
 330     return true;
 331 }
 332