1 /*
2 * Copyright (C) 1996-2021 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 "event.h"
13 #include "globals.h"
14 #include "md5.h"
15 #include "SquidConfig.h"
16 #include "SquidTime.h"
17 #include "StatCounters.h"
18 #include "Store.h"
19 #include "store/Disk.h"
20 #include "store_digest.h"
21 #include "store_key_md5.h"
22 #include "store_rebuild.h"
23 #include "StoreSearch.h"
24 // for tvSubDsec() which should be in SquidTime.h
25 #include "util.h"
26
27 #include <cerrno>
28
29 static StoreRebuildData counts;
30
31 static struct timeval rebuild_start;
32 static void storeCleanup(void *);
33
34 typedef struct {
35 /* total number of "swap.state" entries that will be read */
36 int total;
37 /* number of entries read so far */
38 int scanned;
39 } store_rebuild_progress;
40
41 static store_rebuild_progress *RebuildProgress = NULL;
42
43 static int
storeCleanupDoubleCheck(StoreEntry * e)44 storeCleanupDoubleCheck(StoreEntry * e)
45 {
46 SwapDir *SD = dynamic_cast<SwapDir *>(INDEXSD(e->swap_dirn));
47 return (SD->doubleCheck(*e));
48 }
49
50 static void
storeCleanup(void *)51 storeCleanup(void *)
52 {
53 static int store_errors = 0;
54 static StoreSearchPointer currentSearch;
55 static int validated = 0;
56 static int seen = 0;
57
58 if (currentSearch == NULL || currentSearch->isDone())
59 currentSearch = Store::Root().search();
60
61 size_t statCount = 500;
62
63 // TODO: Avoid the loop (and ENTRY_VALIDATED) unless opt_store_doublecheck.
64 while (statCount-- && !currentSearch->isDone() && currentSearch->next()) {
65 StoreEntry *e;
66
67 e = currentSearch->currentItem();
68
69 ++seen;
70
71 if (EBIT_TEST(e->flags, ENTRY_VALIDATED))
72 continue;
73
74 /*
75 * Calling StoreEntry->release() has no effect because we're
76 * still in 'store_rebuilding' state
77 */
78 if (!e->hasDisk())
79 continue;
80
81 if (opt_store_doublecheck)
82 if (storeCleanupDoubleCheck(e))
83 ++store_errors;
84
85 EBIT_SET(e->flags, ENTRY_VALIDATED);
86
87 /*
88 * Only set the file bit if we know its a valid entry
89 * otherwise, set it in the validation procedure
90 */
91
92 if ((++validated & 0x3FFFF) == 0)
93 /* TODO format the int with with a stream operator */
94 debugs(20, DBG_IMPORTANT, " " << validated << " Entries Validated so far.");
95 }
96
97 if (currentSearch->isDone()) {
98 debugs(20, 2, "Seen: " << seen << " entries");
99 debugs(20, DBG_IMPORTANT, " Completed Validation Procedure");
100 debugs(20, DBG_IMPORTANT, " Validated " << validated << " Entries");
101 debugs(20, DBG_IMPORTANT, " store_swap_size = " << Store::Root().currentSize() / 1024.0 << " KB");
102 --StoreController::store_dirs_rebuilding;
103 assert(0 == StoreController::store_dirs_rebuilding);
104
105 if (opt_store_doublecheck && store_errors) {
106 fatalf("Quitting after finding %d cache index inconsistencies. " \
107 "Removing cache index will force its slow rebuild. " \
108 "Removing -S will let Squid start with an inconsistent " \
109 "cache index (at your own risk).\n", store_errors);
110 }
111
112 if (store_digest)
113 storeDigestNoteStoreReady();
114
115 currentSearch = NULL;
116 } else
117 eventAdd("storeCleanup", storeCleanup, NULL, 0.0, 1);
118 }
119
120 /* meta data recreated from disk image in swap directory */
121 void
122
storeRebuildComplete(StoreRebuildData * dc)123 storeRebuildComplete(StoreRebuildData *dc)
124 {
125 double dt;
126 counts.objcount += dc->objcount;
127 counts.expcount += dc->expcount;
128 counts.scancount += dc->scancount;
129 counts.clashcount += dc->clashcount;
130 counts.dupcount += dc->dupcount;
131 counts.cancelcount += dc->cancelcount;
132 counts.invalid += dc->invalid;
133 counts.badflags += dc->badflags;
134 counts.bad_log_op += dc->bad_log_op;
135 counts.zero_object_sz += dc->zero_object_sz;
136 /*
137 * When store_dirs_rebuilding == 1, it means we are done reading
138 * or scanning all cache_dirs. Now report the stats and start
139 * the validation (storeCleanup()) thread.
140 */
141
142 if (StoreController::store_dirs_rebuilding > 1)
143 return;
144
145 dt = tvSubDsec(rebuild_start, current_time);
146
147 debugs(20, DBG_IMPORTANT, "Finished rebuilding storage from disk.");
148 debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.scancount << " Entries scanned");
149 debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.invalid << " Invalid entries.");
150 debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.badflags << " With invalid flags.");
151 debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.objcount << " Objects loaded.");
152 debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.expcount << " Objects expired.");
153 debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.cancelcount << " Objects cancelled.");
154 debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.dupcount << " Duplicate URLs purged.");
155 debugs(20, DBG_IMPORTANT, " " << std::setw(7) << counts.clashcount << " Swapfile clashes avoided.");
156 debugs(20, DBG_IMPORTANT, " Took "<< std::setw(3)<< std::setprecision(2) << dt << " seconds ("<< std::setw(6) <<
157 ((double) counts.objcount / (dt > 0.0 ? dt : 1.0)) << " objects/sec).");
158 debugs(20, DBG_IMPORTANT, "Beginning Validation Procedure");
159
160 eventAdd("storeCleanup", storeCleanup, NULL, 0.0, 1);
161
162 xfree(RebuildProgress);
163
164 RebuildProgress = NULL;
165 }
166
167 /*
168 * this is ugly. We don't actually start any rebuild threads here,
169 * but only initialize counters, etc. The rebuild threads are
170 * actually started by the filesystem "fooDirInit" function.
171 */
172 void
storeRebuildStart(void)173 storeRebuildStart(void)
174 {
175 counts = StoreRebuildData(); // reset counters
176 rebuild_start = current_time;
177 /*
178 * Note: store_dirs_rebuilding is initialized to 1.
179 *
180 * When we parse the configuration and construct each swap dir,
181 * the construction of that raises the rebuild count.
182 *
183 * This prevents us from trying to write clean logs until we
184 * finished rebuilding - including after a reconfiguration that opens an
185 * existing swapdir. The corresponding decrement * occurs in
186 * storeCleanup(), when it is finished.
187 */
188 RebuildProgress = (store_rebuild_progress *)xcalloc(Config.cacheSwap.n_configured,
189 sizeof(store_rebuild_progress));
190 }
191
192 /*
193 * A fs-specific rebuild procedure periodically reports its
194 * progress.
195 */
196 void
storeRebuildProgress(int sd_index,int total,int sofar)197 storeRebuildProgress(int sd_index, int total, int sofar)
198 {
199 static time_t last_report = 0;
200 double n = 0.0;
201 double d = 0.0;
202
203 if (sd_index < 0)
204 return;
205
206 if (sd_index >= Config.cacheSwap.n_configured)
207 return;
208
209 if (NULL == RebuildProgress)
210 return;
211
212 RebuildProgress[sd_index].total = total;
213
214 RebuildProgress[sd_index].scanned = sofar;
215
216 if (squid_curtime - last_report < 15)
217 return;
218
219 for (sd_index = 0; sd_index < Config.cacheSwap.n_configured; ++sd_index) {
220 n += (double) RebuildProgress[sd_index].scanned;
221 d += (double) RebuildProgress[sd_index].total;
222 }
223
224 debugs(20, DBG_IMPORTANT, "Store rebuilding is "<< std::setw(4)<< std::setprecision(2) << 100.0 * n / d << "% complete");
225 last_report = squid_curtime;
226 }
227
228 #include "fde.h"
229 #include "Generic.h"
230 #include "StoreMeta.h"
231 #include "StoreMetaUnpacker.h"
232
233 struct InitStoreEntry : public unary_function<StoreMeta, void> {
InitStoreEntryInitStoreEntry234 InitStoreEntry(StoreEntry *anEntry, cache_key *aKey):what(anEntry),index(aKey) {}
235
operator ()InitStoreEntry236 void operator()(StoreMeta const &x) {
237 switch (x.getType()) {
238
239 case STORE_META_KEY:
240 assert(x.length == SQUID_MD5_DIGEST_LENGTH);
241 memcpy(index, x.value, SQUID_MD5_DIGEST_LENGTH);
242 break;
243
244 case STORE_META_STD:
245 struct old_metahdr {
246 time_t timestamp;
247 time_t lastref;
248 time_t expires;
249 time_t lastmod;
250 size_t swap_file_sz;
251 uint16_t refcount;
252 uint16_t flags;
253 } *tmp;
254 tmp = (struct old_metahdr *)x.value;
255 assert(x.length == STORE_HDR_METASIZE_OLD);
256 what->timestamp = tmp->timestamp;
257 what->lastref = tmp->lastref;
258 what->expires = tmp->expires;
259 what->lastModified(tmp->lastmod);
260 what->swap_file_sz = tmp->swap_file_sz;
261 what->refcount = tmp->refcount;
262 what->flags = tmp->flags;
263 break;
264
265 case STORE_META_STD_LFS:
266 assert(x.length == STORE_HDR_METASIZE);
267 memcpy(&what->timestamp, x.value, STORE_HDR_METASIZE);
268 break;
269
270 default:
271 break;
272 }
273 }
274
275 StoreEntry *what;
276 cache_key *index;
277 };
278
279 bool
storeRebuildLoadEntry(int fd,int diskIndex,MemBuf & buf,StoreRebuildData &)280 storeRebuildLoadEntry(int fd, int diskIndex, MemBuf &buf, StoreRebuildData &)
281 {
282 if (fd < 0)
283 return false;
284
285 assert(buf.hasSpace()); // caller must allocate
286
287 const int len = FD_READ_METHOD(fd, buf.space(), buf.spaceSize());
288 ++ statCounter.syscalls.disk.reads;
289 if (len < 0) {
290 const int xerrno = errno;
291 debugs(47, DBG_IMPORTANT, "WARNING: cache_dir[" << diskIndex << "]: " <<
292 "Ignoring cached entry after meta data read failure: " << xstrerr(xerrno));
293 return false;
294 }
295
296 buf.appended(len);
297 return true;
298 }
299
300 bool
storeRebuildParseEntry(MemBuf & buf,StoreEntry & tmpe,cache_key * key,StoreRebuildData & stats,uint64_t expectedSize)301 storeRebuildParseEntry(MemBuf &buf, StoreEntry &tmpe, cache_key *key,
302 StoreRebuildData &stats,
303 uint64_t expectedSize)
304 {
305 int swap_hdr_len = 0;
306 StoreMetaUnpacker aBuilder(buf.content(), buf.contentSize(), &swap_hdr_len);
307 if (aBuilder.isBufferZero()) {
308 debugs(47,5, HERE << "skipping empty record.");
309 return false;
310 }
311
312 StoreMeta *tlv_list = nullptr;
313 try {
314 tlv_list = aBuilder.createStoreMeta();
315 } catch (const std::exception &e) {
316 debugs(47, DBG_IMPORTANT, "WARNING: Ignoring store entry because " << e.what());
317 return false;
318 }
319 assert(tlv_list);
320
321 // TODO: consume parsed metadata?
322
323 debugs(47,7, "successful swap meta unpacking; swap_file_sz=" << tmpe.swap_file_sz);
324 memset(key, '\0', SQUID_MD5_DIGEST_LENGTH);
325
326 InitStoreEntry visitor(&tmpe, key);
327 for_each(*tlv_list, visitor);
328 storeSwapTLVFree(tlv_list);
329 tlv_list = NULL;
330
331 if (storeKeyNull(key)) {
332 debugs(47, DBG_IMPORTANT, "WARNING: Ignoring keyless cache entry");
333 return false;
334 }
335
336 tmpe.key = key;
337 /* check sizes */
338
339 if (expectedSize > 0) {
340 if (tmpe.swap_file_sz == 0) {
341 tmpe.swap_file_sz = expectedSize;
342 } else if (tmpe.swap_file_sz == (uint64_t)(expectedSize - swap_hdr_len)) {
343 tmpe.swap_file_sz = expectedSize;
344 } else if (tmpe.swap_file_sz != expectedSize) {
345 debugs(47, DBG_IMPORTANT, "WARNING: Ignoring cache entry due to a " <<
346 "SIZE MISMATCH " << tmpe.swap_file_sz << "!=" << expectedSize);
347 return false;
348 }
349 } else if (tmpe.swap_file_sz <= 0) {
350 // if caller cannot handle unknown sizes, it must check after the call.
351 debugs(47, 7, "unknown size: " << tmpe);
352 }
353
354 if (EBIT_TEST(tmpe.flags, KEY_PRIVATE)) {
355 ++ stats.badflags;
356 return false;
357 }
358
359 return true;
360 }
361
362