src/fs/ufs/RebuildState.cc

   1 /*
   2  *
   3  * DEBUG: section 47    Store Directory Routines
   4  * AUTHOR: Robert Collins
   5  *
   6  * SQUID Web Proxy Cache          http://www.squid-cache.org/
   7  * ----------------------------------------------------------
   8  *
   9  *  Squid is the result of efforts by numerous individuals from
  10  *  the Internet community; see the CONTRIBUTORS file for full
  11  *  details.   Many organizations have provided support for Squid's
  12  *  development; see the SPONSORS file for full details.  Squid is
  13  *  Copyrighted (C) 2001 by the Regents of the University of
  14  *  California; see the COPYRIGHT file for full details.  Squid
  15  *  incorporates software developed and/or copyrighted by other
  16  *  sources; see the CREDITS file for full details.
  17  *
  18  *  This program is free software; you can redistribute it and/or modify
  19  *  it under the terms of the GNU General Public License as published by
  20  *  the Free Software Foundation; either version 2 of the License, or
  21  *  (at your option) any later version.
  22  *
  23  *  This program is distributed in the hope that it will be useful,
  24  *  but WITHOUT ANY WARRANTY; without even the implied warranty of
  25  *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  26  *  GNU General Public License for more details.
  27  *
  28  *  You should have received a copy of the GNU General Public License
  29  *  along with this program; if not, write to the Free Software
  30  *  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA.
  31  *
  32  */
  33
  34 #include "squid.h"
  35 #include "protos.h"
  36 #include "RebuildState.h"
  37 #include "SquidTime.h"
  38 #include "StoreSwapLogData.h"
  39 #include "UFSSwapLogParser.h"
  40
  41 #if HAVE_MATH_H
  42 #include <math.h>
  43 #endif
  44 #if HAVE_SYS_STAT_H
  45 #include <sys/stat.h>
  46 #endif
  47 #if HAVE_ERRNO_H
  48 #include <errno.h>
  49 #endif
  50
  51 CBDATA_NAMESPACED_CLASS_INIT(Fs::Ufs,RebuildState);
  52
  53 Fs::Ufs::RebuildState::RebuildState(RefCount<UFSSwapDir> aSwapDir) :
  54         sd (aSwapDir), LogParser(NULL), e(NULL), fromLog(true), _done (false)
  55 {
  56     /*
  57      * If the swap.state file exists in the cache_dir, then
  58      * we'll use commonUfsDirRebuildFromSwapLog(), otherwise we'll
  59      * use commonUfsDirRebuildFromDirectory() to open up each file
  60      * and suck in the meta data.
  61      */
  62     int clean = 0;
  63     int zeroLengthLog = 0;
  64     FILE *fp = sd->openTmpSwapLog(&clean, &zeroLengthLog);
  65
  66     if (fp && !zeroLengthLog)
  67         LogParser = Fs::Ufs::UFSSwapLogParser::GetUFSSwapLogParser(fp);
  68
  69     if (LogParser == NULL ) {
  70         fromLog = false;
  71
  72         if (fp != NULL)
  73             fclose(fp);
  74
  75     } else {
  76         fromLog = true;
  77         flags.clean = (unsigned int) clean;
  78     }
  79
  80     if (!clean)
  81         flags.need_to_validate = 1;
  82
  83     debugs(47, DBG_IMPORTANT, "Rebuilding storage in " << sd->path << " (" <<
  84            (clean ? "clean log" : (LogParser ? "dirty log" : "no log")) << ")");
  85 }
  86
  87 Fs::Ufs::RebuildState::~RebuildState()
  88 {
  89     sd->closeTmpSwapLog();
  90
  91     if (LogParser)
  92         delete LogParser;
  93 }
  94
  95 void
  96 Fs::Ufs::RebuildState::RebuildStep(void *data)
  97 {
  98     RebuildState *rb = (RebuildState *)data;
  99     rb->rebuildStep();
 100
 101     if (!rb->isDone())
 102         eventAdd("storeRebuild", RebuildStep, rb, 0.01, 1);
 103     else {
 104         -- StoreController::store_dirs_rebuilding;
 105         storeRebuildComplete(&rb->counts);
 106         delete rb;
 107     }
 108 }
 109
 110 /// load entries from swap.state or files until we run out of entries or time
 111 void
 112 Fs::Ufs::RebuildState::rebuildStep()
 113 {
 114     currentEntry(NULL);
 115
 116     // Balance our desire to maximize the number of entries processed at once
 117     // (and, hence, minimize overheads and total rebuild time) with a
 118     // requirement to also process Coordinator events, disk I/Os, etc.
 119     const int maxSpentMsec = 50; // keep small: most RAM I/Os are under 1ms
 120     const timeval loopStart = current_time;
 121
 122     const int totalEntries = LogParser ? LogParser->SwapLogEntries() : -1;
 123
 124     while (!isDone()) {
 125         if (fromLog)
 126             rebuildFromSwapLog();
 127         else
 128             rebuildFromDirectory();
 129
 130         // TODO: teach storeRebuildProgress to handle totalEntries <= 0
 131         if (totalEntries > 0 && (n_read % 4000 == 0))
 132             storeRebuildProgress(sd->index, totalEntries, n_read);
 133
 134         if (opt_foreground_rebuild)
 135             continue; // skip "few entries at a time" check below
 136
 137         getCurrentTime();
 138         const double elapsedMsec = tvSubMsec(loopStart, current_time);
 139         if (elapsedMsec > maxSpentMsec || elapsedMsec < 0) {
 140             debugs(47, 5, HERE << "pausing after " << n_read << " entries in " <<
 141                    elapsedMsec << "ms; " << (elapsedMsec/n_read) << "ms per entry");
 142             break;
 143         }
 144     }
 145 }
 146
 147 /// process one cache file
 148 void
 149 Fs::Ufs::RebuildState::rebuildFromDirectory()
 150 {
 151     cache_key key[SQUID_MD5_DIGEST_LENGTH];
 152
 153     struct stat sb;
 154     int fd = -1;
 155     assert(this != NULL);
 156     debugs(47, 3, HERE << "DIR #" << sd->index);
 157
 158     assert(fd == -1);
 159     sfileno filn = 0;
 160     int size;
 161     fd = getNextFile(&filn, &size);
 162
 163     if (fd == -2) {
 164         debugs(47, DBG_IMPORTANT, "Done scanning " << sd->path << " dir (" <<
 165                n_read << " entries)");
 166         _done = true;
 167         return;
 168     } else if (fd < 0) {
 169         return;
 170     }
 171
 172     assert(fd > -1);
 173     /* lets get file stats here */
 174
 175     ++n_read;
 176
 177     if (fstat(fd, &sb) < 0) {
 178         debugs(47, DBG_IMPORTANT, HERE << "fstat(FD " << fd << "): " << xstrerror());
 179         file_close(fd);
 180         --store_open_disk_fd;
 181         fd = -1;
 182         return;
 183     }
 184
 185     MemBuf buf;
 186     buf.init(SM_PAGE_SIZE, SM_PAGE_SIZE);
 187     if (!storeRebuildLoadEntry(fd, sd->index, buf, counts))
 188         return;
 189
 190     StoreEntry tmpe;
 191     const bool loaded = storeRebuildParseEntry(buf, tmpe, key, counts,
 192                         (int64_t)sb.st_size);
 193
 194     file_close(fd);
 195     --store_open_disk_fd;
 196     fd = -1;
 197
 198     if (!loaded) {
 199         // XXX: shouldn't this be a call to commonUfsUnlink?
 200         sd->unlinkFile(filn); // should we unlink in all failure cases?
 201         return;
 202     }
 203
 204     if (!storeRebuildKeepEntry(tmpe, key, counts))
 205         return;
 206
 207     ++counts.objcount;
 208     // tmpe.dump(5);
 209     currentEntry(sd->addDiskRestore(key,
 210                                     filn,
 211                                     tmpe.swap_file_sz,
 212                                     tmpe.expires,
 213                                     tmpe.timestamp,
 214                                     tmpe.lastref,
 215                                     tmpe.lastmod,
 216                                     tmpe.refcount,  /* refcount */
 217                                     tmpe.flags,     /* flags */
 218                                     (int) flags.clean));
 219     storeDirSwapLog(currentEntry(), SWAP_LOG_ADD);
 220 }
 221
 222 StoreEntry *
 223 Fs::Ufs::RebuildState::currentEntry() const
 224 {
 225     return e;
 226 }
 227
 228 void
 229 Fs::Ufs::RebuildState::currentEntry(StoreEntry *newValue)
 230 {
 231     e = newValue;
 232 }
 233
 234 /// process one swap log entry
 235 void
 236 Fs::Ufs::RebuildState::rebuildFromSwapLog()
 237 {
 238     StoreSwapLogData swapData;
 239
 240     if (LogParser->ReadRecord(swapData) != 1) {
 241         debugs(47, DBG_IMPORTANT, "Done reading " << sd->path << " swaplog (" << n_read << " entries)");
 242         LogParser->Close();
 243         delete LogParser;
 244         LogParser = NULL;
 245         _done = true;
 246         return;
 247     }
 248
 249     ++n_read;
 250
 251     if (!swapData.sane()) {
 252         ++counts.invalid;
 253         return;
 254     }
 255
 256     /*
 257      * BC: during 2.4 development, we changed the way swap file
 258      * numbers are assigned and stored.  The high 16 bits used
 259      * to encode the SD index number.  There used to be a call
 260      * to storeDirProperFileno here that re-assigned the index
 261      * bits.  Now, for backwards compatibility, we just need
 262      * to mask it off.
 263      */
 264     swapData.swap_filen &= 0x00FFFFFF;
 265
 266     debugs(47, 3, HERE << swap_log_op_str[(int) swapData.op]  << " " <<
 267            storeKeyText(swapData.key)  << " "<< std::setfill('0') <<
 268            std::hex << std::uppercase << std::setw(8) <<
 269            swapData.swap_filen);
 270
 271     if (swapData.op == SWAP_LOG_ADD) {
 272         (void) 0;
 273     } else if (swapData.op == SWAP_LOG_DEL) {
 274         /* Delete unless we already have a newer copy anywhere in any store */
 275         /* this needs to become
 276          * 1) unpack url
 277          * 2) make synthetic request with headers ?? or otherwise search
 278          * for a matching object in the store
 279          * TODO FIXME change to new async api
 280          */
 281         currentEntry (Store::Root().get(swapData.key));
 282
 283         if (currentEntry() != NULL && swapData.lastref >= e->lastref) {
 284             undoAdd();
 285             --counts.objcount;
 286             ++counts.cancelcount;
 287         }
 288         return;
 289     } else {
 290         const double
 291         x = ::log(static_cast<double>(++counts.bad_log_op)) / ::log(10.0);
 292
 293         if (0.0 == x - (double) (int) x)
 294             debugs(47, DBG_IMPORTANT, "WARNING: " << counts.bad_log_op << " invalid swap log entries found");
 295
 296         ++counts.invalid;
 297
 298         return;
 299     }
 300
 301     ++counts.scancount; // XXX: should not this be incremented earlier?
 302
 303     if (!sd->validFileno(swapData.swap_filen, 0)) {
 304         ++counts.invalid;
 305         return;
 306     }
 307
 308     if (EBIT_TEST(swapData.flags, KEY_PRIVATE)) {
 309         ++counts.badflags;
 310         return;
 311     }
 312
 313     /* this needs to become
 314      * 1) unpack url
 315      * 2) make synthetic request with headers ?? or otherwise search
 316      * for a matching object in the store
 317      * TODO FIXME change to new async api
 318      */
 319     currentEntry (Store::Root().get(swapData.key));
 320
 321     int used;           /* is swapfile already in use? */
 322
 323     used = sd->mapBitTest(swapData.swap_filen);
 324
 325     /* If this URL already exists in the cache, does the swap log
 326      * appear to have a newer entry?  Compare 'lastref' from the
 327      * swap log to e->lastref. */
 328     /* is the log entry newer than current entry? */
 329     int disk_entry_newer = currentEntry() ? (swapData.lastref > currentEntry()->lastref ? 1 : 0) : 0;
 330
 331     if (used && !disk_entry_newer) {
 332         /* log entry is old, ignore it */
 333         ++counts.clashcount;
 334         return;
 335     } else if (used && currentEntry() && currentEntry()->swap_filen == swapData.swap_filen && currentEntry()->swap_dirn == sd->index) {
 336         /* swapfile taken, same URL, newer, update meta */
 337
 338         if (currentEntry()->store_status == STORE_OK) {
 339             currentEntry()->lastref = swapData.timestamp;
 340             currentEntry()->timestamp = swapData.timestamp;
 341             currentEntry()->expires = swapData.expires;
 342             currentEntry()->lastmod = swapData.lastmod;
 343             currentEntry()->flags = swapData.flags;
 344             currentEntry()->refcount += swapData.refcount;
 345             sd->dereference(*currentEntry());
 346         } else {
 347             debug_trap("commonUfsDirRebuildFromSwapLog: bad condition");
 348             debugs(47, DBG_IMPORTANT, HERE << "bad condition");
 349         }
 350         return;
 351     } else if (used) {
 352         /* swapfile in use, not by this URL, log entry is newer */
 353         /* This is sorta bad: the log entry should NOT be newer at this
 354          * point.  If the log is dirty, the filesize check should have
 355          * caught this.  If the log is clean, there should never be a
 356          * newer entry. */
 357         debugs(47, DBG_IMPORTANT, "WARNING: newer swaplog entry for dirno " <<
 358                sd->index  << ", fileno "<< std::setfill('0') << std::hex <<
 359                std::uppercase << std::setw(8) << swapData.swap_filen);
 360
 361         /* I'm tempted to remove the swapfile here just to be safe,
 362          * but there is a bad race condition in the NOVM version if
 363          * the swapfile has recently been opened for writing, but
 364          * not yet opened for reading.  Because we can't map
 365          * swapfiles back to StoreEntrys, we don't know the state
 366          * of the entry using that file.  */
 367         /* We'll assume the existing entry is valid, probably because
 368          * were in a slow rebuild and the the swap file number got taken
 369          * and the validation procedure hasn't run. */
 370         assert(flags.need_to_validate);
 371         ++counts.clashcount;
 372         return;
 373     } else if (currentEntry() && !disk_entry_newer) {
 374         /* key already exists, current entry is newer */
 375         /* keep old, ignore new */
 376         ++counts.dupcount;
 377         return;
 378     } else if (currentEntry()) {
 379         /* key already exists, this swapfile not being used */
 380         /* junk old, load new */
 381         undoAdd();
 382         --counts.objcount;
 383         ++counts.dupcount;
 384     } else {
 385         /* URL doesnt exist, swapfile not in use */
 386         /* load new */
 387         (void) 0;
 388     }
 389
 390     ++counts.objcount;
 391
 392     currentEntry(sd->addDiskRestore(swapData.key,
 393                                     swapData.swap_filen,
 394                                     swapData.swap_file_sz,
 395                                     swapData.expires,
 396                                     swapData.timestamp,
 397                                     swapData.lastref,
 398                                     swapData.lastmod,
 399                                     swapData.refcount,
 400                                     swapData.flags,
 401                                     (int) flags.clean));
 402
 403     storeDirSwapLog(currentEntry(), SWAP_LOG_ADD);
 404 }
 405
 406 /// undo the effects of adding an entry in rebuildFromSwapLog()
 407 void
 408 Fs::Ufs::RebuildState::undoAdd()
 409 {
 410     StoreEntry *added = currentEntry();
 411     assert(added);
 412     currentEntry(NULL);
 413
 414     // TODO: Why bother with these two if we are going to release?!
 415     added->expireNow();
 416     added->releaseRequest();
 417
 418     if (added->swap_filen > -1) {
 419         UFSSwapDir *sde = dynamic_cast<UFSSwapDir *>(INDEXSD(added->swap_dirn));
 420         assert(sde);
 421         sde->undoAddDiskRestore(added);
 422     }
 423
 424     added->release();
 425 }
 426
 427 int
 428 Fs::Ufs::RebuildState::getNextFile(sfileno * filn_p, int *size)
 429 {
 430     int fd = -1;
 431     int dirs_opened = 0;
 432     debugs(47, 3, HERE << "flag=" << flags.init  << ", " <<
 433            sd->index  << ": /"<< std::setfill('0') << std::hex <<
 434            std::uppercase << std::setw(2) << curlvl1  << "/" << std::setw(2) <<
 435            curlvl2);
 436
 437     if (done)
 438         return -2;
 439
 440     while (fd < 0 && done == 0) {
 441         fd = -1;
 442
 443         if (0 == flags.init) {  /* initialize, open first file */
 444             done = 0;
 445             curlvl1 = 0;
 446             curlvl2 = 0;
 447             in_dir = 0;
 448             flags.init = 1;
 449             assert(Config.cacheSwap.n_configured > 0);
 450         }
 451
 452         if (0 == in_dir) {  /* we need to read in a new directory */
 453             snprintf(fullpath, MAXPATHLEN, "%s/%02X/%02X",
 454                      sd->path,
 455                      curlvl1, curlvl2);
 456
 457             if (dirs_opened)
 458                 return -1;
 459
 460             td = opendir(fullpath);
 461
 462             ++dirs_opened;
 463
 464             if (td == NULL) {
 465                 debugs(47, DBG_IMPORTANT, HERE << "error in opendir (" << fullpath << "): " << xstrerror());
 466             } else {
 467                 entry = readdir(td);    /* skip . and .. */
 468                 entry = readdir(td);
 469
 470                 if (entry == NULL && errno == ENOENT)
 471                     debugs(47, DBG_IMPORTANT, HERE << "WARNING: directory does not exist!");
 472                 debugs(47, 3, HERE << "Directory " << fullpath);
 473             }
 474         }
 475
 476         if (td != NULL && (entry = readdir(td)) != NULL) {
 477             ++in_dir;
 478
 479             if (sscanf(entry->d_name, "%x", &fn) != 1) {
 480                 debugs(47, 3, HERE << "invalid entry " << entry->d_name);
 481                 continue;
 482             }
 483
 484             if (!UFSSwapDir::FilenoBelongsHere(fn, sd->index, curlvl1, curlvl2)) {
 485                 debugs(47, 3, HERE << std::setfill('0') <<
 486                        std::hex << std::uppercase << std::setw(8) << fn  <<
 487                        " does not belong in " << std::dec << sd->index  << "/" <<
 488                        curlvl1  << "/" << curlvl2);
 489
 490                 continue;
 491             }
 492
 493             if (sd->mapBitTest(fn)) {
 494                 debugs(47, 3, HERE << "Locked, continuing with next.");
 495                 continue;
 496             }
 497
 498             snprintf(fullfilename, MAXPATHLEN, "%s/%s",
 499                      fullpath, entry->d_name);
 500             debugs(47, 3, HERE << "Opening " << fullfilename);
 501             fd = file_open(fullfilename, O_RDONLY | O_BINARY);
 502
 503             if (fd < 0)
 504                 debugs(47, DBG_IMPORTANT, HERE << "error opening " << fullfilename << ": " << xstrerror());
 505             else
 506                 ++store_open_disk_fd;
 507
 508             continue;
 509         }
 510
 511         if (td != NULL)
 512             closedir(td);
 513
 514         td = NULL;
 515
 516         in_dir = 0;
 517
 518         if (sd->validL2(++curlvl2))
 519             continue;
 520
 521         curlvl2 = 0;
 522
 523         if (sd->validL1(++curlvl1))
 524             continue;
 525
 526         curlvl1 = 0;
 527
 528         done = 1;
 529     }
 530
 531     *filn_p = fn;
 532     return fd;
 533 }
 534
 535 bool
 536 Fs::Ufs::RebuildState::error() const
 537 {
 538     return false;
 539 }
 540
 541 bool
 542 Fs::Ufs::RebuildState::isDone() const
 543 {
 544     return _done;
 545 }
 546
 547 StoreEntry *
 548 Fs::Ufs::RebuildState::currentItem()
 549 {
 550     return currentEntry();
 551 }