src/fs/ufs/RebuildState.cc

   1 /*
   2  * Copyright (C) 1996-2015 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 "disk.h"
  13 #include "globals.h"
  14 #include "RebuildState.h"
  15 #include "SquidConfig.h"
  16 #include "SquidTime.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(NULL),
  35     curlvl1(0),
  36     curlvl2(0),
  37     in_dir(0),
  38     done(0),
  39     fn(0),
  40     entry(NULL),
  41     td(NULL),
  42     e(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     rb->rebuildStep();
  94
  95     if (!rb->isDone())
  96         eventAdd("storeRebuild", RebuildStep, rb, 0.01, 1);
  97     else {
  98         -- StoreController::store_dirs_rebuilding;
  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     currentEntry(NULL);
 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         debugs(47, DBG_IMPORTANT, HERE << "fstat(FD " << fd << "): " << xstrerror());
 172         file_close(fd);
 173         --store_open_disk_fd;
 174         fd = -1;
 175         return;
 176     }
 177
 178     MemBuf buf;
 179     buf.init(SM_PAGE_SIZE, SM_PAGE_SIZE);
 180     if (!storeRebuildLoadEntry(fd, sd->index, buf, counts))
 181         return;
 182
 183     const uint64_t expectedSize = sb.st_size > 0 ?
 184                                   static_cast<uint64_t>(sb.st_size) : 0;
 185
 186     StoreEntry tmpe;
 187     const bool parsed = storeRebuildParseEntry(buf, tmpe, key, counts,
 188                         expectedSize);
 189
 190     file_close(fd);
 191     --store_open_disk_fd;
 192     fd = -1;
 193
 194     bool accepted = parsed && tmpe.swap_file_sz > 0;
 195     if (parsed && !accepted) {
 196         debugs(47, DBG_IMPORTANT, "WARNING: Ignoring ufs cache entry with " <<
 197                "unknown size: " << tmpe);
 198         accepted = false;
 199     }
 200
 201     if (!accepted) {
 202         // XXX: shouldn't this be a call to commonUfsUnlink?
 203         sd->unlinkFile(filn); // should we unlink in all failure cases?
 204         return;
 205     }
 206
 207     if (!storeRebuildKeepEntry(tmpe, key, counts))
 208         return;
 209
 210     ++counts.objcount;
 211     // tmpe.dump(5);
 212     currentEntry(sd->addDiskRestore(key,
 213                                     filn,
 214                                     tmpe.swap_file_sz,
 215                                     tmpe.expires,
 216                                     tmpe.timestamp,
 217                                     tmpe.lastref,
 218                                     tmpe.lastmod,
 219                                     tmpe.refcount,  /* refcount */
 220                                     tmpe.flags,     /* flags */
 221                                     (int) flags.clean));
 222     storeDirSwapLog(currentEntry(), SWAP_LOG_ADD);
 223 }
 224
 225 StoreEntry *
 226 Fs::Ufs::RebuildState::currentEntry() const
 227 {
 228     return e;
 229 }
 230
 231 void
 232 Fs::Ufs::RebuildState::currentEntry(StoreEntry *newValue)
 233 {
 234     e = newValue;
 235 }
 236
 237 /// process one swap log entry
 238 void
 239 Fs::Ufs::RebuildState::rebuildFromSwapLog()
 240 {
 241     StoreSwapLogData swapData;
 242
 243     if (LogParser->ReadRecord(swapData) != 1) {
 244         debugs(47, DBG_IMPORTANT, "Done reading " << sd->path << " swaplog (" << n_read << " entries)");
 245         LogParser->Close();
 246         delete LogParser;
 247         LogParser = NULL;
 248         _done = true;
 249         return;
 250     }
 251
 252     ++n_read;
 253
 254     if (!swapData.sane()) {
 255         ++counts.invalid;
 256         return;
 257     }
 258
 259     /*
 260      * BC: during 2.4 development, we changed the way swap file
 261      * numbers are assigned and stored.  The high 16 bits used
 262      * to encode the SD index number.  There used to be a call
 263      * to storeDirProperFileno here that re-assigned the index
 264      * bits.  Now, for backwards compatibility, we just need
 265      * to mask it off.
 266      */
 267     swapData.swap_filen &= 0x00FFFFFF;
 268
 269     debugs(47, 3, HERE << swap_log_op_str[(int) swapData.op]  << " " <<
 270            storeKeyText(swapData.key)  << " "<< std::setfill('0') <<
 271            std::hex << std::uppercase << std::setw(8) <<
 272            swapData.swap_filen);
 273
 274     if (swapData.op == SWAP_LOG_ADD) {
 275         (void) 0;
 276     } else if (swapData.op == SWAP_LOG_DEL) {
 277         /* Delete unless we already have a newer copy anywhere in any store */
 278         /* this needs to become
 279          * 1) unpack url
 280          * 2) make synthetic request with headers ?? or otherwise search
 281          * for a matching object in the store
 282          * TODO FIXME change to new async api
 283          */
 284         currentEntry (Store::Root().get(swapData.key));
 285
 286         if (currentEntry() != NULL && swapData.lastref >= e->lastref) {
 287             undoAdd();
 288             --counts.objcount;
 289             ++counts.cancelcount;
 290         }
 291         return;
 292     } else {
 293         const double
 294         x = ::log(static_cast<double>(++counts.bad_log_op)) / ::log(10.0);
 295
 296         if (0.0 == x - (double) (int) x)
 297             debugs(47, DBG_IMPORTANT, "WARNING: " << counts.bad_log_op << " invalid swap log entries found");
 298
 299         ++counts.invalid;
 300
 301         return;
 302     }
 303
 304     ++counts.scancount; // XXX: should not this be incremented earlier?
 305
 306     if (!sd->validFileno(swapData.swap_filen, 0)) {
 307         ++counts.invalid;
 308         return;
 309     }
 310
 311     if (EBIT_TEST(swapData.flags, KEY_PRIVATE)) {
 312         ++counts.badflags;
 313         return;
 314     }
 315
 316     /* this needs to become
 317      * 1) unpack url
 318      * 2) make synthetic request with headers ?? or otherwise search
 319      * for a matching object in the store
 320      * TODO FIXME change to new async api
 321      */
 322     currentEntry (Store::Root().get(swapData.key));
 323
 324     int used;           /* is swapfile already in use? */
 325
 326     used = sd->mapBitTest(swapData.swap_filen);
 327
 328     /* If this URL already exists in the cache, does the swap log
 329      * appear to have a newer entry?  Compare 'lastref' from the
 330      * swap log to e->lastref. */
 331     /* is the log entry newer than current entry? */
 332     int disk_entry_newer = currentEntry() ? (swapData.lastref > currentEntry()->lastref ? 1 : 0) : 0;
 333
 334     if (used && !disk_entry_newer) {
 335         /* log entry is old, ignore it */
 336         ++counts.clashcount;
 337         return;
 338     } else if (used && currentEntry() && currentEntry()->swap_filen == swapData.swap_filen && currentEntry()->swap_dirn == sd->index) {
 339         /* swapfile taken, same URL, newer, update meta */
 340
 341         if (currentEntry()->store_status == STORE_OK) {
 342             currentEntry()->lastref = swapData.timestamp;
 343             currentEntry()->timestamp = swapData.timestamp;
 344             currentEntry()->expires = swapData.expires;
 345             currentEntry()->lastmod = swapData.lastmod;
 346             currentEntry()->flags = swapData.flags;
 347             currentEntry()->refcount += swapData.refcount;
 348             sd->dereference(*currentEntry(), false);
 349         } else {
 350             debug_trap("commonUfsDirRebuildFromSwapLog: bad condition");
 351             debugs(47, DBG_IMPORTANT, HERE << "bad condition");
 352         }
 353         return;
 354     } else if (used) {
 355         /* swapfile in use, not by this URL, log entry is newer */
 356         /* This is sorta bad: the log entry should NOT be newer at this
 357          * point.  If the log is dirty, the filesize check should have
 358          * caught this.  If the log is clean, there should never be a
 359          * newer entry. */
 360         debugs(47, DBG_IMPORTANT, "WARNING: newer swaplog entry for dirno " <<
 361                sd->index  << ", fileno "<< std::setfill('0') << std::hex <<
 362                std::uppercase << std::setw(8) << swapData.swap_filen);
 363
 364         /* I'm tempted to remove the swapfile here just to be safe,
 365          * but there is a bad race condition in the NOVM version if
 366          * the swapfile has recently been opened for writing, but
 367          * not yet opened for reading.  Because we can't map
 368          * swapfiles back to StoreEntrys, we don't know the state
 369          * of the entry using that file.  */
 370         /* We'll assume the existing entry is valid, probably because
 371          * were in a slow rebuild and the the swap file number got taken
 372          * and the validation procedure hasn't run. */
 373         assert(flags.need_to_validate);
 374         ++counts.clashcount;
 375         return;
 376     } else if (currentEntry() && !disk_entry_newer) {
 377         /* key already exists, current entry is newer */
 378         /* keep old, ignore new */
 379         ++counts.dupcount;
 380         return;
 381     } else if (currentEntry()) {
 382         /* key already exists, this swapfile not being used */
 383         /* junk old, load new */
 384         undoAdd();
 385         --counts.objcount;
 386         ++counts.dupcount;
 387     } else {
 388         /* URL doesnt exist, swapfile not in use */
 389         /* load new */
 390         (void) 0;
 391     }
 392
 393     ++counts.objcount;
 394
 395     currentEntry(sd->addDiskRestore(swapData.key,
 396                                     swapData.swap_filen,
 397                                     swapData.swap_file_sz,
 398                                     swapData.expires,
 399                                     swapData.timestamp,
 400                                     swapData.lastref,
 401                                     swapData.lastmod,
 402                                     swapData.refcount,
 403                                     swapData.flags,
 404                                     (int) flags.clean));
 405
 406     storeDirSwapLog(currentEntry(), SWAP_LOG_ADD);
 407 }
 408
 409 /// undo the effects of adding an entry in rebuildFromSwapLog()
 410 void
 411 Fs::Ufs::RebuildState::undoAdd()
 412 {
 413     StoreEntry *added = currentEntry();
 414     assert(added);
 415     currentEntry(NULL);
 416
 417     // TODO: Why bother with these two if we are going to release?!
 418     added->expireNow();
 419     added->releaseRequest();
 420
 421     if (added->swap_filen > -1) {
 422         SwapDir *someDir = INDEXSD(added->swap_dirn);
 423         assert(someDir);
 424         if (UFSSwapDir *ufsDir = dynamic_cast<UFSSwapDir*>(someDir))
 425             ufsDir->undoAddDiskRestore(added);
 426         // else the entry was loaded from and/or is currently in a non-UFS dir
 427         // Thus, there is no use in preserving its disk file (the only purpose
 428         // of undoAddDiskRestore!), even if we could. Instead, we release the
 429         // the entry and [eventually] unlink its disk file or free its slot.
 430     }
 431
 432     added->release();
 433 }
 434
 435 int
 436 Fs::Ufs::RebuildState::getNextFile(sfileno * filn_p, int *)
 437 {
 438     int fd = -1;
 439     int dirs_opened = 0;
 440     debugs(47, 3, HERE << "flag=" << flags.init  << ", " <<
 441            sd->index  << ": /"<< std::setfill('0') << std::hex <<
 442            std::uppercase << std::setw(2) << curlvl1  << "/" << std::setw(2) <<
 443            curlvl2);
 444
 445     if (done)
 446         return -2;
 447
 448     while (fd < 0 && done == 0) {
 449         fd = -1;
 450
 451         if (!flags.init) {  /* initialize, open first file */
 452             // XXX: 0's should not be needed, constructor inits now
 453             done = 0;
 454             curlvl1 = 0;
 455             curlvl2 = 0;
 456             in_dir = 0;
 457             flags.init = true;
 458             assert(Config.cacheSwap.n_configured > 0);
 459         }
 460
 461         if (0 == in_dir) {  /* we need to read in a new directory */
 462             snprintf(fullpath, MAXPATHLEN, "%s/%02X/%02X",
 463                      sd->path,
 464                      curlvl1, curlvl2);
 465
 466             if (dirs_opened)
 467                 return -1;
 468
 469             td = opendir(fullpath);
 470
 471             ++dirs_opened;
 472
 473             if (td == NULL) {
 474                 debugs(47, DBG_IMPORTANT, HERE << "error in opendir (" << fullpath << "): " << xstrerror());
 475             } else {
 476                 entry = readdir(td);    /* skip . and .. */
 477                 entry = readdir(td);
 478
 479                 if (entry == NULL && errno == ENOENT)
 480                     debugs(47, DBG_IMPORTANT, HERE << "WARNING: directory does not exist!");
 481                 debugs(47, 3, HERE << "Directory " << fullpath);
 482             }
 483         }
 484
 485         if (td != NULL && (entry = readdir(td)) != NULL) {
 486             ++in_dir;
 487
 488             if (sscanf(entry->d_name, "%x", &fn) != 1) {
 489                 debugs(47, 3, HERE << "invalid entry " << entry->d_name);
 490                 continue;
 491             }
 492
 493             if (!UFSSwapDir::FilenoBelongsHere(fn, sd->index, curlvl1, curlvl2)) {
 494                 debugs(47, 3, HERE << std::setfill('0') <<
 495                        std::hex << std::uppercase << std::setw(8) << fn  <<
 496                        " does not belong in " << std::dec << sd->index  << "/" <<
 497                        curlvl1  << "/" << curlvl2);
 498
 499                 continue;
 500             }
 501
 502             if (sd->mapBitTest(fn)) {
 503                 debugs(47, 3, HERE << "Locked, continuing with next.");
 504                 continue;
 505             }
 506
 507             snprintf(fullfilename, MAXPATHLEN, "%s/%s",
 508                      fullpath, entry->d_name);
 509             debugs(47, 3, HERE << "Opening " << fullfilename);
 510             fd = file_open(fullfilename, O_RDONLY | O_BINARY);
 511
 512             if (fd < 0)
 513                 debugs(47, DBG_IMPORTANT, HERE << "error opening " << fullfilename << ": " << xstrerror());
 514             else
 515                 ++store_open_disk_fd;
 516
 517             continue;
 518         }
 519
 520         if (td != NULL)
 521             closedir(td);
 522
 523         td = NULL;
 524
 525         in_dir = 0;
 526
 527         if (sd->validL2(++curlvl2))
 528             continue;
 529
 530         curlvl2 = 0;
 531
 532         if (sd->validL1(++curlvl1))
 533             continue;
 534
 535         curlvl1 = 0;
 536
 537         done = 1;
 538     }
 539
 540     *filn_p = fn;
 541     return fd;
 542 }
 543
 544 bool
 545 Fs::Ufs::RebuildState::error() const
 546 {
 547     return false;
 548 }
 549
 550 bool
 551 Fs::Ufs::RebuildState::isDone() const
 552 {
 553     return _done;
 554 }
 555
 556 StoreEntry *
 557 Fs::Ufs::RebuildState::currentItem()
 558 {
 559     return currentEntry();
 560 }
 561