src/fs/ufs/RebuildState.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 47    Store Directory Routines */
  10
  11 #include "squid.h"
  12 #include "fs_io.h"
  13 #include "globals.h"
  14 #include "RebuildState.h"
  15 #include "SquidConfig.h"
  16 #include "store/Disks.h"
  17 #include "store_key_md5.h"
  18 #include "store_rebuild.h"
  19 #include "StoreSwapLogData.h"
  20 #include "tools.h"
  21 #include "UFSSwapLogParser.h"
  22
  23 #include <cerrno>
  24 #include <cmath>
  25 #if HAVE_SYS_STAT_H
  26 #include <sys/stat.h>
  27 #endif
  28
  29 CBDATA_NAMESPACED_CLASS_INIT(Fs::Ufs,RebuildState);
  30
  31 Fs::Ufs::RebuildState::RebuildState(RefCount<UFSSwapDir> aSwapDir) :
  32     sd(aSwapDir),
  33     n_read(0),
  34     LogParser(nullptr),
  35     curlvl1(0),
  36     curlvl2(0),
  37     in_dir(0),
  38     done(0),
  39     fn(0),
  40     entry(nullptr),
  41     td(nullptr),
  42     fromLog(true),
  43     _done(false),
  44     cbdata(nullptr)
  45 {
  46
  47     /*
  48      * If the swap.state file exists in the cache_dir, then
  49      * we'll use commonUfsDirRebuildFromSwapLog(), otherwise we'll
  50      * use commonUfsDirRebuildFromDirectory() to open up each file
  51      * and suck in the meta data.
  52      */
  53     int clean = 0; //TODO: change to bool
  54     int zeroLengthLog = 0;
  55     FILE *fp = sd->openTmpSwapLog(&clean, &zeroLengthLog);
  56
  57     if (fp && !zeroLengthLog)
  58         LogParser = Fs::Ufs::UFSSwapLogParser::GetUFSSwapLogParser(fp);
  59
  60     if (LogParser == nullptr ) {
  61         fromLog = false;
  62
  63         if (fp != nullptr)
  64             fclose(fp);
  65
  66     } else {
  67         fromLog = true;
  68         flags.clean = (clean != 0);
  69     }
  70
  71     if (!clean)
  72         flags.need_to_validate = true;
  73
  74     counts.updateStartTime(current_time);
  75
  76     debugs(47, DBG_IMPORTANT, "Rebuilding storage in " << sd->path << " (" <<
  77            (clean ? "clean log" : (LogParser ? "dirty log" : "no log")) << ")");
  78 }
  79
  80 Fs::Ufs::RebuildState::~RebuildState()
  81 {
  82     sd->closeTmpSwapLog();
  83
  84     if (LogParser)
  85         delete LogParser;
  86 }
  87
  88 void
  89 Fs::Ufs::RebuildState::RebuildStep(void *data)
  90 {
  91     RebuildState *rb = (RebuildState *)data;
  92     if (!reconfiguring)
  93         rb->rebuildStep();
  94
  95     // delay storeRebuildComplete() when reconfiguring to protect storeCleanup()
  96     if (!rb->isDone() || reconfiguring)
  97         eventAdd("storeRebuild", RebuildStep, rb, 0.01, 1);
  98     else {
  99         storeRebuildComplete(&rb->counts);
 100         delete rb;
 101     }
 102 }
 103
 104 /// load entries from swap.state or files until we run out of entries or time
 105 void
 106 Fs::Ufs::RebuildState::rebuildStep()
 107 {
 108     // Balance our desire to maximize the number of entries processed at once
 109     // (and, hence, minimize overheads and total rebuild time) with a
 110     // requirement to also process Coordinator events, disk I/Os, etc.
 111     const int maxSpentMsec = 50; // keep small: most RAM I/Os are under 1ms
 112     const timeval loopStart = current_time;
 113
 114     const int totalEntries = LogParser ? LogParser->SwapLogEntries() : -1;
 115
 116     while (!isDone()) {
 117         if (fromLog)
 118             rebuildFromSwapLog();
 119         else
 120             rebuildFromDirectory();
 121
 122         // TODO: teach storeRebuildProgress to handle totalEntries <= 0
 123         if (totalEntries > 0 && (n_read % 4000 == 0))
 124             storeRebuildProgress(sd->index, totalEntries, n_read);
 125
 126         if (opt_foreground_rebuild)
 127             continue; // skip "few entries at a time" check below
 128
 129         getCurrentTime();
 130         const double elapsedMsec = tvSubMsec(loopStart, current_time);
 131         if (elapsedMsec > maxSpentMsec || elapsedMsec < 0) {
 132             debugs(47, 5, "pausing after " << n_read << " entries in " <<
 133                    elapsedMsec << "ms; " << (elapsedMsec/n_read) << "ms per entry");
 134             break;
 135         }
 136     }
 137 }
 138
 139 /// process one cache file
 140 void
 141 Fs::Ufs::RebuildState::rebuildFromDirectory()
 142 {
 143     cache_key key[SQUID_MD5_DIGEST_LENGTH];
 144
 145     struct stat sb;
 146     int fd = -1;
 147     debugs(47, 3, "DIR #" << sd->index);
 148
 149     assert(fd == -1);
 150     sfileno filn = 0;
 151     int size;
 152     fd = getNextFile(&filn, &size);
 153
 154     if (fd == -2) {
 155         debugs(47, DBG_IMPORTANT, "Done scanning " << sd->path << " dir (" <<
 156                n_read << " entries)");
 157         _done = true;
 158         return;
 159     } else if (fd < 0) {
 160         return;
 161     }
 162
 163     assert(fd > -1);
 164     /* lets get file stats here */
 165
 166     ++n_read;
 167
 168     if (fstat(fd, &sb) < 0) {
 169         int xerrno = errno;
 170         debugs(47, DBG_IMPORTANT, MYNAME << "fstat(FD " << fd << "): " << xstrerr(xerrno));
 171         file_close(fd);
 172         --store_open_disk_fd;
 173         fd = -1;
 174         return;
 175     }
 176
 177     MemBuf buf;
 178     buf.init(SM_PAGE_SIZE, SM_PAGE_SIZE);
 179     if (!storeRebuildLoadEntry(fd, sd->index, buf, counts))
 180         return;
 181
 182     const uint64_t expectedSize = sb.st_size > 0 ?
 183                                   static_cast<uint64_t>(sb.st_size) : 0;
 184
 185     StoreEntry tmpe;
 186     const bool parsed = storeRebuildParseEntry(buf, tmpe, key, counts,
 187                         expectedSize);
 188
 189     file_close(fd);
 190     --store_open_disk_fd;
 191     fd = -1;
 192
 193     bool accepted = parsed && tmpe.swap_file_sz > 0;
 194     if (parsed && !accepted) {
 195         debugs(47, DBG_IMPORTANT, "WARNING: Ignoring ufs cache entry with " <<
 196                "unknown size: " << tmpe);
 197         accepted = false;
 198     }
 199
 200     if (!accepted) {
 201         // XXX: shouldn't this be a call to commonUfsUnlink?
 202         sd->unlinkFile(filn); // should we unlink in all failure cases?
 203         return;
 204     }
 205
 206     addIfFresh(key,
 207                filn,
 208                tmpe.swap_file_sz,
 209                tmpe.expires,
 210                tmpe.timestamp,
 211                tmpe.lastref,
 212                tmpe.lastModified(),
 213                tmpe.refcount,
 214                tmpe.flags);
 215 }
 216
 217 /// if the loaded entry metadata is still relevant, indexes the entry
 218 void
 219 Fs::Ufs::RebuildState::addIfFresh(const cache_key *key,
 220                                   sfileno file_number,
 221                                   uint64_t swap_file_sz,
 222                                   time_t expires,
 223                                   time_t timestamp,
 224                                   time_t lastref,
 225                                   time_t lastmod,
 226                                   uint32_t refcount,
 227                                   uint16_t newFlags)
 228 {
 229     if (!evictStaleAndContinue(key, lastref, counts.dupcount))
 230         return;
 231
 232     ++counts.objcount;
 233     const auto addedEntry = sd->addDiskRestore(key,
 234                             file_number,
 235                             swap_file_sz,
 236                             expires,
 237                             timestamp,
 238                             lastref,
 239                             lastmod,
 240                             refcount,
 241                             newFlags,
 242                             0 /* XXX: unused */);
 243     storeDirSwapLog(addedEntry, SWAP_LOG_ADD);
 244 }
 245
 246 /// Evicts a matching entry if it was last touched before caller's maxRef.
 247 /// \returns false only if the matching entry was touched at or after maxRef,
 248 /// indicating that the caller has supplied outdated maxRef.
 249 bool
 250 Fs::Ufs::RebuildState::evictStaleAndContinue(const cache_key *candidateKey, const time_t maxRef, int &staleCount)
 251 {
 252     if (auto *indexedEntry = Store::Root().peek(candidateKey)) {
 253
 254         if (indexedEntry->lastref >= maxRef) {
 255             indexedEntry->abandon("Fs::Ufs::RebuildState::evictStaleAndContinue");
 256             ++counts.clashcount;
 257             return false;
 258         }
 259
 260         ++staleCount;
 261         indexedEntry->release(true); // evict previously indexedEntry
 262     }
 263
 264     return true;
 265 }
 266
 267 /// process one swap log entry
 268 void
 269 Fs::Ufs::RebuildState::rebuildFromSwapLog()
 270 {
 271     StoreSwapLogData swapData;
 272
 273     if (LogParser->ReadRecord(swapData) != 1) {
 274         debugs(47, DBG_IMPORTANT, "Done reading " << sd->path << " swaplog (" << n_read << " entries)");
 275         LogParser->Close();
 276         delete LogParser;
 277         LogParser = nullptr;
 278         _done = true;
 279         return;
 280     }
 281
 282     ++n_read;
 283
 284     if (!swapData.sane()) {
 285         ++counts.invalid;
 286         return;
 287     }
 288
 289     /*
 290      * BC: during 2.4 development, we changed the way swap file
 291      * numbers are assigned and stored.  The high 16 bits used
 292      * to encode the SD index number.  There used to be a call
 293      * to storeDirProperFileno here that re-assigned the index
 294      * bits.  Now, for backwards compatibility, we just need
 295      * to mask it off.
 296      */
 297     swapData.swap_filen &= 0x00FFFFFF;
 298
 299     debugs(47, 3, swap_log_op_str[(int) swapData.op]  << " " <<
 300            storeKeyText(swapData.key)  << " "<< std::setfill('0') <<
 301            std::hex << std::uppercase << std::setw(8) <<
 302            swapData.swap_filen);
 303
 304     if (swapData.op == SWAP_LOG_ADD) {
 305         (void) 0;
 306     } else if (swapData.op == SWAP_LOG_DEL) {
 307         // remove any older or same-age entry; +1 covers same-age entries
 308         (void)evictStaleAndContinue(swapData.key, swapData.lastref+1, counts.cancelcount);
 309         return;
 310     } else {
 311         const double
 312         x = ::log(static_cast<double>(++counts.bad_log_op)) / ::log(10.0);
 313
 314         if (0.0 == x - (double) (int) x)
 315             debugs(47, DBG_IMPORTANT, "WARNING: " << counts.bad_log_op << " invalid swap log entries found");
 316
 317         ++counts.invalid;
 318
 319         return;
 320     }
 321
 322     ++counts.scancount; // XXX: should not this be incremented earlier?
 323
 324     if (!sd->validFileno(swapData.swap_filen, 0)) {
 325         ++counts.invalid;
 326         return;
 327     }
 328
 329     if (EBIT_TEST(swapData.flags, KEY_PRIVATE)) {
 330         ++counts.badflags;
 331         return;
 332     }
 333
 334     if (sd->mapBitTest(swapData.swap_filen)) {
 335         // While we were scanning the logs, some (unrelated) entry was added to
 336         // our disk using our logged swap_filen. We could change our swap_filen
 337         // and move the store file, but there is no Store API to do that (TODO).
 338         ++counts.clashcount;
 339         return;
 340     }
 341
 342     addIfFresh(swapData.key,
 343                swapData.swap_filen,
 344                swapData.swap_file_sz,
 345                swapData.expires,
 346                swapData.timestamp,
 347                swapData.lastref,
 348                swapData.lastmod,
 349                swapData.refcount,
 350                swapData.flags);
 351 }
 352
 353 int
 354 Fs::Ufs::RebuildState::getNextFile(sfileno * filn_p, int *)
 355 {
 356     int fd = -1;
 357     int dirs_opened = 0;
 358     debugs(47, 3, "flag=" << flags.init  << ", " <<
 359            sd->index  << ": /"<< std::setfill('0') << std::hex <<
 360            std::uppercase << std::setw(2) << curlvl1  << "/" << std::setw(2) <<
 361            curlvl2);
 362
 363     if (done)
 364         return -2;
 365
 366     while (fd < 0 && done == 0) {
 367         fd = -1;
 368
 369         if (!flags.init) {  /* initialize, open first file */
 370             // XXX: 0's should not be needed, constructor inits now
 371             done = 0;
 372             curlvl1 = 0;
 373             curlvl2 = 0;
 374             in_dir = 0;
 375             flags.init = true;
 376             assert(Config.cacheSwap.n_configured > 0);
 377         }
 378
 379         if (0 == in_dir) {  /* we need to read in a new directory */
 380             fullpath.Printf("%s/%02X/%02X",
 381                             sd->path,
 382                             curlvl1, curlvl2);
 383
 384             if (dirs_opened)
 385                 return -1;
 386
 387             td = opendir(fullpath.c_str());
 388
 389             ++dirs_opened;
 390
 391             if (!td) {
 392                 int xerrno = errno;
 393                 debugs(47, DBG_IMPORTANT, "ERROR: " << MYNAME << "in opendir (" << fullpath << "): " << xstrerr(xerrno));
 394             } else {
 395                 entry = readdir(td);    /* skip . and .. */
 396                 entry = readdir(td);
 397
 398                 if (entry == nullptr && errno == ENOENT)
 399                     debugs(47, DBG_IMPORTANT, "WARNING: directory does not exist!");
 400                 debugs(47, 3, "Directory " << fullpath);
 401             }
 402         }
 403
 404         if (td != nullptr && (entry = readdir(td)) != nullptr) {
 405             ++in_dir;
 406
 407             if (sscanf(entry->d_name, "%x", &fn) != 1) {
 408                 debugs(47, 3, "invalid entry " << entry->d_name);
 409                 continue;
 410             }
 411
 412             if (!UFSSwapDir::FilenoBelongsHere(fn, sd->index, curlvl1, curlvl2)) {
 413                 debugs(47, 3, std::setfill('0') <<
 414                        std::hex << std::uppercase << std::setw(8) << fn  <<
 415                        " does not belong in " << std::dec << sd->index  << "/" <<
 416                        curlvl1  << "/" << curlvl2);
 417
 418                 continue;
 419             }
 420
 421             if (sd->mapBitTest(fn)) {
 422                 debugs(47, 3, "Locked, continuing with next.");
 423                 continue;
 424             }
 425
 426             fullfilename.Printf(SQUIDSBUFPH "/%s",
 427                                 SQUIDSBUFPRINT(fullpath), entry->d_name);
 428             debugs(47, 3, "Opening " << fullfilename);
 429             fd = file_open(fullfilename.c_str(), O_RDONLY | O_BINARY);
 430
 431             if (fd < 0) {
 432                 int xerrno = errno;
 433                 debugs(47, DBG_IMPORTANT, "ERROR: " << MYNAME << "opening " << fullfilename << ": " << xstrerr(xerrno));
 434             } else
 435                 ++store_open_disk_fd;
 436
 437             continue;
 438         }
 439
 440         if (td != nullptr)
 441             closedir(td);
 442
 443         td = nullptr;
 444
 445         in_dir = 0;
 446
 447         if (sd->validL2(++curlvl2))
 448             continue;
 449
 450         curlvl2 = 0;
 451
 452         if (sd->validL1(++curlvl1))
 453             continue;
 454
 455         curlvl1 = 0;
 456
 457         done = 1;
 458     }
 459
 460     *filn_p = fn;
 461     return fd;
 462 }
 463
 464 bool
 465 Fs::Ufs::RebuildState::error() const
 466 {
 467     return false;
 468 }
 469
 470 bool
 471 Fs::Ufs::RebuildState::isDone() const
 472 {
 473     return _done;
 474 }
 475