src/fs/ufs/RebuildState.cc

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