From: wessels <> Date: Sat, 30 Mar 1996 04:17:23 +0000 (+0000) Subject: assign store.c to debugging section 20 X-Git-Tag: SQUID_3_0_PRE1~6336 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=c943f3313a892d71be08ad823a58b1969e56a817;p=thirdparty%2Fsquid.git assign store.c to debugging section 20 fixed storeRebuildFromDisk bug introduced when switched from fdopen(, "a") to fdopen(, "w"). Now storeInit() makes a little more sense. --- diff --git a/src/store.cc b/src/store.cc index a17bed48c6..b4fc582074 100644 --- a/src/store.cc +++ b/src/store.cc @@ -1,5 +1,9 @@ -/* $Id: store.cc,v 1.15 1996/03/29 01:07:38 wessels Exp $ */ +/* $Id: store.cc,v 1.16 1996/03/29 21:17:23 wessels Exp $ */ + +/* + * DEBUG: Section 20 store + */ /* * Here is a summary of the routines which change mem_status and swap_status: @@ -70,9 +74,7 @@ static unsigned long store_swap_high = 0; static unsigned long store_swap_low = 0; static int swaplog_fd = 0; static int swaplog_lock; -static int swaplog_tmp_fd = 0; FILE *swaplog_stream = NULL; -FILE *swaplog_tmp_stream = NULL; /* counter for uncachable objects */ static int uncache_count = 0; @@ -80,6 +82,7 @@ static int keychange_count = 0; /* key temp buffer */ static char key_temp_buffer[MAX_URL]; +static char swaplog_file[MAX_FILE_NAME_LEN]; /* patch cache_dir to accomodate multiple disk storage */ dynamic_array *cache_dirs = NULL; @@ -143,7 +146,7 @@ void create_store_mem_obj(e) { if (e) { if (has_mem_obj(e)) - debug(0, 1, "create_store_mem_obj: old memory not released\n"); + debug(20, 1, "create_store_mem_obj: old memory not released\n"); e->mem_obj = (MemObject *) xcalloc(1, sizeof(MemObject)); meta_data.store_in_mem_objects++; } @@ -207,7 +210,7 @@ void storeSetMemStatus(e, status) if (e->mem_status == IN_MEMORY && status != IN_MEMORY) { if (e->key == NULL) { - debug(0, 0, "storeSetMemStatus: NULL key for %s\n", e->url); + debug(20, 0, "storeSetMemStatus: NULL key for %s\n", e->url); return; } if ((ptr = hash_lookup(in_mem_table, e->key))) @@ -229,13 +232,13 @@ void storeFreeEntry(e) if (e == (StoreEntry *) NULL) return; - debug(0, 5, "storeFreeEntry: Freeing %s\n", e->url); + debug(20, 5, "storeFreeEntry: Freeing %s\n", e->url); if (has_mem_obj(e)) { store_mem_size -= e->mem_obj->e_current_len - e->mem_obj->e_lowest_offset; - debug(0, 8, "storeFreeEntry: Freeing %d in-memory bytes\n", + debug(20, 8, "storeFreeEntry: Freeing %d in-memory bytes\n", e->mem_obj->e_current_len); - debug(0, 8, "storeFreeEntry: store_mem_size = %d\n", store_mem_size); + debug(20, 8, "storeFreeEntry: store_mem_size = %d\n", store_mem_size); if (e->mem_obj->data) { e->mem_obj->data->mem_free(e->mem_obj->data); e->mem_obj->data = NULL; @@ -270,11 +273,11 @@ void storeFreeEntry(e) void storeFreeEntryData(e) StoreEntry *e; { - debug(0, 5, "storeFreeEntryData: Freeing data-buffer only %s\n", e->url); + debug(20, 5, "storeFreeEntryData: Freeing data-buffer only %s\n", e->url); store_mem_size -= e->mem_obj->e_current_len - e->mem_obj->e_lowest_offset; - debug(0, 8, "storeFreeEntryData: Freeing %d in-memory bytes\n", + debug(20, 8, "storeFreeEntryData: Freeing %d in-memory bytes\n", e->mem_obj->e_current_len); - debug(0, 8, "storeFreeEntryData: store_mem_size = %d\n", store_mem_size); + debug(20, 8, "storeFreeEntryData: store_mem_size = %d\n", store_mem_size); e->object_len = 0; e->mem_obj->e_current_len = 0; if (e->mem_obj->data) { @@ -288,13 +291,13 @@ void storeFreeEntryData(e) void storePurgeMem(e) StoreEntry *e; { - debug(0, 5, "storePurgeMem: Freeing memory-copy of %s\n", e->url); + debug(20, 5, "storePurgeMem: Freeing memory-copy of %s\n", e->url); if (!has_mem_obj(e)) return; if (storeEntryLocked(e)) { - debug(0, 0, "storePurgeMem: someone (storeGetMemSpace?) is purging a locked object?\n"); - debug(0, 0, "%s", storeToString(e)); + debug(20, 0, "storePurgeMem: someone (storeGetMemSpace?) is purging a locked object?\n"); + debug(20, 0, "%s", storeToString(e)); fatal_dump(NULL); } /* free up memory data */ @@ -304,9 +307,9 @@ void storePurgeMem(e) --meta_data.hot_vm; } store_mem_size -= e->object_len - e->mem_obj->e_lowest_offset; - debug(0, 8, "storePurgeMem: Freeing %d in-memory bytes\n", + debug(20, 8, "storePurgeMem: Freeing %d in-memory bytes\n", e->object_len); - debug(0, 8, "storePurgeMem: store_mem_size = %d\n", store_mem_size); + debug(20, 8, "storePurgeMem: store_mem_size = %d\n", store_mem_size); storeSetMemStatus(e, NOT_IN_MEMORY); e->mem_obj->e_current_len = 0; /* free up pending list table */ @@ -332,13 +335,13 @@ int storeLockObject(e) int status = 0; e->lock_count++; - debug(0, 5, "storeLockObject: locks %d: \n", e->lock_count, e->url); + debug(20, 5, "storeLockObject: locks %d: \n", e->lock_count, e->url); if ((e->mem_status == NOT_IN_MEMORY) && /* Not in memory */ (e->swap_status != SWAP_OK) && /* Not on disk */ (e->status != STORE_PENDING) /* Not being fetched */ ) { - debug(0, 0, "storeLockObject: NOT_IN_MEMORY && !SWAP_OK && !STORE_PENDING conflict: . aborting...\n", e->url); + debug(20, 0, "storeLockObject: NOT_IN_MEMORY && !SWAP_OK && !STORE_PENDING conflict: . aborting...\n", e->url); /* If this sanity check fails, we should just ... */ fatal_dump(NULL); } @@ -372,7 +375,7 @@ int storeUnlockObject(e) if ((int) e->lock_count > 0) e->lock_count--; else if (e->lock_count == 0) { - debug(0, 0, "Entry lock count %d is out-of-whack\n", e->lock_count); + debug(20, 0, "Entry lock count %d is out-of-whack\n", e->lock_count); } /* Prevent UMR if we end up freeing the entry */ e_lock_count = (int) e->lock_count; @@ -405,7 +408,7 @@ StoreEntry *storeGet(url) { hash_link *hptr = NULL; - debug(0, 5, "storeGet: looking up %s\n", url); + debug(20, 5, "storeGet: looking up %s\n", url); if (table != (HashID) 0) { if ((hptr = hash_lookup(table, url)) != NULL) @@ -418,7 +421,7 @@ char *storeGenerateKey(url, request_type_id) char *url; int request_type_id; { - debug(0, 5, "storeGenerateKey: type=%d %s\n", request_type_id, url); + debug(20, 5, "storeGenerateKey: type=%d %s\n", request_type_id, url); if (request_type_id == REQUEST_OP_POST) { sprintf(key_temp_buffer, "/post/%s", url); return key_temp_buffer; @@ -446,7 +449,7 @@ StoreEntry *storeAdd(url, type_notused, mime_hdr, cachable, html_request, reques char key[MAX_URL + 16]; StoreEntry *e = NULL; - debug(0, 5, "storeAdd: %s\n", url); + debug(20, 5, "storeAdd: %s\n", url); meta_data.store_entries++; meta_data.url_strings += strlen(url); @@ -543,13 +546,13 @@ StoreEntry *storeAddDiskRestore(url, file_number, size, expires, timestamp) { StoreEntry *e = NULL; - debug(0, 5, "StoreAddDiskRestore: : size %d: expires %d: file_number %d\n", + debug(20, 5, "StoreAddDiskRestore: : size %d: expires %d: file_number %d\n", url, size, expires, file_number); if (file_map_bit_test(file_number)) { - debug(0, 0, "This file number is already allocated!\n"); - debug(0, 0, " --> file_number %d\n", file_number); - debug(0, 0, " --> \n", url); + debug(20, 0, "This file number is already allocated!\n"); + debug(20, 0, " --> file_number %d\n", file_number); + debug(20, 0, " --> \n", url); return (NULL); } meta_data.store_entries++; @@ -598,7 +601,7 @@ int storeRegister(e, fd, handler, data) PendingEntry *pe = (PendingEntry *) xmalloc(sizeof(PendingEntry)); int old_size, i, j; - debug(0, 5, "storeRegister: FD %d \n", fd, e->url); + debug(20, 5, "storeRegister: FD %d \n", fd, e->url); memset(pe, '\0', sizeof(PendingEntry)); pe->fd = fd; @@ -636,7 +639,7 @@ int storeRegister(e, fd, handler, data) safe_free(e->mem_obj->pending); e->mem_obj->pending = tmp; - debug(0, 10, "storeRegister: grew pending list to %d for slot %d.\n", + debug(20, 10, "storeRegister: grew pending list to %d for slot %d.\n", e->mem_obj->pending_list_size, i); } @@ -654,7 +657,7 @@ int storeUnregister(e, fd) int i; int freed = 0; - debug(0, 10, "storeUnregister: called for FD %d \n", fd, e->url); + debug(20, 10, "storeUnregister: called for FD %d \n", fd, e->url); /* look for entry in client_list */ if (e->mem_obj->client_list) { @@ -676,7 +679,7 @@ int storeUnregister(e, fd) } } - debug(0, 10, "storeUnregister: returning %d\n", freed); + debug(20, 10, "storeUnregister: returning %d\n", freed); return freed; } @@ -691,8 +694,8 @@ void storeDeleteBehind(e) int n_client = 0; int i; - debug(0, 3, "storeDeleteBehind: Object: %s\n", e->key); - debug(0, 3, "storeDeleteBehind:\tOriginal Lowest Offset: %d \n", e->mem_obj->e_lowest_offset); + debug(20, 3, "storeDeleteBehind: Object: %s\n", e->key); + debug(20, 3, "storeDeleteBehind:\tOriginal Lowest Offset: %d \n", e->mem_obj->e_lowest_offset); free_up_to = e->mem_obj->e_lowest_offset; target_offset = 0; @@ -708,18 +711,18 @@ void storeDeleteBehind(e) } if (n_client == 0) { - debug(0, 3, "storeDeleteBehind:\tThere is no client in the list.\n"); - debug(0, 3, "\t\tTry to delete as fast as possible.\n"); + debug(20, 3, "storeDeleteBehind:\tThere is no client in the list.\n"); + debug(20, 3, "\t\tTry to delete as fast as possible.\n"); target_offset = e->mem_obj->e_current_len; } - debug(0, 3, "storeDeleteBehind:\tThe target offset is : %d\n", target_offset); + debug(20, 3, "storeDeleteBehind:\tThe target offset is : %d\n", target_offset); if (target_offset) { free_up_to = (int) e->mem_obj->data->mem_free_data_upto(e->mem_obj->data, target_offset); - debug(0, 3, " Object is freed upto : %d\n", free_up_to); + debug(20, 3, " Object is freed upto : %d\n", free_up_to); store_mem_size -= free_up_to - e->mem_obj->e_lowest_offset; } - debug(0, 3, "storeDeleteBehind:\tOutgoing Lowest Offset : %d\n", free_up_to); + debug(20, 3, "storeDeleteBehind:\tOutgoing Lowest Offset : %d\n", free_up_to); e->mem_obj->e_lowest_offset = free_up_to; } @@ -752,12 +755,12 @@ static void InvokeHandlers(e) void storeStartDeleteBehind(e) StoreEntry *e; { - debug(0, 2, "storeStartDeleteBehind: Object: %s\n", e->key); + debug(20, 2, "storeStartDeleteBehind: Object: %s\n", e->key); if (e->flag & DELETE_BEHIND) { - debug(0, 2, "storeStartDeleteBehind:\tis already in delete behind mode.\n"); + debug(20, 2, "storeStartDeleteBehind:\tis already in delete behind mode.\n"); return; } - debug(0, 2, "storeStartDeleteBehind:\tis now in delete behind mode.\n"); + debug(20, 2, "storeStartDeleteBehind:\tis now in delete behind mode.\n"); /* change its key, so it couldn't be found by other client */ storeChangeKey(e); BIT_SET(e->flag, DELETE_BEHIND); @@ -774,26 +777,26 @@ int storeAppend(e, data, len) { /* validity check -- sometimes it's called with bogus values */ if (e == NULL || !has_mem_obj(e) || e->mem_obj->data == NULL) { - debug(0, 0, "storeAppend (len = %d): Invalid StoreEntry, aborting...\n", + debug(20, 0, "storeAppend (len = %d): Invalid StoreEntry, aborting...\n", len); if (len < 512) fwrite(data, len, 1, debug_log); - debug(0, 0, "%s", storeToString(e)); + debug(20, 0, "%s", storeToString(e)); fatal_dump(NULL); } if (len) { - debug(0, 5, "storeAppend: appending %d bytes for %s\n", len, e->url); + debug(20, 5, "storeAppend: appending %d bytes for %s\n", len, e->url); /* get some extra storage if needed */ (void) storeGetMemSpace(len, 0); store_mem_size += len; - debug(0, 8, "storeAppend: growing store_mem_size by %d\n", len); - debug(0, 8, "storeAppend: store_mem_size = %d\n", store_mem_size); + debug(20, 8, "storeAppend: growing store_mem_size by %d\n", len); + debug(20, 8, "storeAppend: store_mem_size = %d\n", store_mem_size); (void) e->mem_obj->data->mem_append(e->mem_obj->data, data, len); e->mem_obj->e_current_len += len; - debug(0, 8, "storeAppend: e_current_len = %d\n", + debug(20, 8, "storeAppend: e_current_len = %d\n", e->mem_obj->e_current_len); } if ((e->status != STORE_ABORTED) && !(e->flag & DELAY_SENDING)) @@ -851,23 +854,23 @@ int storeSwapInHandle(fd_notused, buf, len, flag, e, offset_notused) StoreEntry *e; int offset_notused; { - debug(0, 2, "storeSwapInHandle: \n", e->url); + debug(20, 2, "storeSwapInHandle: \n", e->url); if ((flag < 0) && (flag != DISK_EOF)) { - debug(0, 0, "storeSwapInHandle: SwapIn failure (err code = %d).\n", flag); + debug(20, 0, "storeSwapInHandle: SwapIn failure (err code = %d).\n", flag); put_free_8k_page(e->mem_obj->e_swap_buf); storeSetMemStatus(e, NOT_IN_MEMORY); file_close(e->mem_obj->swap_fd); swapInError(-1, e); /* Invokes storeAbort() and completes the I/O */ return -1; } - debug(0, 5, "storeSwapInHandle: e->swap_offset = %d\n", + debug(20, 5, "storeSwapInHandle: e->swap_offset = %d\n", e->mem_obj->swap_offset); - debug(0, 5, "storeSwapInHandle: len = %d\n", + debug(20, 5, "storeSwapInHandle: len = %d\n", len); - debug(0, 5, "storeSwapInHandle: e->e_current_len = %d\n", + debug(20, 5, "storeSwapInHandle: e->e_current_len = %d\n", e->mem_obj->e_current_len); - debug(0, 5, "storeSwapInHandle: e->object_len = %d\n", + debug(20, 5, "storeSwapInHandle: e->object_len = %d\n", e->object_len); /* always call these, even if len == 0 */ @@ -887,14 +890,14 @@ int storeSwapInHandle(fd_notused, buf, len, flag, e, offset_notused) storeSetMemStatus(e, IN_MEMORY); put_free_8k_page(e->mem_obj->e_swap_buf); file_close(e->mem_obj->swap_fd); - debug(0, 5, "storeSwapInHandle: SwapIn complete: from %s.\n", + debug(20, 5, "storeSwapInHandle: SwapIn complete: from %s.\n", e->url, storeSwapFullPath(e->swap_file_number, NULL)); if (e->mem_obj->e_current_len != e->object_len) { - debug(0, 0, "storeSwapInHandle: WARNING! Object size mismatch.\n"); - debug(0, 0, " --> \n", e->url); - debug(0, 0, " --> Expecting %d bytes from file: %s\n", e->object_len, + debug(20, 0, "storeSwapInHandle: WARNING! Object size mismatch.\n"); + debug(20, 0, " --> \n", e->url); + debug(20, 0, " --> Expecting %d bytes from file: %s\n", e->object_len, storeSwapFullPath(e->swap_file_number, NULL)); - debug(0, 0, " --> Only read %d bytes\n", + debug(20, 0, " --> Only read %d bytes\n", e->mem_obj->e_current_len); } if (e->flag & RELEASE_REQUEST) @@ -911,7 +914,7 @@ int storeSwapInStart(e) /* sanity check! */ if ((e->swap_status != SWAP_OK) || (e->swap_file_number < 0)) { - debug(0, 0, "storeSwapInStart: ? \n", e->swap_file_number, e->url); + debug(20, 0, "storeSwapInStart: ? \n", e->swap_file_number, e->url); if (has_mem_obj(e)) e->mem_obj->swap_fd = -1; return -1; @@ -922,13 +925,13 @@ int storeSwapInStart(e) e->mem_obj->swap_fd = fd = file_open(storeSwapFullPath(e->swap_file_number, NULL), NULL, O_RDONLY); if (fd < 0) { - debug(0, 0, "storeSwapInStart: Unable to open swapfile: %s for\n\t\n", + debug(20, 0, "storeSwapInStart: Unable to open swapfile: %s for\n\t\n", storeSwapFullPath(e->swap_file_number, NULL), e->url); storeSetMemStatus(e, NOT_IN_MEMORY); /* Invoke a store abort that should free the destroy_store_mem_obj(e); */ return -1; } - debug(0, 5, "storeSwapInStart: initialized swap file '%s' for \n", + debug(20, 5, "storeSwapInStart: initialized swap file '%s' for \n", storeSwapFullPath(e->swap_file_number, NULL), e->url); e->mem_obj->data = memInit(); @@ -958,14 +961,14 @@ void storeSwapOutHandle(fd, flag, e) static char logmsg[6000]; char *page_ptr = NULL; - debug(0, 5, "storeSwapOutHandle: \n", e->url); + debug(20, 5, "storeSwapOutHandle: \n", e->url); e->timestamp = cached_curtime; storeSwapFullPath(e->swap_file_number, filename); page_ptr = e->mem_obj->e_swap_buf; if (flag < 0) { - debug(0, 1, "storeSwapOutHandle: SwapOut failure (err code = %d).\n", + debug(20, 1, "storeSwapOutHandle: SwapOut failure (err code = %d).\n", flag); e->swap_status = NO_SWAP; put_free_8k_page(page_ptr); @@ -986,13 +989,13 @@ void storeSwapOutHandle(fd, flag, e) } return; } - debug(0, 6, "storeSwapOutHandle: e->swap_offset = %d\n", + debug(20, 6, "storeSwapOutHandle: e->swap_offset = %d\n", e->mem_obj->swap_offset); - debug(0, 6, "storeSwapOutHandle: e->e_swap_buf_len = %d\n", + debug(20, 6, "storeSwapOutHandle: e->e_swap_buf_len = %d\n", e->mem_obj->e_swap_buf_len); - debug(0, 6, "storeSwapOutHandle: e->object_len = %d\n", + debug(20, 6, "storeSwapOutHandle: e->object_len = %d\n", e->object_len); - debug(0, 6, "storeSwapOutHandle: store_swap_size = %dk\n", + debug(20, 6, "storeSwapOutHandle: store_swap_size = %dk\n", store_swap_size); e->mem_obj->swap_offset += e->mem_obj->e_swap_buf_len; @@ -1002,10 +1005,10 @@ void storeSwapOutHandle(fd, flag, e) /* swapping complete */ e->swap_status = SWAP_OK; file_close(e->mem_obj->swap_fd); - debug(0, 5, "storeSwapOutHandle: SwapOut complete: to %s.\n", + debug(20, 5, "storeSwapOutHandle: SwapOut complete: to %s.\n", e->url, storeSwapFullPath(e->swap_file_number, NULL)); put_free_8k_page(page_ptr); - sprintf(logmsg, "FILE: %s URL: %s %d %d %d\n", + sprintf(logmsg, "%s %s %d %d %d\n", filename, e->url, (int) e->expires, @@ -1049,19 +1052,19 @@ int storeSwapOutStart(e) fd = file_open(swapfilename, NULL, O_RDWR | O_CREAT | O_TRUNC); if (fd < 0) { - debug(0, 0, "storeSwapOutStart: Unable to open swapfile: %s\n", + debug(20, 0, "storeSwapOutStart: Unable to open swapfile: %s\n", swapfilename); file_map_bit_reset(swapfileno); e->swap_file_number = -1; return -1; } e->mem_obj->swap_fd = fd; - debug(0, 5, "storeSwapOutStart: Begin SwapOut to FD %d FILE %s.\n", + debug(20, 5, "storeSwapOutStart: Begin SwapOut to FD %d FILE %s.\n", e->url, fd, swapfilename); e->swap_file_number = swapfileno; if ((e->mem_obj->e_swap_access = file_write_lock(e->mem_obj->swap_fd)) < 0) { - debug(0, 0, "storeSwapOutStart: Unable to lock swapfile: %s\n", + debug(20, 0, "storeSwapOutStart: Unable to lock swapfile: %s\n", swapfilename); file_map_bit_reset(e->swap_file_number); e->swap_file_number = -1; @@ -1113,9 +1116,12 @@ void storeRebuildFromDisk() int sfileno = 0; off_t size; int fast_mode = 0; + FILE *old_log = NULL; + FILE *new_log = NULL; + char *new_log_name = NULL; for (i = 0; i < ncache_dirs; ++i) - debug(0, 1, "Rebuilding storage from disk image in %s\n", swappath(i)); + debug(20, 1, "Rebuilding storage from disk image in %s\n", swappath(i)); start = cached_curtime = time(NULL); sprintf(line_in, "%s/log-last-clean", swappath(0)); @@ -1126,22 +1132,34 @@ void storeRebuildFromDisk() fast_mode = (sb.st_mtime <= last_clean) ? 1 : 0; } } - if (fast_mode) - debug(0, 1, "Rebuilding in FAST MODE.\n"); + /* Open the existing swap log for reading */ + if ((old_log = fopen(swaplog_file, "r")) == (FILE *) NULL) { + sprintf(tmp_error_buf, "storeRebuildFromDisk: %s: %s", + swaplog_file, xstrerror()); + fatal(tmp_error_buf); + } + /* Open a new log for writing */ + sprintf(line_in, "%s.new", swaplog_file); + new_log_name = xstrdup(line_in); + new_log = fopen(new_log_name, "w"); + if (new_log == (FILE *) NULL) { + sprintf(tmp_error_buf, "storeRebuildFromDisk: %s: %s", + new_log_name, xstrerror()); + fatal(tmp_error_buf); + } - /* go to top of the file */ - (void) lseek(swaplog_fd, 0L, SEEK_SET); + if (fast_mode) + debug(20, 1, "Rebuilding in FAST MODE.\n"); memset(line_in, '\0', 4096); - while (fgets(line_in, 4096, swaplog_stream)) { - + while (fgets(line_in, 4096, old_log)) { if ((linecount++ & 0x7F) == 0) /* update current time */ cached_curtime = time(NULL); if ((linecount & 0xFFF) == 0) - debug(0, 1, " %7d Lines read so far.\n", linecount); + debug(20, 1, " %7d Lines read so far.\n", linecount); - debug(0, 10, "line_in: %s", line_in); + debug(20, 10, "line_in: %s", line_in); if ((line_in[0] == '\0') || (line_in[0] == '\n') || (line_in[0] == '#')) continue; /* skip bad lines */ @@ -1151,7 +1169,7 @@ void storeRebuildFromDisk() scan3 = 0; size = 0; - if (sscanf(line_in, "FILE: %[^ ] URL: %[^ ] %d %d %d", + if (sscanf(line_in, "%s %s %d %d %d", log_swapfile, url, &scan1, &scan2, &scan3) < 4) { #ifdef UNLINK_ON_RELOAD if (log_swapfile[0]) @@ -1177,13 +1195,13 @@ void storeRebuildFromDisk() if (stat(swapfile, &sb) < 0) { if (expires < cached_curtime) { - debug(0, 3, "storeRebuildFromDisk: Expired: \n", url); + debug(20, 3, "storeRebuildFromDisk: Expired: \n", url); #ifdef UNLINK_ON_RELOAD safeunlink(swapfile, 1); #endif expcount++; } else { - debug(0, 3, "storeRebuildFromDisk: Swap file missing: : %s: %s.\n", url, swapfile, xstrerror()); + debug(20, 3, "storeRebuildFromDisk: Swap file missing: : %s: %s.\n", url, swapfile, xstrerror()); #ifdef UNLINK_ON_RELOAD safeunlink(log_swapfile, 1); #endif @@ -1204,17 +1222,17 @@ void storeRebuildFromDisk() continue; } timestamp = sb.st_mtime; - debug(0, 10, "storeRebuildFromDisk: Cached file exists: : %s\n", + debug(20, 10, "storeRebuildFromDisk: Cached file exists: : %s\n", url, swapfile); } if ((e = storeGet(url))) { - debug(0, 6, "storeRebuildFromDisk: Duplicate: \n", url); + debug(20, 6, "storeRebuildFromDisk: Duplicate: \n", url); storeRelease(e); objcount--; dupcount++; } if (expires < cached_curtime) { - debug(0, 3, "storeRebuildFromDisk: Expired: \n", url); + debug(20, 3, "storeRebuildFromDisk: Expired: \n", url); #ifdef UNLINK_ON_RELOAD safeunlink(swapfile, 1); #endif @@ -1225,7 +1243,7 @@ void storeRebuildFromDisk() store_swap_size += (int) ((size + 1023) >> 10); objcount++; - fprintf(swaplog_tmp_stream, "FILE: %s URL: %s %d %d %d\n", + fprintf(new_log, "%s %s %d %d %d\n", swapfile, url, (int) expires, (int) timestamp, (int) size); storeAddDiskRestore(url, sfileno, (int) size, expires, timestamp); CacheInfo->proto_newobject(CacheInfo, @@ -1233,20 +1251,26 @@ void storeRebuildFromDisk() (int) size, TRUE); } - fflush(swaplog_tmp_stream); + fclose(old_log); + fclose(new_log); + if (rename(new_log_name, swaplog_file) < 0) { + sprintf(tmp_error_buf, "storeRebuildFromDisk: rename: %s", + xstrerror()); + fatal(tmp_error_buf); + } + xfree(new_log_name); + stop = cached_curtime = time(NULL); r = stop - start; - /* swapfileno = sfileno; */ - /* PBD: Start swapfileno at zero, so that old swap files are overwritten */ - debug(0, 1, "Finished rebuilding storage from disk image.\n"); - debug(0, 1, " %7d Lines read from previous logfile.\n", linecount); - debug(0, 1, " %7d Objects loaded.\n", objcount); - debug(0, 1, " %7d Objects expired.\n", expcount); - debug(0, 1, " %7d Duplicate URLs purged.\n", dupcount); - debug(0, 1, " %7d Swapfile clashes avoided.\n", clashcount); - debug(0, 1, " Took %d seconds (%6.1lf objects/sec).\n", + debug(20, 1, "Finished rebuilding storage from disk image.\n"); + debug(20, 1, " %7d Lines read from previous logfile.\n", linecount); + debug(20, 1, " %7d Objects loaded.\n", objcount); + debug(20, 1, " %7d Objects expired.\n", expcount); + debug(20, 1, " %7d Duplicate URLs purged.\n", dupcount); + debug(20, 1, " %7d Swapfile clashes avoided.\n", clashcount); + debug(20, 1, " Took %d seconds (%6.1lf objects/sec).\n", r > 0 ? r : 0, (double) objcount / (r > 0 ? r : 1)); - debug(0, 1, " store_swap_size = %dk\n", store_swap_size); + debug(20, 1, " store_swap_size = %dk\n", store_swap_size); /* touch a timestamp file */ sprintf(line_in, "%s/log-last-clean", swappath(0)); @@ -1271,7 +1295,7 @@ int storeGetMemSize() void storeComplete(e) StoreEntry *e; { - debug(0, 5, "storeComplete: \n", e->url); + debug(20, 5, "storeComplete: \n", e->url); e->object_len = e->mem_obj->e_current_len; InvokeHandlers(e); @@ -1305,7 +1329,7 @@ int storeAbort(e, msg) static char mime_hdr[300]; static char abort_msg[2000]; - debug(0, 6, "storeAbort: \n", e->url); + debug(20, 6, "storeAbort: \n", e->url); e->expires = cached_curtime + getNegativeTTL(); e->status = STORE_ABORTED; storeSetMemStatus(e, IN_MEMORY); @@ -1336,7 +1360,7 @@ int storeAbort(e, msg) if ((int) (strlen(msg) + strlen(mime_hdr) + 50) < 2000) { sprintf(abort_msg, "HTTP/1.0 400 Cache Detected Error\r\n%s\r\n\r\n%s", mime_hdr, msg); } else { - debug(0, 0, "storeAbort: WARNING: Must increase msg length!"); + debug(20, 0, "storeAbort: WARNING: Must increase msg length!"); } storeAppend(e, abort_msg, strlen(abort_msg)); e->mem_obj->e_abort_msg = xstrdup(abort_msg); @@ -1419,7 +1443,7 @@ int storeWalkThrough(proc, data) if ((++n & 0xFF) == 0) cached_curtime = time(NULL); if ((n & 0xFFF) == 0) - debug(0, 2, "storeWalkThrough: %7d objects so far.\n", n); + debug(20, 2, "storeWalkThrough: %7d objects so far.\n", n); count += proc(e, data); } return count; @@ -1434,12 +1458,12 @@ int removeOldEntry(e, data) { time_t curtime = *((time_t *) data); - debug(0, 5, "removeOldEntry: Checking: %s\n", e->url); - debug(0, 6, "removeOldEntry: * curtime: %8ld\n", curtime); - debug(0, 6, "removeOldEntry: * e->timestamp: %8ld\n", e->timestamp); - debug(0, 6, "removeOldEntry: * time in cache: %8ld\n", + debug(20, 5, "removeOldEntry: Checking: %s\n", e->url); + debug(20, 6, "removeOldEntry: * curtime: %8ld\n", curtime); + debug(20, 6, "removeOldEntry: * e->timestamp: %8ld\n", e->timestamp); + debug(20, 6, "removeOldEntry: * time in cache: %8ld\n", curtime - e->timestamp); - debug(0, 6, "removeOldEntry: * time-to-live: %8ld\n", + debug(20, 6, "removeOldEntry: * time-to-live: %8ld\n", e->expires - cached_curtime); if ((cached_curtime > e->expires) && (e->status != STORE_PENDING)) { @@ -1454,10 +1478,10 @@ int storePurgeOld() { int n; - debug(0, 3, "storePurgeOld: Begin purging TTL-expired objects\n"); + debug(20, 3, "storePurgeOld: Begin purging TTL-expired objects\n"); n = storeWalkThrough(removeOldEntry, (caddr_t) & cached_curtime); - debug(0, 3, "storePurgeOld: Done purging TTL-expired objects.\n"); - debug(0, 3, "storePurgeOld: %d objects expired\n", n); + debug(20, 3, "storePurgeOld: Done purging TTL-expired objects.\n"); + debug(20, 3, "storePurgeOld: %d objects expired\n", n); return n; } @@ -1492,7 +1516,7 @@ int storeGetMemSpace(size, check_vm_number) if (!check_vm_number && ((store_mem_size + size) < store_mem_high)) return 0; - debug(0, 2, "storeGetMemSpace: Starting...\n"); + debug(20, 2, "storeGetMemSpace: Starting...\n"); LRU_list = create_dynamic_array(meta_data.store_in_mem_objects, MEM_LRUSCAN_BLOCK); pending_entry_list = create_dynamic_array(meta_data.store_in_mem_objects, MEM_LRUSCAN_BLOCK); @@ -1510,7 +1534,7 @@ int storeGetMemSpace(size, check_vm_number) continue; } if (cached_curtime > e->expires) { - debug(0, 2, "storeGetMemSpace: Expired: %s\n", e->url); + debug(20, 2, "storeGetMemSpace: Expired: %s\n", e->url); n_expired++; /* Delayed release */ storeRelease(e); @@ -1527,26 +1551,26 @@ int storeGetMemSpace(size, check_vm_number) } else { n_cantpurge++; mem_cantpurge += e->mem_obj->e_current_len; - debug(0, 5, "storeGetMemSpace: Can't purge %7d bytes: %s\n", + debug(20, 5, "storeGetMemSpace: Can't purge %7d bytes: %s\n", e->mem_obj->e_current_len, e->url); if (e->swap_status != SWAP_OK) - debug(0, 5, "storeGetMemSpace: --> e->swap_status != SWAP_OK\n"); + debug(20, 5, "storeGetMemSpace: --> e->swap_status != SWAP_OK\n"); if (e->lock_count) - debug(0, 5, "storeGetMemSpace: --> e->lock_count %d\n", e->lock_count); + debug(20, 5, "storeGetMemSpace: --> e->lock_count %d\n", e->lock_count); } } - debug(0, 2, "storeGetMemSpace: Current size: %7d bytes\n", store_mem_size); - debug(0, 2, "storeGetMemSpace: High W Mark: %7d bytes\n", store_mem_high); - debug(0, 2, "storeGetMemSpace: Low W Mark: %7d bytes\n", store_mem_low); - debug(0, 2, "storeGetMemSpace: Entry count: %7d items\n", meta_data.store_entries); - debug(0, 2, "storeGetMemSpace: Scanned: %7d items\n", n_scanned); - debug(0, 2, "storeGetMemSpace: In memory: %7d items\n", n_inmem); - debug(0, 2, "storeGetMemSpace: Hot vm count: %7d items\n", meta_data.hot_vm); - debug(0, 2, "storeGetMemSpace: Expired: %7d items\n", n_expired); - debug(0, 2, "storeGetMemSpace: Negative Cached: %7d items\n", n_aborted); - debug(0, 2, "storeGetMemSpace: Can't purge: %7d items\n", n_cantpurge); - debug(0, 2, "storeGetMemSpace: Can't purge size: %7d bytes\n", mem_cantpurge); - debug(0, 2, "storeGetMemSpace: Sorting LRU_list: %7d items\n", LRU_list->index); + debug(20, 2, "storeGetMemSpace: Current size: %7d bytes\n", store_mem_size); + debug(20, 2, "storeGetMemSpace: High W Mark: %7d bytes\n", store_mem_high); + debug(20, 2, "storeGetMemSpace: Low W Mark: %7d bytes\n", store_mem_low); + debug(20, 2, "storeGetMemSpace: Entry count: %7d items\n", meta_data.store_entries); + debug(20, 2, "storeGetMemSpace: Scanned: %7d items\n", n_scanned); + debug(20, 2, "storeGetMemSpace: In memory: %7d items\n", n_inmem); + debug(20, 2, "storeGetMemSpace: Hot vm count: %7d items\n", meta_data.hot_vm); + debug(20, 2, "storeGetMemSpace: Expired: %7d items\n", n_expired); + debug(20, 2, "storeGetMemSpace: Negative Cached: %7d items\n", n_aborted); + debug(20, 2, "storeGetMemSpace: Can't purge: %7d items\n", n_cantpurge); + debug(20, 2, "storeGetMemSpace: Can't purge size: %7d bytes\n", mem_cantpurge); + debug(20, 2, "storeGetMemSpace: Sorting LRU_list: %7d items\n", LRU_list->index); qsort((char *) LRU_list->collection, LRU_list->index, sizeof(e), (int (*)(const void *, const void *)) compareLastRef); /* Kick LRU out until we have enough memory space */ @@ -1579,29 +1603,29 @@ int storeGetMemSpace(size, check_vm_number) destroy_dynamic_array(LRU_list); - debug(0, 2, "storeGetMemSpace: After freeing size: %7d bytes\n", store_mem_size); - debug(0, 2, "storeGetMemSpace: Purged: %7d items\n", n_purged); - debug(0, 2, "storeGetMemSpace: Released: %7d items\n", n_released); + debug(20, 2, "storeGetMemSpace: After freeing size: %7d bytes\n", store_mem_size); + debug(20, 2, "storeGetMemSpace: Purged: %7d items\n", n_purged); + debug(20, 2, "storeGetMemSpace: Released: %7d items\n", n_released); if (check_vm_number) { /* don't check for size */ destroy_dynamic_array(pending_entry_list); - debug(0, 2, "storeGetMemSpace: Done.\n"); + debug(20, 2, "storeGetMemSpace: Done.\n"); return 0; } if ((store_mem_size + size) < store_mem_high) { /* we don't care for hot_vm count here, just the storage size. */ over_highwater = over_max = 0; destroy_dynamic_array(pending_entry_list); - debug(0, 2, "storeGetMemSpace: Done.\n"); + debug(20, 2, "storeGetMemSpace: Done.\n"); return 0; } if ((store_mem_size + size) < getCacheMemMax()) { /* We're over high water mark here, but still under absolute max */ if (!over_highwater) { /* print only once when the condition occur until it clears. */ - debug(0, 1, "storeGetMemSpace: Allocating beyond the high water mark with total size of %d\n", + debug(20, 1, "storeGetMemSpace: Allocating beyond the high water mark with total size of %d\n", store_mem_size + size); over_highwater = 1; } @@ -1611,11 +1635,11 @@ int storeGetMemSpace(size, check_vm_number) /* We're over absolute max */ if (!over_max) { /* print only once when the condition occur until it clears. */ - debug(0, 1, "storeGetMemSpace: Allocating beyond the MAX Store with total size of %d\n", + debug(20, 1, "storeGetMemSpace: Allocating beyond the MAX Store with total size of %d\n", store_mem_size + size); - debug(0, 1, " Start Deleting Behind for every pending objects\n:"); - debug(0, 1, " You should really adjust your cache_mem, high/low water mark,\n"); - debug(0, 1, " max object size to suit your need.\n"); + debug(20, 1, " Start Deleting Behind for every pending objects\n:"); + debug(20, 1, " You should really adjust your cache_mem, high/low water mark,\n"); + debug(20, 1, " max object size to suit your need.\n"); over_max = 1; } /* delete all of them, we desperate for a space. */ @@ -1630,11 +1654,11 @@ int storeGetMemSpace(size, check_vm_number) storeStartDeleteBehind(pending_entry_list->collection[i]); } if (n_deleted_behind) { - debug(0, 1, "storeGetMemSpace: Due to memory flucuation, put %d objects to DELETE_BEHIND MODE.\n", + debug(20, 1, "storeGetMemSpace: Due to memory flucuation, put %d objects to DELETE_BEHIND MODE.\n", n_deleted_behind); } destroy_dynamic_array(pending_entry_list); - debug(0, 2, "storeGetMemSpace: Done.\n"); + debug(20, 2, "storeGetMemSpace: Done.\n"); return 0; } @@ -1642,7 +1666,7 @@ int compareSize(e1, e2) StoreEntry **e1, **e2; { if (!e1 || !e2) { - debug(0, 1, "compareSize: Called with at least one null argument, shouldn't happen.\n"); + debug(20, 1, "compareSize: Called with at least one null argument, shouldn't happen.\n"); return 0; } if ((*e1)->mem_obj->e_current_len > (*e2)->mem_obj->e_current_len) @@ -1714,13 +1738,13 @@ int storeGetSwapSpace(size) if (!fReduceSwap && (store_swap_size + kb_size <= store_swap_high)) { return 0; } - debug(0, 2, "storeGetSwapSpace: Starting...\n"); + debug(20, 2, "storeGetSwapSpace: Starting...\n"); /* Set flag if swap size over high-water-mark */ if (store_swap_size + kb_size > store_swap_high) fReduceSwap = 1; - debug(0, 2, "storeGetSwapSpace: Need %d bytes...\n", size); + debug(20, 2, "storeGetSwapSpace: Need %d bytes...\n", size); LRU_list = create_dynamic_array(LRU_cur_size, LRU_cur_size); /* remove expired objects until recover enough space or no expired objects */ @@ -1743,7 +1767,7 @@ int storeGetSwapSpace(size) (e->lock_count == 0) && /* Be overly cautious */ (e->mem_status != SWAPPING_IN)) { /* Not if it's being faulted into memory */ if (cached_curtime > e->expires) { - debug(0, 2, "storeRemoveExpiredObj: Expired: \n", e->url); + debug(20, 2, "storeRemoveExpiredObj: Expired: \n", e->url); /* just call release. don't have to check for lock status. * storeRelease will take care of that and set a pending flag * if it's still locked. */ @@ -1755,13 +1779,13 @@ int storeGetSwapSpace(size) ++scan_in_objs; } } else { - debug(0, 2, "storeGetSwapSpace: Can't purge %7d bytes: \n", + debug(20, 2, "storeGetSwapSpace: Can't purge %7d bytes: \n", e->object_len, e->url); if (e->lock_count) { - debug(0, 2, "\t\te->lock_count %d\n", e->lock_count); + debug(20, 2, "\t\te->lock_count %d\n", e->lock_count); } if (e->swap_status == SWAPPING_OUT) { - debug(0, 2, "\t\te->swap_status == SWAPPING_OUT\n"); + debug(20, 2, "\t\te->swap_status == SWAPPING_OUT\n"); } locked++; locked_size += e->mem_obj->e_current_len; @@ -1776,7 +1800,7 @@ int storeGetSwapSpace(size) ) { fReduceSwap = 0; destroy_dynamic_array(LRU_list); - debug(0, 2, "storeGetSwapSpace: Finished, %d objects expired.\n", + debug(20, 2, "storeGetSwapSpace: Finished, %d objects expired.\n", expired); return 0; } @@ -1790,16 +1814,16 @@ int storeGetSwapSpace(size) } /* for */ /* end of candidate selection */ - debug(0, 2, "storeGetSwapSpace: Current Size: %7d kbytes\n", store_swap_size); - debug(0, 2, "storeGetSwapSpace: High W Mark: %7d kbytes\n", store_swap_high); - debug(0, 2, "storeGetSwapSpace: Low W Mark: %7d kbytes\n", store_swap_low); - debug(0, 2, "storeGetSwapSpace: Entry count: %7d items\n", meta_data.store_entries); - debug(0, 2, "storeGetSwapSpace: Scanned: %7d items\n", scanned); - debug(0, 2, "storeGetSwapSpace: Expired: %7d items\n", expired); - debug(0, 2, "storeGetSwapSpace: Locked: %7d items\n", locked); - debug(0, 2, "storeGetSwapSpace: Locked Space: %7d bytes\n", locked_size); - debug(0, 2, "storeGetSwapSpace: Scan in array: %7d bytes\n", scan_in_objs); - debug(0, 2, "storeGetSwapSpace: LRU candidate: %7d items\n", LRU_list->index); + debug(20, 2, "storeGetSwapSpace: Current Size: %7d kbytes\n", store_swap_size); + debug(20, 2, "storeGetSwapSpace: High W Mark: %7d kbytes\n", store_swap_high); + debug(20, 2, "storeGetSwapSpace: Low W Mark: %7d kbytes\n", store_swap_low); + debug(20, 2, "storeGetSwapSpace: Entry count: %7d items\n", meta_data.store_entries); + debug(20, 2, "storeGetSwapSpace: Scanned: %7d items\n", scanned); + debug(20, 2, "storeGetSwapSpace: Expired: %7d items\n", expired); + debug(20, 2, "storeGetSwapSpace: Locked: %7d items\n", locked); + debug(20, 2, "storeGetSwapSpace: Locked Space: %7d bytes\n", locked_size); + debug(20, 2, "storeGetSwapSpace: Scan in array: %7d bytes\n", scan_in_objs); + debug(20, 2, "storeGetSwapSpace: LRU candidate: %7d items\n", LRU_list->index); /* Although all expired objects removed, still didn't recover enough */ /* space. Kick LRU out until we have enough swap space */ @@ -1812,34 +1836,34 @@ int storeGetSwapSpace(size) if (storeRelease(LRU) == 0) { removed++; } else { - debug(0, 2, "storeGetSwapSpace: Help! Can't remove objects. <%s>\n", + debug(20, 2, "storeGetSwapSpace: Help! Can't remove objects. <%s>\n", LRU->url); } } } - debug(0, 2, "storeGetSwapSpace: After Freeing Size: %7d kbytes\n", store_swap_size); + debug(20, 2, "storeGetSwapSpace: After Freeing Size: %7d kbytes\n", store_swap_size); /* free the list */ destroy_dynamic_array(LRU_list); if ((store_swap_size + kb_size > store_swap_high)) { if (++swap_help > SWAP_MAX_HELP) { - debug(0, 0, "storeGetSwapSpace: Nothing to free with %d Kbytes in use.\n", + debug(20, 0, "storeGetSwapSpace: Nothing to free with %d Kbytes in use.\n", store_swap_size); - debug(0, 0, "--> Asking for %d bytes\n", size); - debug(0, 0, "WARNING! Repeated failures to allocate swap space!\n"); - debug(0, 0, "WARNING! Please check your disk space.\n"); + debug(20, 0, "--> Asking for %d bytes\n", size); + debug(20, 0, "WARNING! Repeated failures to allocate swap space!\n"); + debug(20, 0, "WARNING! Please check your disk space.\n"); swap_help = 0; } else { - debug(0, 2, "storeGetSwapSpace: Nothing to free with %d Kbytes in use.\n", + debug(20, 2, "storeGetSwapSpace: Nothing to free with %d Kbytes in use.\n", store_swap_size); - debug(0, 2, "--> Asking for %d bytes\n", size); + debug(20, 2, "--> Asking for %d bytes\n", size); } } else { swap_help = 0; } - debug(0, 2, "storeGetSwapSpace: Finished, %d objects removed.\n", removed); + debug(20, 2, "storeGetSwapSpace: Finished, %d objects removed.\n", removed); return 0; } @@ -1859,28 +1883,28 @@ int storeRelease(e) BIT_SET(e->flag, RELEASE_REQUEST); return -1; } - debug(0, 5, "storeRelease: Releasing: %s\n", e->url); + debug(20, 5, "storeRelease: Releasing: %s\n", e->url); if (table == (HashID) 0) return -1; if (e->key == NULL) { - debug(0, 0, "storeRelease: NULL key for %s\n", e->url); - debug(0, 0, "Dump of Entry 'e':\n %s\n", storeToString(e)); + debug(20, 0, "storeRelease: NULL key for %s\n", e->url); + debug(20, 0, "Dump of Entry 'e':\n %s\n", storeToString(e)); fatal_dump(NULL); } if ((hptr = hash_lookup(table, e->key)) == NULL) { - debug(0, 0, "storeRelease: Not Found: %s\n", e->url); - debug(0, 0, "Dump of Entry 'e':\n %s\n", storeToString(e)); + debug(20, 0, "storeRelease: Not Found: %s\n", e->url); + debug(20, 0, "Dump of Entry 'e':\n %s\n", storeToString(e)); fatal_dump(NULL); } result = (StoreEntry *) hptr; if (result != e) { - debug(0, 0, "storeRelease: Duplicated entry? \n", + debug(20, 0, "storeRelease: Duplicated entry? \n", result->url ? result->url : "NULL"); - debug(0, 0, "Dump of Entry 'e':\n%s", storeToString(e)); - debug(0, 0, "Dump of Entry 'result':\n%s", storeToString(result)); + debug(20, 0, "Dump of Entry 'e':\n%s", storeToString(e)); + debug(20, 0, "Dump of Entry 'result':\n%s", storeToString(result)); fatal_dump(NULL); } if (e->type_id == REQUEST_OP_GET) { @@ -1895,7 +1919,7 @@ int storeRelease(e) } } } - debug(0, 3, "storeRelease: Release object key: %s \n", e->key); + debug(20, 3, "storeRelease: Release object key: %s \n", e->key); if (e->swap_status == SWAP_OK && (e->swap_file_number > -1)) { (void) safeunlink(storeSwapFullPath(e->swap_file_number, NULL), 0); @@ -1925,7 +1949,7 @@ void storeChangeKey(e) return; if (e->key == NULL) { - debug(0, 0, "storeChangeKey: NULL key for %s\n", e->url); + debug(25, 0, "storeChangeKey: NULL key for %s\n", e->url); return; } if (table == (HashID) 0) @@ -1934,7 +1958,7 @@ void storeChangeKey(e) if ((table_entry = hash_lookup(table, e->key))) result = (StoreEntry *) table_entry; if (result != e) { - debug(0, 1, "storeChangeKey: Key is not unique for key: %s\n", e->key); + debug(25, 1, "storeChangeKey: Key is not unique for key: %s\n", e->key); return; } storeHashDelete(table_entry); @@ -1951,7 +1975,8 @@ void storeChangeKey(e) void storeUnChangeKey(e) StoreEntry *e; { - StoreEntry *result = NULL; + StoreEntry *E1 = NULL; + StoreEntry *E2 = NULL; static char key[MAX_URL + 32]; hash_link *table_entry = NULL; char *t = NULL; @@ -1960,16 +1985,16 @@ void storeUnChangeKey(e) return; if (e->key == NULL) { - debug(0, 0, "storeUnChangeKey: NULL key for %s\n", e->url); + debug(25, 0, "storeUnChangeKey: NULL key for %s\n", e->url); return; } if (table == (HashID) 0) fatal_dump("storeUnChangeKey: Hash table 'table' is zero!\n"); if ((table_entry = hash_lookup(table, e->key))) - result = (StoreEntry *) table_entry; - if (result != e) { - debug(0, 1, "storeUnChangeKey: Key is not unique for key: %s\n", + E1 = (StoreEntry *) table_entry; + if (E1 != e) { + debug(25, 1, "storeUnChangeKey: Key is not unique for key: %s\n", e->key); return; } @@ -1980,13 +2005,26 @@ void storeUnChangeKey(e) if (t == NULL) fatal_dump("storeUnChangeKey: Can't find a second slash.\n"); strcpy(key, t + 1); - if (!(result->flag & KEY_URL)) - safe_free(result->key); - result->key = xstrdup(key); + if ((table_entry = hash_lookup(table, key))) { + debug(25, 0, "storeUnChangeKey: '%s' already exists! Releasing/Moving.\n", + key); + E2 = (StoreEntry *) table_entry; + /* get rid of the old entry */ + if (storeEntryLocked(E2)) { + /* change original hash key to get out of the new object's way */ + storeChangeKey(E2); + BIT_SET(E2->flag, RELEASE_REQUEST); + } else { + storeRelease(E2); + } + } + if (!(E1->flag & KEY_URL)) + safe_free(E1->key); + E1->key = xstrdup(key); storeHashInsert(e); - BIT_RESET(result->flag, KEY_CHANGE); - BIT_SET(result->flag, KEY_URL); - debug(0, 0, "storeUnChangeKey: Changed back to '%s'\n", key); + BIT_RESET(E1->flag, KEY_CHANGE); + BIT_SET(E1->flag, KEY_URL); + debug(25, 0, "storeUnChangeKey: Changed back to '%s'\n", key); } /* return if the current key is the original one. */ @@ -2003,8 +2041,8 @@ int storeEntryLocked(e) StoreEntry *e; { if (!e) { - debug(0, 0, "This entry should be valid.\n"); - debug(0, 0, "%s", storeToString(e)); + debug(20, 0, "This entry should be valid.\n"); + debug(20, 0, "%s", storeToString(e)); fatal_dump(NULL); } return ((e->lock_count) || @@ -2028,16 +2066,16 @@ int storeCopy(e, stateoffset, maxSize, buf, size) if (stateoffset < e->mem_obj->e_lowest_offset) { /* this should not happen. Logic race !!! */ - debug(0, 1, "storeCopy: Client Request a chunk of data in area lower than the lowest_offset\n"); - debug(0, 1, " Current Lowest offset : %d\n", e->mem_obj->e_lowest_offset); - debug(0, 1, " Requested offset : %d\n", stateoffset); + debug(20, 1, "storeCopy: Client Request a chunk of data in area lower than the lowest_offset\n"); + debug(20, 1, " Current Lowest offset : %d\n", e->mem_obj->e_lowest_offset); + debug(20, 1, " Requested offset : %d\n", stateoffset); /* can't really do anything here. Client may hang until lifetime runout. */ return 0; } *size = (available_to_write >= maxSize) ? maxSize : available_to_write; - debug(0, 6, "storeCopy: avail_to_write=%d, store_offset=%d\n", + debug(20, 6, "storeCopy: avail_to_write=%d, store_offset=%d\n", *size, stateoffset); if (*size > 0) @@ -2130,17 +2168,17 @@ int storeClientCopy(e, stateoffset, maxSize, buf, size, fd) if (stateoffset < e->mem_obj->e_lowest_offset) { /* this should not happen. Logic race !!! */ - debug(0, 1, "storeClientCopy: Client Request a chunk of data in area lower than the lowest_offset\n"); - debug(0, 1, " fd : %d\n", fd); - debug(0, 1, " Current Lowest offset : %d\n", e->mem_obj->e_lowest_offset); - debug(0, 1, " Requested offset : %d\n", stateoffset); + debug(20, 1, "storeClientCopy: Client Request a chunk of data in area lower than the lowest_offset\n"); + debug(20, 1, " fd : %d\n", fd); + debug(20, 1, " Current Lowest offset : %d\n", e->mem_obj->e_lowest_offset); + debug(20, 1, " Requested offset : %d\n", stateoffset); /* can't really do anything here. Client may hang until lifetime runout. */ return 0; } *size = (available_to_write >= maxSize) ? maxSize : available_to_write; - debug(0, 6, "storeCopy: avail_to_write=%d, store_offset=%d\n", + debug(20, 6, "storeCopy: avail_to_write=%d, store_offset=%d\n", *size, stateoffset); /* update the lowest requested offset */ @@ -2218,122 +2256,105 @@ int storeEntryValidToSend(e) return 0; } -int storeInit() +static int storeVerifySwapDirs(clean) + int clean; { - static char tmpbuf[FATAL_BUF_SIZE]; - static char swaplog_file[MAX_FILE_NAME_LEN]; - static char swaplog_tmp_file[MAX_FILE_NAME_LEN]; - int directory_created = 0; - struct stat sb; int inx; char *path = NULL; - - (void) file_map_create(MAX_SWAP_FILE); + struct stat sb; + int directory_created = 0; + char *cmdbuf = NULL; for (inx = 0; inx < ncache_dirs; ++inx) { path = swappath(inx); - debug(0, 10, "storeInit: Creating swap space in %s\n", path); + debug(20, 10, "storeInit: Creating swap space in %s\n", path); if (stat(path, &sb) < 0) { /* we need to create a directory for swap file here. */ if (mkdir(path, 0777) < 0) { - sprintf(tmpbuf, - "Failed to create swap directory %s: %s\n", - path, xstrerror()); - if (errno != EEXIST) - fatal(tmpbuf); + if (errno != EEXIST) { + sprintf(tmp_error_buf, "Failed to create swap directory %s: %s", + path, + xstrerror()); + fatal(tmp_error_buf); + } } if (stat(path, &sb) < 0) { - sprintf(tmpbuf, - "Failed to verify swap directory %s: %s\n", + sprintf(tmp_error_buf, + "Failed to verify swap directory %s: %s", path, xstrerror()); - fatal(tmpbuf); + fatal(tmp_error_buf); } - debug(0, 1, "storeInit: Created swap directory %s\n", path); + debug(20, 1, "storeInit: Created swap directory %s\n", path); directory_created = 1; } - if (zap_disk_store) { - debug(0, 1, "storeInit: Zapping all objects on disk storage.\n"); - /* This could be dangerous, second copy of cache can destroy the existing - * swap files of the previous cache. We may use rc file do it. */ - tmpbuf[0] = '\0'; - sprintf(tmpbuf, "cd %s; rm -rf log [0-9][0-9]", path); - debug(0, 1, "storeInit: Running '%s'\n", tmpbuf); - system(tmpbuf); /* XXX should avoid system(3) */ + if (clean) { + debug(20, 1, "storeInit: Zapping all objects on disk storage.\n"); + /* This could be dangerous, second copy of cache can destroy + * the existing swap files of the previous cache. We may + * use rc file do it. */ + cmdbuf = xcalloc(1, BUFSIZ); + sprintf(cmdbuf, "cd %s; /bin/rm -rf log [0-9][0-9]", path); + debug(20, 1, "storeInit: Running '%s'\n", cmdbuf); + system(cmdbuf); /* XXX should avoid system(3) */ + xfree(cmdbuf); } } - sprintf(swaplog_file, "%s/log", swappath(0)); + return directory_created; +} - swaplog_fd = file_open(swaplog_file, NULL, O_RDWR | O_CREAT | O_APPEND); - if (swaplog_fd < 0) { - sprintf(tmpbuf, "Cannot open swap logfile: %s\n", swaplog_file); - fatal(tmpbuf); - } - swaplog_stream = fdopen(swaplog_fd, "w"); - if (!swaplog_stream) { - debug(0, 1, "storeInit: fdopen(%d, \"w\"): %s\n", swaplog_fd, xstrerror()); - sprintf(tmpbuf, "Cannot open a stream for swap logfile: %s\n", swaplog_file); - fatal(tmpbuf); +static void storeCreateSwapSubDirs() +{ + int i, j; + static char name[1024]; + for (j = 0; j < ncache_dirs; j++) { + for (i = 0; i < SWAP_DIRECTORIES; i++) { + sprintf(name, "%s/%02d", swappath(j), i); + if (mkdir(name, 0755) < 0) { + if (errno != EEXIST) { + sprintf(tmp_error_buf, + "Failed to make swap directory %s: %s", + name, xstrerror()); + fatal(tmp_error_buf); + } + } + } } - swaplog_lock = file_write_lock(swaplog_fd); +} - sprintf(swaplog_tmp_file, "%s/log_tmp", swappath(0)); +int storeInit() +{ + int dir_created; + + file_map_create(MAX_SWAP_FILE); + dir_created = storeVerifySwapDirs(zap_disk_store); + + sprintf(swaplog_file, "%s/log", swappath(0)); - swaplog_tmp_fd = file_open(swaplog_tmp_file, NULL, O_RDWR | O_TRUNC | O_CREAT | O_APPEND); - if (swaplog_tmp_fd < 0) { - sprintf(tmpbuf, "Cannot open swap tmp logfile: %s\n", swaplog_tmp_file); - fatal(tmpbuf); - } - swaplog_tmp_stream = fdopen(swaplog_tmp_fd, "w"); - if (!swaplog_tmp_stream) { - sprintf(tmpbuf, "Cannot open a stream for swap tmp logfile: %s\n", swaplog_tmp_file); - fatal(tmpbuf); - } if (!zap_disk_store) { ok_write_clean_log = 0; storeRebuildFromDisk(); - - /* rename tmp_log to log */ - file_write_unlock(swaplog_fd, swaplog_lock); - file_close(swaplog_fd); - safeunlink(swaplog_file, 0); - link(swaplog_tmp_file, swaplog_file); - - swaplog_fd = file_open(swaplog_file, NULL, O_RDWR | O_CREAT | O_APPEND); - if (swaplog_fd < 0) { - sprintf(tmpbuf, "Cannot reopen swap logfile: %s\n", swaplog_file); - fatal(tmpbuf); - } - swaplog_stream = fdopen(swaplog_fd, "w"); - if (!swaplog_stream) { - sprintf(tmpbuf, "Cannot reopen a stream for swap logfile: %s\n", swaplog_file); - fatal(tmpbuf); - } - swaplog_lock = file_write_lock(swaplog_fd); ok_write_clean_log = 1; } - /* close tmp_log file here. Possibly remove if it is not linked to - * the real one. */ - file_close(swaplog_tmp_fd); - safeunlink(swaplog_tmp_file, 0); - - /* Create Small directories in swap */ - if (directory_created || zap_disk_store) { - int i, j; - char name[1024]; - for (j = 0; j < ncache_dirs; j++) { - for (i = 0; i < SWAP_DIRECTORIES; i++) { - sprintf(name, "%s/%02d", swappath(j), i); - if (mkdir(name, 0755) < 0) { - if (errno != EEXIST) { - sprintf(tmpbuf, - "Failed to make swap directory %s: %s\n", - name, xstrerror()); - fatal(tmpbuf); - } - } - } - } + swaplog_fd = file_open(swaplog_file, NULL, O_WRONLY | O_CREAT | O_APPEND); + if (swaplog_fd < 0) { + sprintf(tmp_error_buf, "Cannot open swap logfile: %s", swaplog_file); + fatal(tmp_error_buf); + } + swaplog_stream = fdopen(swaplog_fd, "w"); + if (!swaplog_stream) { + debug(20, 1, "storeInit: fdopen(%d, \"w\"): %s\n", + swaplog_fd, + xstrerror()); + sprintf(tmp_error_buf, + "Cannot open a stream for swap logfile: %s\n", + swaplog_file); + fatal(tmp_error_buf); } + swaplog_lock = file_write_lock(swaplog_fd); + + if (dir_created || zap_disk_store) + storeCreateSwapSubDirs(); + store_mem_high = (long) (getCacheMemMax() / 100) * getCacheMemHighWaterMark(); store_mem_low = (long) (getCacheMemMax() / 100) * @@ -2363,7 +2384,6 @@ int storeInit() void storeSanityCheck() { static char name[4096]; - static char tmpbuf[4096]; int i; if (ncache_dirs < 1) @@ -2379,12 +2399,12 @@ void storeSanityCheck() * errno indicates that the directory doesn't exist */ if (errno != ENOENT) continue; - sprintf(tmpbuf, "WARNING: Cannot write to %s for storage swap area.\nForcing a *full restart* (e.g., cached -z)...", name); + sprintf(tmp_error_buf, "WARNING: Cannot write to %s for storage swap area.\nForcing a *full restart* (e.g., cached -z)...", name); #if HAVE_SYSLOG if (syslog_enable) - syslog(LOG_ALERT, tmpbuf); + syslog(LOG_ALERT, tmp_error_buf); #endif - fprintf(stderr, "cached: %s\n", tmpbuf); + fprintf(stderr, "cached: %s\n", tmp_error_buf); zap_disk_store = 1; return; } @@ -2410,7 +2430,7 @@ int parse_file_number(s) return (atoi(&s[len + 1])); } } - debug(0, 1, "parse_file_number: Could not determine the swap file number from %s.\n", s); + debug(20, 1, "parse_file_number: Could not determine the swap file number from %s.\n", s); return (0); } @@ -2447,7 +2467,7 @@ int storeMaintainSwapSpace() e = (StoreEntry *) link_ptr; if ((cached_curtime > e->expires) && (e->swap_status == SWAP_OK)) { - debug(0, 2, "storeMaintainSwapSpace: Expired: \n", + debug(20, 2, "storeMaintainSwapSpace: Expired: \n", e->expires - cached_curtime, e->url); /* just call release. don't have to check for lock status. * storeRelease will take care of that and set a pending flag @@ -2472,27 +2492,24 @@ int storeWriteCleanLog() StoreEntry *e = NULL; static char swapfilename[MAX_FILE_NAME_LEN]; static char clean_log[MAX_FILE_NAME_LEN]; - static char swaplog_file[MAX_FILE_NAME_LEN]; - static char tmpbuf[FATAL_BUF_SIZE]; FILE *fp = NULL; int n = 0; time_t start, stop, r; if (!ok_write_clean_log) { - debug(0, 1, "storeWriteCleanLog: Not currently OK to rewrite swap log.\n"); - debug(0, 1, "storeWriteCleanLog: Operation aborted.\n"); + debug(20, 1, "storeWriteCleanLog: Not currently OK to rewrite swap log.\n"); + debug(20, 1, "storeWriteCleanLog: Operation aborted.\n"); return 0; } - debug(0, 1, "storeWriteCleanLog: Starting...\n"); + debug(20, 1, "storeWriteCleanLog: Starting...\n"); start = cached_curtime = time(NULL); sprintf(clean_log, "%s/log_clean", swappath(0)); - sprintf(swaplog_file, "%s/log", swappath(0)); if ((fp = fopen(clean_log, "a+")) == NULL) { - debug(0, 0, "storeWriteCleanLog: %s: %s", clean_log, xstrerror()); + debug(20, 0, "storeWriteCleanLog: %s: %s", clean_log, xstrerror()); return 0; } for (e = storeGetFirst(); e; e = storeGetNext()) { - debug(0, 5, "storeWriteCleanLog: \n", e->url); + debug(20, 5, "storeWriteCleanLog: \n", e->url); if (e->swap_file_number < 0) continue; if (e->swap_status != SWAP_OK) @@ -2500,49 +2517,49 @@ int storeWriteCleanLog() if (e->object_len <= 0) continue; storeSwapFullPath(e->swap_file_number, swapfilename); - fprintf(fp, "FILE: %s URL: %s %d %d %d\n", + fprintf(fp, "%s %s %d %d %d\n", swapfilename, e->url, (int) e->expires, (int) e->timestamp, e->object_len); if ((++n & 0xFFF) == 0) { cached_curtime = time(NULL); - debug(0, 1, " %7d lines written so far.\n", n); + debug(20, 1, " %7d lines written so far.\n", n); } } fclose(fp); if (file_write_unlock(swaplog_fd, swaplog_lock) != DISK_OK) { - debug(0, 0, "storeWriteCleanLog: Failed to unlock swaplog!\n"); - debug(0, 0, "storeWriteCleanLog: Current swap logfile not replaced.\n"); + debug(20, 0, "storeWriteCleanLog: Failed to unlock swaplog!\n"); + debug(20, 0, "storeWriteCleanLog: Current swap logfile not replaced.\n"); return 0; } if (rename(clean_log, swaplog_file) < 0) { - debug(0, 0, "storeWriteCleanLog: rename failed: %s\n", + debug(20, 0, "storeWriteCleanLog: rename failed: %s\n", xstrerror()); return 0; } file_close(swaplog_fd); swaplog_fd = file_open(swaplog_file, NULL, O_RDWR | O_CREAT | O_APPEND); if (swaplog_fd < 0) { - sprintf(tmpbuf, "Cannot open swap logfile: %s\n", swaplog_file); - fatal(tmpbuf); + sprintf(tmp_error_buf, "Cannot open swap logfile: %s", swaplog_file); + fatal(tmp_error_buf); } swaplog_stream = fdopen(swaplog_fd, "w"); if (!swaplog_stream) { - sprintf(tmpbuf, "Cannot open a stream for swap logfile: %s\n", + sprintf(tmp_error_buf, "Cannot open a stream for swap logfile: %s", swaplog_file); - fatal(tmpbuf); + fatal(tmp_error_buf); } swaplog_lock = file_write_lock(swaplog_fd); stop = cached_curtime = time(NULL); r = stop - start; - debug(0, 1, " Finished. Wrote %d lines.\n", n); - debug(0, 1, " Took %d seconds (%6.1lf lines/sec).\n", + debug(20, 1, " Finished. Wrote %d lines.\n", n); + debug(20, 1, " Took %d seconds (%6.1lf lines/sec).\n", r > 0 ? r : 0, (double) n / (r > 0 ? r : 1)); /* touch a timestamp file */ - sprintf(swaplog_file, "%s/log-last-clean", swappath(0)); - file_close(file_open(swaplog_file, NULL, O_WRONLY | O_CREAT | O_TRUNC)); + sprintf(clean_log, "%s/log-last-clean", swappath(0)); + file_close(file_open(clean_log, NULL, O_WRONLY | O_CREAT | O_TRUNC)); return n; }