diff --git a/src/bloom-filter.c b/src/bloom-filter.c index 04082c7e..6d3b9377 100644 --- a/src/bloom-filter.c +++ b/src/bloom-filter.c @@ -193,11 +193,13 @@ static values_t byte_bit_location(unsigned long startvalue, int bits_in_chunk) { int bloomfilter_add(bloomfilter_options_t *options, const void *key, size_t klen) { values_t values; - log_print(LOG_DEBUG, SECTION_BLOOM_DEFAULT, "bloomfilter_add: enter \'%s\' :: salt %ul", key, options->salt); + log_print(LOG_DEBUG, SECTION_BLOOM_DEFAULT, "bloomfilter_add: enter \'%s\' :: salt %lu", key, options->salt); values.hashvalue = options->hashfcn(options->salt, key, klen); for (unsigned int idx = 0; idx < options->num_chunks; idx++) { values = byte_bit_location(values.hashvalue, options->bits_in_chunk); - log_print(LOG_DEBUG, SECTION_BLOOM_DEFAULT, "bloomfilter_add: iter %d :: key: \'%s\' :: salt: %ul :: byte %d :: bit %d", idx, key, values.hashvalue, values.bytevalue, values.bitvalue); + log_print(LOG_DEBUG, SECTION_BLOOM_DEFAULT, + "bloomfilter_add: iter %d :: key: \'%s\' :: salt: %lu :: byte %d :: bit %d", + idx, key, values.hashvalue, values.bytevalue, values.bitvalue); options->bitfield[values.bytevalue] |= values.bitvalue; } return 0; @@ -207,11 +209,13 @@ int bloomfilter_add(bloomfilter_options_t *options, const void *key, size_t klen bool bloomfilter_exists(bloomfilter_options_t * options, const void *key, size_t klen) { values_t values; - log_print(LOG_DEBUG, SECTION_BLOOM_DEFAULT, "bloomfilter_exists: enter \'%s\' :: salt %ul", key, options->salt); + log_print(LOG_DEBUG, SECTION_BLOOM_DEFAULT, "bloomfilter_exists: enter \'%s\' :: salt %lu", key, options->salt); values.hashvalue = options->hashfcn(options->salt, key, klen); for (unsigned int idx = 0; idx < options->num_chunks; idx++) { values = byte_bit_location(values.hashvalue, options->bits_in_chunk); - log_print(LOG_DEBUG, SECTION_BLOOM_DEFAULT, "bloomfilter_exists: iter %d :: key: \'%s\' :: salt: %ul :: byte %d :: bit %d", idx, key, values.hashvalue, values.bytevalue, values.bitvalue); + log_print(LOG_DEBUG, SECTION_BLOOM_DEFAULT, + "bloomfilter_exists: iter %d :: key: \'%s\' :: salt: %lu :: byte %d :: bit %d", + idx, key, values.hashvalue, values.bytevalue, values.bitvalue); if ((options->bitfield[values.bytevalue] & values.bitvalue) == 0) return false; } return true; diff --git a/src/fusedav.c b/src/fusedav.c index 6a03e436..f168f1d1 100644 --- a/src/fusedav.c +++ b/src/fusedav.c @@ -182,82 +182,131 @@ static void getdir_propfind_callback(__unused void *userdata, const char *path, static const char *funcname = "getdir_propfind_callback"; struct fusedav_config *config = fuse_get_context()->private_data; + struct stat_cache_value *existing = NULL; struct stat_cache_value value; GError *subgerr1 = NULL ; - GError *subgerr2 = NULL ; - // Zero-out structure; some fields we don't populate but want to be 0, e.g. st_atim.tv_nsec + log_print(LOG_INFO, SECTION_FUSEDAV_PROP, "%s: %s (%lu)", funcname, path, status_code); + memset(&value, 0, sizeof(struct stat_cache_value)); value.st = st; + // Indicate that this update is the result of a propfind + stat_cache_from_propfind(&value, true); + + // 1. See if we have an item in the local cache + // It might be a positive (existing) entry, or a negative (non-existent) one + existing = stat_cache_value_get(config->cache, path, true, &subgerr1); + if (subgerr1) { + g_propagate_prefixed_error(gerr, subgerr1, "%s: ", funcname); + return; + } - log_print(LOG_INFO, SECTION_FUSEDAV_PROP, "%s: %s (%lu)", - funcname, path, status_code); + /* Notes on dual-binding race conditions and odd 404s + * Binding A does a propfind. + * Binding B does a propfind on a path with multiple directories. + * Say, /abcdir. Binding B starts the propfind at /, and abcdir + * still exists. Then Binding A deletes the directory abcdir. + * Then Binding B's propfind moves to abcdir where it does the + * next stage in its propfind. But abcdir no longer exists. + * The fileserver returns 404, which gets processed in + * props.c:simple_propfind() and turned into a 410 (why? see below), + * and this function gets called, with ctime set to 0. In this case, + * we need to delete the directory entry. + * + * Note that this is completely different from the normal case: + * Binding A removes the directory /abcdir. + * When that is done, Binding B does a propfind. When the propfind + * processes /, the fileserver will note that the directory /abcdir + * has been deleted, and Binding B will call this function via a + * different path in props.c, with an existing st.st_ctime, processed + * in one of the else clauses below. + * + * (When the fileserver detects that a file or directory has + * been deleted outside of a race condition like this, it uses code + * 410 to indicate this. If the fileserver goes to do a propfind + * on a directory which no longer exists as in this race condition, + * it returns a 404. For consistency's sake, simple_propfind() turns + * that 404 into a 410 to be detected here.) + */ - if (status_code == 410) { - struct stat_cache_value *existing; + // 2. If ctime is 0, fileserver has just deleted this item, so no need + // to query again, just delete it - log_print(LOG_INFO, SECTION_FUSEDAV_PROP, "%s: DELETE %s (%lu)", - funcname, path, status_code); - existing = stat_cache_value_get(config->cache, path, true, &subgerr1); - if (subgerr1) { - g_propagate_prefixed_error(gerr, subgerr1, "%s: ", funcname); - return; + // If it exists locally already as a negative item, it will get + // reinserted as a negative item + if (st.st_ctime == 0) { + if (status_code != 410) { + // I don't see how we can get ctime == 0 and status code other than 410 + log_print(LOG_ERR, SECTION_FUSEDAV_PROP, + "%s: unexpected status code on propfind with st_ctime == 0: %lu on %s", + funcname, status_code, path); + g_set_error(gerr, fusedav_quark(), EINVAL, + "%s: Unexpected ctime as 0 but status_code not 410 (%lu)", funcname, status_code); } - - /* Binding A does a propfind. - * Binding B does a propfind on a path with multiple directories. - * Say, /abcdir. Binding B starts the propfind at /, and abcdir - * still exists. Then Binding A deletes the directory abcdir. - * Then Binding B's propfind moves to abcdir where it does the - * next stage in its propfind. But abcdir no longer exists. - * The fileserver returns 404, which gets processed in - * props.c:simple_propfind() and turned into a 410 (why? see below), - * and this function gets called, with ctime set to 0. In this case, - * we need to delete the directory entry. - * - * Note that this is completely different from the normal case: - * Binding A removes the directory /abcdir. - * When that is done, Binding B does a propfind. When the propfind - * processes /, the fileserver will note that the directory /abcdir - * has been deleted, and Binding B will call this function via a - * different path in props.c, with an existing st.st_ctime, processed - * in one of the else clauses below. - * - * (When the fileserver detects that a file or directory has - * been deleted outside of a race condition like this, it uses code - * 410 to indicate this. If the fileserver goes to do a propfind - * on a directory which no longer exists as in this race condition, - * it returns a 404. For consistency's sake, simple_propfind() turns - * that 404 into a 410 to be detected here.) - */ - if (st.st_ctime == 0) { - log_print(LOG_NOTICE, SECTION_FUSEDAV_PROP, + else { + log_print(LOG_WARNING, SECTION_FUSEDAV_PROP, "%s: Path removed on different binding while in the middle of this propfind: %s", funcname, path); - // Fall through to delete + // We'll correct this error if we see it, but check to see if it happens often + if (!stat_cache_is_negative_entry(value)) { + log_print(LOG_WARNING, SECTION_FUSEDAV_PROP, + "%s: Expected negative entry (2); got: %s : st_mode=%d", funcname, path, st.st_mode); + } + // Inserting negative entry + stat_cache_negative_set(&value); + stat_cache_value_set(config->cache, path, &value, &subgerr1); + if (subgerr1) { + g_propagate_prefixed_error(gerr, subgerr1, "%s: ", funcname); + } } - /* If existing indicates that the file existed at a later timestamp than this delete, keep it. */ - /* By returning early, here and other places below, we are not updating the updated field on the file, - * which stat_cache_value_set below would do; we leave that value as it was. We are not seeing a - * creation for this file in the propfind, so it would not be correct to update the updated value as if we had. - */ - else if (existing && existing->updated > st.st_ctime) { + } + + // 3. local update is more recent than propfind returns + + /* Indicates that the local item existed at a later timestamp than what the propfind is indicating, + * so keep whatever is currently in the cache. + * This should be correct both for positive and negative entries in the local cache + */ + else if (existing && existing->updated > st.st_ctime) { + if (status_code == 410) { log_print(LOG_NOTICE, SECTION_FUSEDAV_PROP, "%s: Ignoring outdated removal of path: %s (%lu %lu)", funcname, path, existing->updated, st.st_ctime); - free(existing); - return; } - /* If existing indicates that the file existed at the same timestamp as this delete, - * we don't know which to honor. So query the server to see if it exists there and - * use that. - */ - else if (existing && existing->updated == st.st_ctime) { + else { + log_print(LOG_INFO, SECTION_FUSEDAV_PROP, + "%s: Ignoring outdated creation of path: %s (%lu %lu)", + funcname, path, existing->updated, st.st_ctime); + stat_cache_value_set(config->cache, path, &value, &subgerr1); + } + } + + // 4. Confusion! Two things happen at same time. Query fileserver for canonical view + + /* If existing indicates that the local file existed at the same timestamp as this deletion/creation, + * we don't know which to honor. So query the server to see if it exists there and + * use that. + */ + else if (existing && existing->updated == st.st_ctime) { + bool local_negative = stat_cache_is_negative_entry(*existing); + bool remote_negative = (status_code == 410); + if (local_negative == remote_negative) { + // Nothing to do + log_print(LOG_INFO, SECTION_FUSEDAV_PROP, + "%s: Updated equals ctime, but operations match, nothing to do : %s", funcname, path); + // But we still need to call 'set' to update the local_generation + if (!local_negative) { + stat_cache_value_set(config->cache, path, &value, &subgerr1); + } + } + else { CURL *session = NULL; long response_code = 500; // seed it as bad so we can enter the loop CURLcode res = CURLE_OK; - free(existing); + log_print(LOG_NOTICE, SECTION_FUSEDAV_PROP, + "%s: Updated equals ctime, making HEAD request: %s (%lu %lu)", + funcname, path, existing->updated, st.st_ctime); for (int idx = 0; idx < num_filesystem_server_nodes && (res != CURLE_OK || response_code >= 500); idx++) { bool tmp_session = true; @@ -274,7 +323,7 @@ static void getdir_propfind_callback(__unused void *userdata, const char *path, curl_easy_setopt(session, CURLOPT_NOBODY, 1); log_print(LOG_NOTICE, SECTION_FUSEDAV_PROP, - "%s: saw 410; calling HEAD on %s", funcname, path); + "%s: saw %lu; calling HEAD on %s", funcname, status_code, path); timed_curl_easy_perform(session, &res, &response_code, &elapsed_time); bool non_retriable_error = process_status(funcname, session, res, response_code, elapsed_time, idx, path, tmp_session); @@ -290,59 +339,89 @@ static void getdir_propfind_callback(__unused void *userdata, const char *path, set_dynamic_logging(); g_set_error(gerr, fusedav_quark(), ENETDOWN, "%s: curl failed: %s : rc: %ld\n", funcname, curl_easy_strerror(res), response_code); + // Stick with what we got, either a positive or negative entry + free(existing); return; } else { trigger_saint_event(CLUSTER_SUCCESS); } + // fileserver doesn't think the file exists, so delete it locally + // It's possible what we had locally was a negative entry, but + // making a new negative entry is not harmful. if (response_code >= 400 && response_code < 500) { - // fall through to delete log_print(LOG_NOTICE, SECTION_FUSEDAV_PROP, - "%s: saw 410; executed HEAD; file doesn't exist: %s", - funcname, path); + "%s: saw %lu; executed HEAD; file doesn't exist: %s", + funcname, status_code, path); + // Inserting negative entry + if (st.st_mode != 0) { + log_print(LOG_WARNING, SECTION_FUSEDAV_PROP, + "%s: Expected negative entry (4); got: %s : st_mode=%d", funcname, path, st.st_mode); + } + stat_cache_negative_set(&value); + stat_cache_value_set(config->cache, path, &value, &subgerr1); + if (subgerr1) { + g_propagate_prefixed_error(gerr, subgerr1, "%s: ", funcname); + } } + // fileserver thinks file exists. If we got a 410, we could just keep things the way they were. + // But we'd have to check that what was local wasn't a negative entry. + // Seems wise to just create in all cases else { - // REVIEW: if the file exists, do we want to call stat_cache_value_set and update its ->updated value? if (response_code >= 200 && response_code < 300) { - // We're not deleting since it exists; jump out! log_print(LOG_NOTICE, SECTION_FUSEDAV_PROP, - "%s: saw 410; executed HEAD; file exists: %s", - funcname, path); + "%s: saw %lu; executed HEAD; file exists: %s", + funcname, status_code, path); + stat_cache_value_set(config->cache, path, &value, &subgerr1); + if (subgerr1) { + g_propagate_prefixed_error(gerr, subgerr1, "%s: ", funcname); + } } else { - // On error, prefer retaining a file which should be deleted over deleting a file which should be retained + // On error, retain local file g_set_error(gerr, fusedav_quark(), EINVAL, - "%s(%s): saw 410; HEAD returns unexpected response from curl %ld", - funcname, path, response_code); + "%s(%s): saw %lu; HEAD returns unexpected response from curl %ld", + funcname, path, status_code, response_code); } - return; } } - - log_print(LOG_INFO, SECTION_FUSEDAV_PROP, "%s: Removing path: %s", - funcname, path); - stat_cache_delete(config->cache, path, &subgerr1); - filecache_delete(config->cache, path, true, &subgerr2); - // If we need to combine 2 errors, use one of the error messages in the propagated prefix - if (subgerr1 && subgerr2) { - g_propagate_prefixed_error(gerr, subgerr1, "%s: %s :: ", funcname, subgerr2->message); - } - else if (subgerr1) { - g_propagate_prefixed_error(gerr, subgerr1, "%s: ", funcname); - } - else if (subgerr2) { - g_propagate_prefixed_error(gerr, subgerr2, "%s: ", funcname); - } } + // 5. local entry is older than what propfind is showing + + /* if local entry exists but ctime is older than what propfind indicates, use + * what propfind gives us. On 410, delete, even if what exists is already + * a negative entry; otherwise, create, even if what already exists is a + * positive entry. + * + * Since we're unconditionally creating or deleting regardless of what is + * existing, we can use this code whether or not there is an existing item + */ else { - log_print(LOG_INFO, SECTION_FUSEDAV_PROP, "%s: CREATE %s (%lu)", - funcname, path, status_code); - stat_cache_value_set(config->cache, path, &value, &subgerr1); - if (subgerr1) { - g_propagate_prefixed_error(gerr, subgerr1, "%s: ", funcname); - return; + log_print(LOG_DEBUG, SECTION_FUSEDAV_PROP, "%s: status_code: %lu; normal case, deleting or creating: %s", + funcname, status_code, path); + if (status_code == 410) { + // Inserting negative entry + if (st.st_mode != 0) { + log_print(LOG_WARNING, SECTION_FUSEDAV_PROP, + "%s: Expected negative entry (5); got: %s : st_mode=%d", funcname, path, st.st_mode); + } + log_print(LOG_NOTICE, SECTION_FUSEDAV_PROP, "%s: normal case, deleting: %s", + funcname, path); + stat_cache_negative_set(&value); + stat_cache_value_set(config->cache, path, &value, &subgerr1); + if (subgerr1) { + g_propagate_prefixed_error(gerr, subgerr1, "%s: ", funcname); + } + } + else { + stat_cache_value_set(config->cache, path, &value, &subgerr1); + if (subgerr1) { + g_propagate_prefixed_error(gerr, subgerr1, "%s: ", funcname); + } } } + + if (existing) free(existing); } static void getdir_cache_callback(__unused const char *path_prefix, const char *filename, void *user) { @@ -536,8 +615,7 @@ static void getattr_propfind_callback(__unused void *userdata, const char *path, unsigned long status_code, GError **gerr) { struct fusedav_config *config = fuse_get_context()->private_data; struct stat_cache_value value; - GError *subgerr1 = NULL; - GError *subgerr2 = NULL; + GError *subgerr = NULL; // Zero-out structure; some fields we don't populate but want to be 0, e.g. st_atim.tv_nsec memset(&value, 0, sizeof(struct stat_cache_value)); @@ -545,32 +623,26 @@ static void getattr_propfind_callback(__unused void *userdata, const char *path, if (status_code == 410) { log_print(LOG_NOTICE, SECTION_FUSEDAV_PROP, "getattr_propfind_callback: Deleting from stat cache: %s", path); - stat_cache_delete(config->cache, path, &subgerr1); - filecache_delete(config->cache, path, true, &subgerr2); - - // If we need to combine 2 errors, use one of the error messages in the propagated prefix - if (subgerr1 && subgerr2) { - log_print(LOG_NOTICE, SECTION_FUSEDAV_PROP, "getattr_propfind_callback: %s: %s: %s", path, subgerr1->message, subgerr2->message); - g_propagate_prefixed_error(gerr, subgerr1, "getattr_propfind_callback: %s :: ", subgerr2->message); - return; - } - else if (subgerr1) { - log_print(LOG_NOTICE, SECTION_FUSEDAV_PROP, "getattr_propfind_callback: %s: %s", path, subgerr1->message); - g_propagate_prefixed_error(gerr, subgerr1, "getattr_propfind_callback: "); - return; + // Create a negative entry + if (st.st_mode != 0) { + log_print(LOG_WARNING, SECTION_FUSEDAV_PROP, + "getattr_propfind_callback: Expected negative entry; got: %s : st_mode=%d", path, st.st_mode); } - else if (subgerr2) { - log_print(LOG_NOTICE, SECTION_FUSEDAV_PROP, "getattr_propfind_callback: %s: %s", path, subgerr2->message); - g_propagate_prefixed_error(gerr, subgerr2, "getattr_propfind_callback: "); + value.st.st_mode = 0; // Make it so, even if it already is + stat_cache_value_set(config->cache, path, &value, &subgerr); + + if (subgerr) { + log_print(LOG_NOTICE, SECTION_FUSEDAV_PROP, "getattr_propfind_callback: %s: %s", path, subgerr->message); + g_propagate_prefixed_error(gerr, subgerr, "getattr_propfind_callback: "); return; } } else { log_print(LOG_INFO, SECTION_FUSEDAV_PROP, "getattr_propfind_callback: Adding to stat cache: %s", path); - stat_cache_value_set(config->cache, path, &value, &subgerr1); - if (subgerr1) { - log_print(LOG_NOTICE, SECTION_FUSEDAV_PROP, "getattr_propfind_callback: %s: %s", path, subgerr1->message); - g_propagate_prefixed_error(gerr, subgerr1, "getattr_propfind_callback: "); + stat_cache_value_set(config->cache, path, &value, &subgerr); + if (subgerr) { + log_print(LOG_NOTICE, SECTION_FUSEDAV_PROP, "getattr_propfind_callback: %s: %s", path, subgerr->message); + g_propagate_prefixed_error(gerr, subgerr, "getattr_propfind_callback: "); return; } } @@ -612,36 +684,122 @@ static int get_stat_from_cache(const char *path, struct stat *stbuf, enum ignore // else we're not skipping the freshness check and maybe the item is in the cache but just out of date log_print(LOG_DYNAMIC, SECTION_FUSEDAV_STAT, "get_stat_from_cache: Treating key as absent or expired for path %s.", path); return -EKEYEXPIRED; + } + // If st_mode is 0, this is a negative (non-existing) entry + else if (response->st.st_mode == 0) { + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "get_stat_from_cache: negative entry response from stat_cache_value_get for path %s.", path); + return -ENOENT; } log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "get_stat_from_cache: Got response from stat_cache_value_get for path %s.", path); *stbuf = response->st; - print_stat(stbuf, "stat_cache_value_get response"); + print_stat(stbuf, "stat_cache_value_get response", path); free(response); - log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "get_stat_from_cache(%s, stbuf, %d): returns %s", path, skip_freshness_check, stbuf->st_mode ? "0" : "ENOENT"); - if (stbuf->st_mode == 0 || inject_error(fusedav_error_statstmode)) { - g_set_error(gerr, fusedav_quark(), ENOENT, "get_stat_from_cache: stbuf mode is 0: "); - return -1; - } + log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "get_stat_from_cache(%s, stbuf, %d)", path, skip_freshness_check); + return 0; +} +// If its a nonnegative entry and outside the TTL, even if 0, then needs_propfind is true +// If its a negative entry, then the TTL is a fibonacci sequence +static bool requires_propfind(const char *path, time_t time_since, GError **gerr) { + struct fusedav_config *config = fuse_get_context()->private_data; + const char *funcname = "requires_propfind"; + struct stat_cache_value *value = NULL; + bool skip_freshness_check = true; + GError *subgerr = NULL; + + // Get the entry + value = stat_cache_value_get(config->cache, path, skip_freshness_check, &subgerr); + + // Check for error and return + if (subgerr) { + g_propagate_prefixed_error(gerr, subgerr, "%s: ", funcname); + return true; + } + + // If a value was returned from the stat cache ... + if (value != NULL) { + // And the path exists in the cache ... + if (!stat_cache_is_negative_entry(*value)) { + // Requested path exists as non-negative entry. + // If stale, (time_since > STAT_CACHE_NEGATIVE_TTL) return true + // Otherwise, return false + // If TTL is 0, this still works. + // NB Given our current configuration, I don't think we can see + // a non-stale real (nonnegative) value. All non-stale real + // values will have been returned as fresh before this gets called. + bool stale = time_since > STAT_CACHE_NEGATIVE_TTL; + if (stale) { + stats_counter_local("propfind-nonnegative-cache", 1, pfsamplerate); + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "%s: true on non-negative entry %s", funcname, path); + } else { + stats_counter_local("propfind-negative-cache", 1, pfsamplerate); + BUMP(propfind_negative_cache); + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "%s: false on non-negative %s", funcname, path); + } + return stale; + } + // The value was tagged as a negative (non-existent) value ... + else { + time_t current_time = time(NULL); + time_t next_time; + + next_time = stat_cache_next_propfind(*value); + + // Our "time to next propfind" is still in the future, so no propfind ... + if (next_time > current_time) { + stats_counter_local("propfind-negative-cache", 1, pfsamplerate); + BUMP(propfind_negative_cache); + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, + "%s: no propfind needed yet on negative entry %s", funcname, path); + log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, + "%s: no propfind needed yet on negative entry %s; now:next:upd:made--%lu:%lu:%lu", + funcname, path, current_time, next_time, value->updated); + return false; + } else { + // Time for a new propfind + stats_counter_local("propfind-negative-ttl-expired", 1, pfsamplerate); + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, + "%s; new propfind for path: %s, c/nt: %lu: %lu", + funcname, path, current_time, next_time); + + return true; + } + } + } else { + // No value. We haven't previously cached its non-existence, so assume + // this is the first attempt at this item + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "%s; first propfind for path: %s", + funcname, path); + + stats_counter_local("propfind-nonnegative-cache", 1, pfsamplerate); + return true; + } } static void get_stat(const char *path, struct stat *stbuf, GError **gerr) { struct fusedav_config *config = fuse_get_context()->private_data; + const char *funcname = "get_stat"; char *parent_path = NULL; + struct stat_cache_value value; GError *tmpgerr = NULL; + GError *subgerr = NULL; time_t parent_children_update_ts; bool is_base_directory; + bool needs_propfind; int ret = -ENOENT; enum ignore_freshness skip_freshness_check = OFF; time_t time_since; memset(stbuf, 0, sizeof(struct stat)); + memset(&value, 0, sizeof(struct stat_cache_value)); + // Reset from_propfind to false before starting, to clear any previous value + stat_cache_from_propfind(&value, false); - log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "get_stat(%s, stbuf)", path); + log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "%s:(%s, stbuf)", funcname, path); - log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "Checking if path %s matches base directory.", path); + log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "%s: Checking if path %s matches base directory.", funcname, path); is_base_directory = (strcmp(path, "/") == 0); // If it's the root directory and all attributes are specified, construct a response. @@ -650,16 +808,16 @@ static void get_stat(const char *path, struct stat *stbuf, GError **gerr) { // mode = 0 (unspecified), is_dir = true; fd = -1, irrelevant for dir fill_stat_generic(stbuf, 0, true, -1, &tmpgerr); if (tmpgerr) { - g_propagate_prefixed_error(gerr, tmpgerr, "get_stat: "); + g_propagate_prefixed_error(gerr, tmpgerr, "%s: ", funcname); return; } - log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "Used constructed stat data for base directory."); + log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "%s: Used constructed stat data for base directory.", funcname); return; } if (config->grace && use_saint_mode()) { - log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "get_stat: Using saint mode on %s", path); + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "%s: Using saint mode on %s", funcname, path); skip_freshness_check = SAINT_MODE; } @@ -669,7 +827,7 @@ static void get_stat(const char *path, struct stat *stbuf, GError **gerr) { // Propagate the error but let the rest of the logic determine return value // Unless we change the logic in get_stat_from_cache, it will return ENOENT or ENETDOWN if (tmpgerr) { - g_propagate_prefixed_error(gerr, tmpgerr, "get_stat: "); + g_propagate_prefixed_error(gerr, tmpgerr, "%s: ", funcname); return; } else if (ret == 0) { @@ -677,38 +835,37 @@ static void get_stat(const char *path, struct stat *stbuf, GError **gerr) { } // else fall through, this would be for EKEYEXPIRED, indicating statcache miss - log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "STAT-CACHE-MISS"); + log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "%s: STAT-CACHE-MISS", funcname); // If it's the root directory or refresh_dir_for_file_stat is false, // just do a single, zero-depth PROPFIND. if (!config->refresh_dir_for_file_stat || is_base_directory) { - GError *subgerr = NULL; - log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "Performing zero-depth PROPFIND on path: %s", path); + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "%s: Performing zero-depth PROPFIND on path: %s", funcname, path); stats_counter_local("propfind-root", 1, pfsamplerate); ret = simple_propfind_with_redirect(path, PROPFIND_DEPTH_ZERO, 0, getattr_propfind_callback, NULL, &subgerr); if (subgerr) { // Delete from cache on error; ignore errors from stat_cache_delete since we already have one - g_propagate_prefixed_error(gerr, subgerr, "get_stat: "); - stat_cache_delete(config->cache, path, NULL); + g_propagate_prefixed_error(gerr, subgerr, "%s: ", funcname); + stat_cache_value_set(config->cache, path, &value, NULL); goto fail; } else if (ret < 0) { // We don't ever expect ret < 0 without gerr - stat_cache_delete(config->cache, path, &subgerr); + stat_cache_value_set(config->cache, path, &value, &subgerr); if (subgerr) { - g_propagate_prefixed_error(gerr, subgerr, "get_stat: PROPFIND failed"); + g_propagate_prefixed_error(gerr, subgerr, "%s: PROPFIND failed", funcname); goto fail; } - g_set_error(gerr, fusedav_quark(), ENETDOWN, "get_stat: PROPFIND failed"); + g_set_error(gerr, fusedav_quark(), ENETDOWN, "%s: PROPFIND failed", funcname); goto fail; } - log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "Zero-depth PROPFIND succeeded: %s", path); + log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "%s: Zero-depth PROPFIND succeeded: %s", funcname, path); // The propfind succeeded, so if the item does not exist, then it is ENOENT. skip_freshness_check = ALREADY_FRESH; // If in saint mode and the item wasn't already in the stat cache, this will return ENETDOWN. get_stat_from_cache(path, stbuf, skip_freshness_check, &subgerr); if (subgerr) { - g_propagate_prefixed_error(gerr, subgerr, "get_stat: "); + g_propagate_prefixed_error(gerr, subgerr, "%s: ", funcname); goto fail; } // success (we could just return, but it looks more consistent to goto finish after the goto fails above @@ -721,13 +878,14 @@ static void get_stat(const char *path, struct stat *stbuf, GError **gerr) { parent_path = path_parent(path); if (parent_path == NULL) goto fail; - log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "Getting parent path entry: %s", parent_path); + log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "%s: Getting parent path entry: %s", funcname, parent_path); parent_children_update_ts = stat_cache_read_updated_children(config->cache, parent_path, &tmpgerr); if (tmpgerr) { - g_propagate_prefixed_error(gerr, tmpgerr, "get_stat: "); + g_propagate_prefixed_error(gerr, tmpgerr, "%s: ", funcname); goto fail; } - log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "Parent was updated: %s %lu", parent_path, parent_children_update_ts); + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, + "%s: Parent was updated: %s %lu", funcname, parent_path, parent_children_update_ts); /* When new files are being uploaded to fresh directories, it will trigger complete propfinds * which can be expensive. We saw also where we saw repeated complete propfinds to the same @@ -761,31 +919,77 @@ static void get_stat(const char *path, struct stat *stbuf, GError **gerr) { time_since = time(NULL) - parent_children_update_ts; // Keep stats for each second 0-6, then bucket everything over 6 stats_histo("profind_ttl", time_since, 6, pfsamplerate); - // If the parent directory is out of date, update it. - if (time_since > STAT_CACHE_NEGATIVE_TTL) { - GError *subgerr = NULL; + needs_propfind = requires_propfind(path, time_since, &tmpgerr); + if (tmpgerr) { + g_propagate_prefixed_error(gerr, tmpgerr, "%s: ", funcname); + goto fail; + } - stats_counter_local("propfind-nonnegative-cache", 1, pfsamplerate); - log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "get_stat: Calling update_directory: %s; attempt_progressive_update will be %d", - parent_path, (parent_children_update_ts > 0)); + if (needs_propfind) { + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "%s: Calling update_directory: %s; attempt_progressive_update will be %d", + funcname, parent_path, (parent_children_update_ts > 0)); // If parent_children_update_ts is 0, there are no entries for updated_children in statcache // In that case, skip the progressive propfind and go straight to complete propfind update_directory(parent_path, (parent_children_update_ts > 0), &subgerr); if (subgerr) { - g_propagate_prefixed_error(gerr, subgerr, "get_stat: "); + g_propagate_prefixed_error(gerr, subgerr, "%s: ", funcname); goto fail; } - } else { - stats_counter_local("propfind-negative-cache", 1, pfsamplerate); - BUMP(propfind_negative_cache); - } + } // Try again to hit the file in the stat cache. skip_freshness_check = ALREADY_FRESH; ret = get_stat_from_cache(path, stbuf, skip_freshness_check, &tmpgerr); if (tmpgerr) { - log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "get_stat: propagating error from get_stat_from_cache on %s", path); - g_propagate_prefixed_error(gerr, tmpgerr, "get_stat: "); + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, + "%s: error from get_stat_from_cache on %s :: %d", funcname, path, tmpgerr->code); + if (tmpgerr->code == ENOENT) { + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "%s: ENOENT on %s; creating negative entry", funcname, path); + // Only need to adjust negative entry if there really was a propfind + if (needs_propfind) { + log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, + "%s: creating negative entry (A). %s: st_mode: %d", funcname, path, stbuf->st_mode); + // Add a negative entry + if (stbuf->st_mode != 0) { + log_print(LOG_WARNING, SECTION_FUSEDAV_PROP, + "%s: Expected negative entry (a); got: %s : st_mode=%d", funcname, path, stbuf->st_mode); + } + stat_cache_from_propfind(&value, true); + value.st = *stbuf; + value.st.st_mode = 0; // Make it so, even if it already is + log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "%s: ENOENT on %s; calling stat_cache_value_set on if", funcname, path); + stat_cache_value_set(config->cache, path, &value, &subgerr); + } + if (subgerr) { + g_propagate_prefixed_error(gerr, subgerr, "%s: ENOENT: ", funcname); + goto fail; + } + } + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "%s: propagating error from get_stat_from_cache on %s", funcname, path); + g_propagate_prefixed_error(gerr, tmpgerr, "%s: ", funcname); + goto fail; + } else if (ret == -ENOENT) { + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "%s: ENOENT from get_stat_from_cache on %s", funcname, path); + // Only need to adjust negative entry if there really was a propfind + if (needs_propfind) { + log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, + "%s: creating negative entry (B). %s: st_mode: %d", funcname, path, stbuf->st_mode); + // Add a negative entry + if (stbuf->st_mode != 0) { + log_print(LOG_WARNING, SECTION_FUSEDAV_PROP, + "%s: Expected negative entry (b); got: %s : st_mode=%d", funcname, path, stbuf->st_mode); + } + stat_cache_from_propfind(&value, true); + value.st = *stbuf; + value.st.st_mode = 0; // Make it so, even if it already is + log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "%s: ENOENT on %s; calling stat_cache_value_set on else", funcname, path); + stat_cache_value_set(config->cache, path, &value, &subgerr); + } + if (subgerr) { + g_propagate_prefixed_error(gerr, subgerr, "%s: ENOENT: ", funcname); + goto fail; + } + g_set_error(gerr, fusedav_quark(), ENOENT, "%s: ENOENT", funcname); goto fail; } if (ret == 0) goto finish; @@ -891,7 +1095,7 @@ static int dav_getattr(const char *path, struct stat *stbuf) { } return processed_gerror("dav_getattr: ", path, &gerr); } - print_stat(stbuf, "dav_getattr"); + print_stat(stbuf, "dav_getattr", path); log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "Done: dav_getattr(%s)", path); return 0; @@ -901,6 +1105,7 @@ static void common_unlink(const char *path, bool do_unlink, GError **gerr) { static const char *funcname = "common_unlink"; struct fusedav_config *config = fuse_get_context()->private_data; struct stat st; + struct stat_cache_value value; GError *gerr2 = NULL; GError *gerr3 = NULL; @@ -960,8 +1165,10 @@ static void common_unlink(const char *path, bool do_unlink, GError **gerr) { log_print(LOG_DEBUG, SECTION_FUSEDAV_FILE, "%s: calling filecache_delete on %s", funcname, path); filecache_delete(config->cache, path, true, &gerr2); - log_print(LOG_DEBUG, SECTION_FUSEDAV_FILE, "%s: calling stat_cache_delete on %s", funcname, path); - stat_cache_delete(config->cache, path, &gerr3); + memset(&value, 0, sizeof(struct stat_cache_value)); + log_print(LOG_DEBUG, SECTION_FUSEDAV_FILE, "%s: calling stat_cache_negative_entry on %s", funcname, path); + stat_cache_value_set(config->cache, path, &value, &gerr3); + // stat_cache_negative_entry(config->cache, path, update, &gerr3); // If we need to combine 2 errors, use one of the error messages in the propagated prefix if (gerr2 && gerr3) { @@ -996,7 +1203,7 @@ static int dav_unlink(const char *path) { return processed_gerror("dav_unlink: ", path, &gerr); } - log_print(LOG_INFO, SECTION_FUSEDAV_FILE, "dav_unlink: deleted \"%s\")", path); + log_print(LOG_NOTICE, SECTION_FUSEDAV_FILE, "dav_unlink: deleted \"%s\")", path); return 0; } @@ -1006,6 +1213,7 @@ static int dav_rmdir(const char *path) { GError *gerr = NULL; char fn[PATH_MAX]; bool has_child; + struct stat_cache_value value; struct stat st; long response_code = 500; // seed it as bad so we can enter the loop CURLcode res = CURLE_OK; @@ -1025,15 +1233,16 @@ static int dav_rmdir(const char *path) { return processed_gerror(funcname, path, &gerr); } + update_directory(path, true, &gerr); + if (gerr) { + return processed_gerror(funcname, path, &gerr); + } + if (!S_ISDIR(st.st_mode)) { log_print(LOG_INFO, SECTION_FUSEDAV_DIR, "%s: failed to remove `%s\': Not a directory", funcname, path); return -ENOTDIR; } - // The slash should force it to find entries in the directory after the slash, and - // not the directory itself - snprintf(fn, sizeof(fn), "%s/", path); - // Check to see if it is empty ... // get_stat already called update_directory, which called stat_cache_updated_children // so the stat cache should be up to date. @@ -1043,6 +1252,10 @@ static int dav_rmdir(const char *path) { return -ENOTEMPTY; } + // The slash should force it to find entries in the directory after the slash, and + // not the directory itself + snprintf(fn, sizeof(fn), "%s/", path); + for (int idx = 0; idx < num_filesystem_server_nodes && (res != CURLE_OK || response_code >= 500); idx++) { CURL *session; struct curl_slist *slist = NULL; @@ -1081,7 +1294,9 @@ static int dav_rmdir(const char *path) { log_print(LOG_DEBUG, SECTION_FUSEDAV_DIR, "%s: removed(%s)", funcname, path); - stat_cache_delete(config->cache, path, &gerr); + memset(&value, 0, sizeof(struct stat_cache_value)); + stat_cache_value_set(config->cache, path, &value, &gerr); + // stat_cache_negative_entry(config->cache, path, update, &gerr); if (gerr) { return processed_gerror(funcname, path, &gerr); } @@ -1179,6 +1394,7 @@ static int dav_rename(const char *from, const char *to) { struct stat st; char fn[PATH_MAX]; struct stat_cache_value *entry = NULL; + struct stat_cache_value value; long response_code = 500; // seed it as bad so we can enter the loop CURLcode res = CURLE_OK; @@ -1197,7 +1413,7 @@ static int dav_rename(const char *from, const char *to) { get_stat(from, &st, &gerr); if (gerr) { - server_ret = processed_gerror("dav_rmdir: ", from, &gerr); + server_ret = processed_gerror("dav_rename: ", from, &gerr); goto finish; } @@ -1300,7 +1516,9 @@ static int dav_rename(const char *from, const char *to) { goto finish; } - stat_cache_delete(config->cache, from, &gerr); + memset(&value, 0, sizeof(struct stat_cache_value)); + stat_cache_value_set(config->cache, from, &value, &gerr); + // stat_cache_negative_entry(config->cache, from, update, &gerr); if (gerr) { local_ret = processed_gerror(funcname, from, &gerr); goto finish; diff --git a/src/props.c b/src/props.c index 0560237f..c4fdf852 100644 --- a/src/props.c +++ b/src/props.c @@ -352,7 +352,7 @@ static size_t header_callback(void *contents, size_t length, size_t nmemb, __unu "header_callback: got readonly:'%s'", header); } else if (strcasestr(header, "readwrite") != NULL) { clear_readonly_mode(); - log_print(LOG_INFO, SECTION_PROPS_DEFAULT, + log_print(LOG_DEBUG, SECTION_PROPS_DEFAULT, "header_callback: got readwrite:'%s'", header); } else { // If we get something other than readonly or readwrite, punt. Default is read-write @@ -363,7 +363,7 @@ static size_t header_callback(void *contents, size_t length, size_t nmemb, __unu } } - log_print(LOG_INFO, SECTION_PROPS_DEFAULT, "header_callback: '%s' :: %d, %d", header, length, nmemb); + log_print(LOG_DEBUG, SECTION_PROPS_DEFAULT, "header_callback: '%s' :: %d, %d", header, length, nmemb); free(header); return length * nmemb; } @@ -441,7 +441,7 @@ int simple_propfind(const char *path, size_t depth, time_t last_updated, props_r ""); // Perform the request and parse the response. - log_print(LOG_INFO, SECTION_PROPS_DEFAULT, "%s: About to perform (%s) PROPFIND (%ul).", + log_print(LOG_INFO, SECTION_PROPS_DEFAULT, "%s: About to perform (%s) PROPFIND (%lu).", funcname, last_updated > 0 ? "progressive" : "complete", last_updated); timed_curl_easy_perform(session, &res, &response_code, &elapsed_time); diff --git a/src/session.c b/src/session.c index dc152b4d..34dab8ff 100644 --- a/src/session.c +++ b/src/session.c @@ -432,11 +432,11 @@ static int session_debug(__unused CURL *handle, curl_infotype type, char *data, // We want to see the "Trying message, but the others only when in some // level of debug if (strstr(msg, "Trying")) { - log_print(LOG_INFO, SECTION_SESSION_DEFAULT, "cURL: %s", msg); + log_print(LOG_DEBUG, SECTION_SESSION_DEFAULT, "cURL: %s", msg); print_ipaddr_pair(msg); } else { - log_print(LOG_INFO, SECTION_SESSION_DEFAULT, "cURL: %s", msg); + log_print(LOG_DEBUG, SECTION_SESSION_DEFAULT, "cURL: %s", msg); } free(msg); } diff --git a/src/statcache.c b/src/statcache.c index 6ed39d36..398d4179 100644 --- a/src/statcache.c +++ b/src/statcache.c @@ -74,8 +74,8 @@ unsigned long stat_cache_get_local_generation(void) { return ret; } -int print_stat(struct stat *stbuf, const char *title) { - log_print(LOG_DEBUG, SECTION_STATCACHE_OUTPUT, "stat: %s", title); +int print_stat(struct stat *stbuf, const char *title, const char *path) { + log_print(LOG_DEBUG, SECTION_STATCACHE_OUTPUT, "stat: %s :: %s", title, path); log_print(LOG_DEBUG, SECTION_STATCACHE_OUTPUT, " .st_mode=%04o", stbuf->st_mode); log_print(LOG_DEBUG, SECTION_STATCACHE_OUTPUT, " .st_nlink=%ld", stbuf->st_nlink); log_print(LOG_DEBUG, SECTION_STATCACHE_OUTPUT, " .st_uid=%d", stbuf->st_uid); @@ -290,6 +290,7 @@ void stat_cache_open(stat_cache_t **cache, struct stat_cache_supplemental *suppl log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "%s: Cache does not exist, using new data version %d", funcname); data_version = STAT_CACHE_DATA_VERSION; } + log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "%s: Using data version %d", funcname, data_version); stat_cache_data_version_set(*cache, data_version, &subgerr); @@ -355,6 +356,13 @@ struct stat_cache_value *stat_cache_value_get(stat_cache_t *cache, const char *p stats_counter("statcache_miss", 1, pfsamplerate); return NULL; } + // If this is a negative entry, we need to return the value so the entry can be processed + else if (value->st.st_mode == 0) { + log_print(LOG_INFO, SECTION_STATCACHE_CACHE, "stat_cache_value_get: negative entry on path: %s", path); + stats_counter("statcache_negative_entry", 1, pfsamplerate); + print_stat(&value->st, "stat_cache_value_get", path); + return value; + } if (vallen != sizeof(struct stat_cache_value)) { g_set_error (gerr, leveldb_quark(), E_SC_LDBERR, "stat_cache_value_get: Length %lu is not expected length %lu.", vallen, sizeof(struct stat_cache_value)); @@ -403,7 +411,8 @@ struct stat_cache_value *stat_cache_value_get(stat_cache_t *cache, const char *p directory, time_since); free(directory); if (time_since > CACHE_TIMEOUT) { - log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "stat_cache_value_get: %s is too old (%lu seconds).", + log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, + "stat_cache_value_get: Parent directory for %s is too old (%lu seconds).", path, time_since); free(value); stats_counter("statcache_stale", 1, pfsamplerate); @@ -501,13 +510,127 @@ time_t stat_cache_read_updated_children(stat_cache_t *cache, const char *path, G return ret; } +// Use atime to store the next time we want a propfind +time_t stat_cache_next_propfind(struct stat_cache_value value) { + return value.st.st_atime; +} + +// A negative entry is an item in the cache which represents a miss, +// so we can cache its non-existence and regulate how often +// we make a propfind request to the server to check if it has +// come into existence. +bool stat_cache_is_negative_entry(struct stat_cache_value value) { + // The struct stat st gets zero'ed out when we put a negative entry in the cache. + // If an extant item is put in the cache, at st_mode will be non-zero. + // So use st_mode as our check for non-existence + if (value.st.st_mode == 0) return true; + else return false; +} + +// We use st_mode == 0 to denote that the entry is a negative (non-existing) one +void stat_cache_negative_set(struct stat_cache_value *value) { + value->st.st_mode = 0; +} + +// We need to know if this access was from a propfind in order to +// correctly note when to next call propfind on a negative entry +void stat_cache_from_propfind(struct stat_cache_value *value, bool bvalue) { + value->from_propfind = bvalue; +} + +// Determine the next fibs value (if we've reached it) +// curvalue is always a fib +static int next_fibs(const int curvalue, const int idx) { + // A negative entry will gradually wait longer and longer to retry until + // about 10 minutes (610 seconds); then every 610 seconds thereafter + static const int fibs[] = {0, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610}; + static const int fibs_len = sizeof(fibs) / sizeof(int); + + // If we're at the last element already, return that last indexed value + // (It should never be greater than fibs_len - 1; just being careful) + if (idx >= fibs_len - 1) return fibs[fibs_len - 1]; + + // If an exact match, return the next indexed value + if (curvalue == fibs[idx]) return fibs[idx + 1]; + + // The sentinel + return -1; +} + +// Create or update a negative entry in the stat cache for a deleted or non-existent object +static void stat_cache_negative_entry(stat_cache_t *cache, const char *path, struct stat_cache_value *value, GError **gerr) { + static const char *funcname = "stat_cache_negative_entry"; + struct stat_cache_value *existing = NULL; + GError *subgerr = NULL ; + + existing = stat_cache_value_get(cache, path, true, &subgerr); + if (subgerr) { + g_propagate_prefixed_error(gerr, subgerr, "%s: failed on stat_cache_get for %s", funcname, path); + return; + } + + if (existing) { + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "%s: incrementing entry %s", funcname, path); + // Keep mtime constant, equal to the time when the negative entry was created + // atime then is incremented by the next fib + if (stat_cache_is_negative_entry(*existing)) { + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "%s: negative entry %s", funcname, path); + if (value->from_propfind) { + int curfib; + int nextfib; + int idx = 0; + curfib = existing->st.st_atime - existing->st.st_mtime; + nextfib = next_fibs(curfib, idx); + while (nextfib == -1) { + idx++; + nextfib = next_fibs(curfib, idx); + } + + // Reset mtime to the current atime, and atime to the nextfib increment + value->st.st_mtime = existing->st.st_atime; + value->st.st_atime += existing->st.st_atime + nextfib; + log_print(LOG_NOTICE, SECTION_FUSEDAV_STAT, "%s: negative entry from propfind %s", funcname, path); + log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, + "%s: %s: negative entry from propfind; mode: %lu; atime: %lu; mtime: %lu", + funcname, path, value->st.st_mode, value->st.st_atime, value->st.st_mtime); + } + else { + // Just copy the st from existing to value + value->st = existing->st; + log_print(LOG_NOTICE, SECTION_FUSEDAV_STAT, + "%s: %s: negative entry not from propfind; mode: %lu; atime: %lu; mtime: %lu", + funcname, path, value->st.st_mode, value->st.st_atime, value->st.st_mtime); + } + } + free(existing); + } + else { + time_t curtime = time(NULL); + log_print(LOG_INFO, SECTION_FUSEDAV_STAT, "%s: creating entry %s", funcname, path); + value->st.st_mtime = curtime; + value->st.st_atime = curtime + 1; // the next fib + } + + // Check for error and return + if (subgerr) { + g_propagate_prefixed_error(gerr, subgerr, "%s: failed setting new negative entry for %s", funcname, path); + } + + log_print(LOG_DEBUG, SECTION_FUSEDAV_STAT, "%s: %s: mode: %lu; atime: %lu; mtime: %lu", + funcname, path, value->st.st_mode, value->st.st_atime, value->st.st_mtime); + + return; +} + void stat_cache_value_set(stat_cache_t *cache, const char *path, struct stat_cache_value *value, GError **gerr) { + static const char *funcname = "stat_cache_value_set"; leveldb_writeoptions_t *options; + GError *subgerr = NULL ; char *errptr = NULL; char *key; if (path == NULL) { - log_print(LOG_NOTICE, SECTION_STATCACHE_CACHE, "stat_cache_value_set: input path is null"); + log_print(LOG_NOTICE, SECTION_STATCACHE_CACHE, "%s: input path is null", funcname); return; } @@ -515,12 +638,23 @@ void stat_cache_value_set(stat_cache_t *cache, const char *path, struct stat_cac assert(value); + if (stat_cache_is_negative_entry(*value)) { + // Update value with negative entry values + stat_cache_negative_entry(cache, path, value, &subgerr); + if (subgerr) { + g_propagate_prefixed_error(gerr, subgerr, "%s: failed on stat_cache_negative_entry for %s", funcname, path); + return; + } + log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "%s: negative_entry; %s (mode %04o: atime %lu: mtime %lu)", + funcname, path, value->st.st_mode, value->st.st_atime, value->st.st_mtime); + } + value->updated = time(NULL); value->local_generation = stat_cache_get_local_generation(); key = path2key(path, false); - log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "CSET: %s (mode %04o: updated %lu: loc_gen %lu)", - key, value->st.st_mode, value->updated, value->local_generation); + log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "%s: %s (mode %04o: updated %lu: loc_gen %lu: atime %lu: mtime %lu)", + funcname, key, value->st.st_mode, value->updated, value->local_generation, value->st.st_atime, value->st.st_mtime); options = leveldb_writeoptions_create(); leveldb_put(cache, options, key, strlen(key) + 1, (char *) value, sizeof(struct stat_cache_value), &errptr); @@ -529,9 +663,9 @@ void stat_cache_value_set(stat_cache_t *cache, const char *path, struct stat_cac free(key); if (errptr != NULL || inject_error(statcache_error_setldb)) { - g_set_error (gerr, leveldb_quark(), E_SC_LDBERR, "stat_cache_value_set: leveldb_set error: %s", errptr ? errptr : "inject-error"); + g_set_error (gerr, leveldb_quark(), E_SC_LDBERR, "%s: leveldb_set error: %s", funcname, errptr ? errptr : "inject-error"); free(errptr); - log_print(LOG_ALERT, SECTION_STATCACHE_CACHE, "stat_cache_value_set: leveldb_get error, kill fusedav process"); + log_print(LOG_ALERT, SECTION_STATCACHE_CACHE, "%s: leveldb_get error, kill fusedav process", funcname); kill(getpid(), SIGTERM); return; } @@ -569,15 +703,20 @@ void stat_cache_delete(stat_cache_t *cache, const char *path, GError **gerr) { void stat_cache_delete_parent(stat_cache_t *cache, const char *path, GError **gerr) { char *p; GError *tmpgerr = NULL; + struct stat_cache_value value; BUMP(statcache_del_parent); + // Zero-out structure; some fields we don't populate but want to be 0, e.g. st_atim.tv_nsec + memset(&value, 0, sizeof(struct stat_cache_value)); + log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "stat_cache_delete_parent: %s", path); if ((p = path_parent(path))) { log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "stat_cache_delete_parent: deleting parent %s", p); - stat_cache_delete(cache, p, &tmpgerr); + stat_cache_negative_set(&value); + stat_cache_value_set(cache, path, &value, &tmpgerr); if (tmpgerr) { g_propagate_prefixed_error(gerr, tmpgerr, "stat_cache_delete_parent: "); } @@ -591,7 +730,8 @@ void stat_cache_delete_parent(stat_cache_t *cache, const char *path, GError **ge } else { log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "stat_cache_delete_parent: not deleting parent, deleting child %s", path); - stat_cache_delete(cache, path, &tmpgerr); + stat_cache_negative_set(&value); + stat_cache_value_set(cache, path, &value, &tmpgerr); if (tmpgerr) { g_propagate_prefixed_error(gerr, tmpgerr, "stat_cache_delete_parent: no parent path"); } @@ -748,8 +888,11 @@ int stat_cache_enumerate(stat_cache_t *cache, const char *path_prefix, void (*f) while ((entry = stat_cache_iter_current(iter))) { log_print(LOG_DEBUG, SECTION_STATCACHE_ITER, "key: %s", entry->key); log_print(LOG_DEBUG, SECTION_STATCACHE_ITER, "fn: %s", entry->key + (iter->key_prefix_len - 1)); - f(path_prefix, entry->key + (iter->key_prefix_len - 1), user); - ++found_entries; + // Ignore negative (non-existent) entries, those tagged with st_mode == 0 + if (entry->value->st.st_mode != 0) { + f(path_prefix, entry->key + (iter->key_prefix_len - 1), user); + ++found_entries; + } free(entry); stat_cache_iter_next(iter); } @@ -765,6 +908,7 @@ int stat_cache_enumerate(stat_cache_t *cache, const char *path_prefix, void (*f) void stat_cache_walk(void) { leveldb_readoptions_t *roptions; struct leveldb_iterator_t *iter; + const struct stat_cache_value *itervalue; log_print(LOG_NOTICE, SECTION_STATCACHE_CACHE, "stat_cache_walk: starting: %p", gcache); @@ -773,9 +917,14 @@ void stat_cache_walk(void) { iter = leveldb_create_iterator(gcache, roptions); // We've kept a pointer to cache for just this call leveldb_iter_seek_to_first(iter); for (; leveldb_iter_valid(iter); leveldb_iter_next(iter)) { - size_t klen; + size_t klen, vlen; + bool negative_entry; + char posneg[] = "positive"; const char *iterkey = leveldb_iter_key(iter, &klen); - log_print(LOG_NOTICE, SECTION_STATCACHE_CACHE, "stat_cache_walk: iterkey = %s", iterkey); + itervalue = (const struct stat_cache_value *) leveldb_iter_value(iter, &vlen); + negative_entry = stat_cache_is_negative_entry(*itervalue); + if (negative_entry) strcpy(posneg, "negative"); + log_print(LOG_NOTICE, SECTION_STATCACHE_CACHE, "stat_cache_walk: iterkey = %s :: posneg: %s", iterkey, posneg); } leveldb_iter_destroy(iter); leveldb_readoptions_destroy(roptions); @@ -789,12 +938,15 @@ bool stat_cache_dir_has_child(stat_cache_t *cache, const char *path) { BUMP(statcache_has_child); - log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "stat_cache_dir_has_children(%s)", path); + log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "stat_cache_dir_has_child(%s)", path); iter = stat_cache_iter_init(cache, path); if ((entry = stat_cache_iter_current(iter))) { - has_children = true; - log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "stat_cache_dir_has_children(%s); entry \'%s\'", path, entry->key); + // Ignore negative (non-existent) entries, those tagged with st_mode == 0 + if (entry->value->st.st_mode != 0) { + has_children = true; + log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "stat_cache_dir_has_child(%s); entry \'%s\'", path, entry->key); + } free(entry); } stat_cache_iterator_free(iter); @@ -807,22 +959,30 @@ void stat_cache_delete_older(stat_cache_t *cache, const char *path_prefix, unsig struct stat_cache_entry *entry; GError *tmpgerr = NULL; unsigned int deleted_entries = 0; + struct stat_cache_value value; BUMP(statcache_delete_older); + // Zero-out structure; some fields we don't populate but want to be 0, e.g. st_atim.tv_nsec + memset(&value, 0, sizeof(struct stat_cache_value)); + log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "stat_cache_delete_older: %s", path_prefix); iter = stat_cache_iter_init(cache, path_prefix); while ((entry = stat_cache_iter_current(iter))) { - log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "stat_cache_delete_older: %s: min_gen %lu: loc_gen %lu", - entry->key, minimum_local_generation, entry->value->local_generation); - if (entry->value->local_generation < minimum_local_generation) { - stat_cache_delete(cache, key2path(entry->key), &tmpgerr); - ++deleted_entries; - if (tmpgerr) { - g_propagate_prefixed_error(gerr, tmpgerr, "stat_cache_delete_older: "); - free(entry); - stat_cache_iterator_free(iter); - return; + // Not deleting, rather, inserting negative entries. + if (entry->value->st.st_mode != 0) { + log_print(LOG_DEBUG, SECTION_STATCACHE_CACHE, "stat_cache_delete_older: %s: min_gen %lu: loc_gen %lu", + entry->key, minimum_local_generation, entry->value->local_generation); + if (entry->value->local_generation < minimum_local_generation) { + stat_cache_negative_set(&value); + stat_cache_value_set(cache, key2path(entry->key), &value, &tmpgerr); + if (tmpgerr) { + g_propagate_prefixed_error(gerr, tmpgerr, "stat_cache_delete_older: "); + free(entry); + stat_cache_iterator_free(iter); + return; + } + ++deleted_entries; } } free(entry); @@ -1006,7 +1166,8 @@ void stat_cache_prune(stat_cache_t *cache, bool first) { } if (bloomfilter_exists(boptions, parentpath, strlen(parentpath))) { - log_print(LOG_DEBUG, SECTION_STATCACHE_PRUNE, "stat_cache_prune: exists in bloom filter\'%s\'", parentpath); + log_print(LOG_DEBUG, SECTION_STATCACHE_PRUNE, + "stat_cache_prune: parent exists in bloom filter\'%s\'", parentpath); // If the parent is in the filter, and this child is a directory, add it to // the filter for iteration at the next depth if (S_ISDIR(itervalue->st.st_mode)) { @@ -1021,16 +1182,20 @@ void stat_cache_prune(stat_cache_t *cache, bool first) { // Future version of fusedav will have negative entries. If we revert a binding back, get rid // of these negative entries on startup, so as not to confuse this version of fusedav if (first && itervalue->st.st_mode == 0) { - log_print(LOG_INFO, SECTION_STATCACHE_PRUNE, "stat_cache_prune: deleting negative entry \'%s\'", path); + log_print(LOG_NOTICE, SECTION_STATCACHE_PRUNE, "stat_cache_prune: deleting negative entry \'%s\'", path); stat_cache_delete(cache, path, NULL); } } } else { - log_print(LOG_DEBUG, SECTION_STATCACHE_PRUNE, "stat_cache_prune: doesn't exist in bloom filter \'%s\'", parentpath); + struct stat_cache_value value; + // Zero-out structure; some fields we don't populate but want to be 0, e.g. st_atim.tv_nsec + memset(&value, 0, sizeof(struct stat_cache_value)); + log_print(LOG_NOTICE, SECTION_STATCACHE_PRUNE, "stat_cache_prune: doesn't exist in bloom filter \'%s\'", parentpath); ++deleted_entries; - log_print(LOG_INFO, SECTION_STATCACHE_PRUNE, "stat_cache_prune: deleting \'%s\'", path); - stat_cache_delete(cache, path, NULL); + log_print(LOG_NOTICE, SECTION_STATCACHE_PRUNE, "stat_cache_prune: setting negative entry \'%s\'", path); + stat_cache_negative_set(&value); + stat_cache_value_set(cache, path, &value, NULL); } free(parentpath); } @@ -1095,10 +1260,11 @@ void stat_cache_prune(stat_cache_t *cache, bool first) { log_print(LOG_DEBUG, SECTION_STATCACHE_PRUNE, "stat_cache_prune: exists in bloom filter (basepath of)\'%s\'", iterkey); } else { - log_print(LOG_DEBUG, SECTION_STATCACHE_PRUNE, "stat_cache_prune: updated_children: deleting \'%s\'", iterkey); + log_print(LOG_NOTICE, SECTION_STATCACHE_PRUNE, "stat_cache_prune: updated_children: deleting \'%s\'", iterkey); ++deleted_entries; // We recreate the basics of stat_cache_delete here, since we can't call it directly // since it doesn't deal with keys with "updated_children:" + // NB. We are not imitating stat_cache_negative_entry here woptions = leveldb_writeoptions_create(); leveldb_delete(cache, woptions, iterkey, strlen(iterkey) + 1, &errptr); leveldb_writeoptions_destroy(woptions); diff --git a/src/statcache.h b/src/statcache.h index fa2f09e2..e139a828 100644 --- a/src/statcache.h +++ b/src/statcache.h @@ -53,16 +53,17 @@ struct stat_cache_iterator { size_t key_prefix_len; }; +// For values which exist in the cache struct stat_cache_value { struct stat st; unsigned long local_generation; time_t updated; - bool prepopulated; // Added to the local cache; not from the server. + bool from_propfind; // A propfind caused this update char remote_generation[RGEN_LEN]; }; void stat_cache_print_stats(void); -int print_stat(struct stat *stbuf, const char *title); +int print_stat(struct stat *stbuf, const char *title, const char *path); unsigned long stat_cache_get_local_generation(void); @@ -75,12 +76,17 @@ time_t stat_cache_read_updated_children(stat_cache_t *cache, const char *path, G void stat_cache_value_set(stat_cache_t *cache, const char *path, struct stat_cache_value *value, GError **gerr); void stat_cache_value_free(struct stat_cache_value *value); +bool stat_cache_is_negative_entry(struct stat_cache_value value); +void stat_cache_negative_set(struct stat_cache_value *value); +time_t stat_cache_next_propfind(struct stat_cache_value value); +void stat_cache_from_propfind(struct stat_cache_value *value, bool bvalue); void stat_cache_delete(stat_cache_t *cache, const char* path, GError **gerr); void stat_cache_delete_parent(stat_cache_t *cache, const char *path, GError **gerr); void stat_cache_delete_older(stat_cache_t *cache, const char *key_prefix, unsigned long minimum_local_generation, GError **gerr); void stat_cache_walk(void); -int stat_cache_enumerate(stat_cache_t *cache, const char *key_prefix, void (*f) (const char *path_prefix, const char *filename, void *user), void *user, bool force); +int stat_cache_enumerate(stat_cache_t *cache, const char *key_prefix, void (*f) (const char *path_prefix, + const char *filename, void *user), void *user, bool force); bool stat_cache_dir_has_child(stat_cache_t *cache, const char *path); void stat_cache_prune(stat_cache_t *cache, bool first); diff --git a/tests/Makefile b/tests/Makefile index 1c334822..a0087eee 100644 --- a/tests/Makefile +++ b/tests/Makefile @@ -1,10 +1,16 @@ testdir = /root/pantheon/fusedav/tests +curdir := $(shell pwd) cltest = $(testdir)/cltest.sh # usage on Makefile line: 'cltest-flags=-i64' # -i is iters; default is 64 cltest-flags= +urlencode = $(testdir)/urlencode.sh +# usage on Makefile line: 'urlencode-flags=-i64' +# -i is iters; default is 1 +urlencode-flags= + statcacheprune = $(testdir)/statcacheprune.sh # usage on Makefile line: 'statcacheprune-flags=-d2 -f64 -tdflt' # default for -d is 2; max allowed is 4; for -f it's 64 @@ -24,6 +30,21 @@ dutest = $(testdir)/dutest.sh # -v for verbose dutest-flags= +# Create a lot of files in a lot of directories +writefiles-create = $(testdir)/writefiles-create.sh +# -v for verbose +writefiles-create-flags= + +# Remove a lot of files in a lot of directories +writefiles-remove = $(testdir)/writefiles-remove.sh +# -v for verbose +writefiles-remove-flags= + +# Write some files, delete some of them, check for correct positive/negative entries +write-delete-checknegative = $(testdir)/write-delete-checknegative.sh +# -v for verbose +write-delete-checknegative-flags= + # NB: no PASS/FAIL notification yet from iozone, still requires eyeballs iozone = /root/pantheon/iozone/src/current/iozone # -g: start with files of this size (by default 64K) @@ -52,6 +73,10 @@ continualwrites = $(testdir)/continualwrites # flag -v for verbose, -f# for number of files 'continualwrites-flags=-v -w -f16' continualwrites-flags = +rename = $(testdir)/rename +# flag -v for verbose 'rename-flags=-v' +rename-flags = + one-open-many-writes = $(testdir)/one-open-many-writes # flag -v for verbose, -f# for number of files 'one-open-many-writes=-v -w -f16' one-open-many-writes-flags = @@ -62,9 +87,14 @@ forensichaventest-flags = trunc = $(testdir)/trunc # -v for verbose, -r# for number of rounds, -f# for number of files, -s# for size of write, -i# for -# number of write iters'trunc-flags=-v -r 8 -f 8 -s 32 -i 16' +# number of write iters 'trunc-flags=-v -r 8 -f 8 -s 32 -i 16' trunc-flags = +pfbackoff = $(testdir)/pfbackoff.sh +# -v for verbose, -n# for number of rounds +# number of iters 'pfbackoff-flags=-v -n 8' +pfbackoff-flags = + saintmode-haproxy = $(testdir)/saintmode-haproxy.sh # -v for verbose, -i# for number of write iters'saintmode-haproxy-flags=-v -i 16' saintmode-haproxy-flags = @@ -109,24 +139,32 @@ forensic-haven-cleanup = $(testdir)/forensic-haven-cleanup.sh # -v for verbose, 'forensic-haven-cleanup-flags=-v' forensic-haven-cleanup-flags = -all: run-simple-stress-tests +all: run-simple-stress-tests run-nonfiles-tests +# S +# # restrict unit tests to low-resource tests -run-unit-tests: echo-start run-cltest run-statcacheprune run-dutest run-readrecursive run-readwhatwaswritten-unit run-readwhatwaswritten-unlink-unit run-continualwrites-unit run-trunc run-forensic-haven-cleanup run-iozone-unit echo-finish +run-unit-tests: echo-start run-cltest run-urlencode run-statcacheprune run-dutest run-writefiles-create run-readrecursive run-writefiles-remove run-readwhatwaswritten-unit run-readwhatwaswritten-unlink-unit run-continualwrites-unit run-rename run-trunc run-iozone-unit echo-finish # stress test is all test, but run the stress version if there is both a unit and a stress version. e.g. iozone -run-stress-tests: echo-start run-cltest run-statcacheprune run-dutest run-readrecursive run-readwhatwaswritten-stress run-readwhatwaswritten-unlink-stress run-continualwrites-unit run-trunc run-forensic-haven-cleanup run-iozone-stress run-saintmode-haproxy run-saintmode-nginx run-unhealthy-haproxy run-saintmode-writes-nginx echo-finish +run-stress-tests: echo-start run-cltest run-urlencode run-statcacheprune run-dutest run-writefiles-create run-readrecursive run-writefiles-remove run-readwhatwaswritten-stress run-readwhatwaswritten-unlink-stress run-continualwrites-unit run-rename run-trunc run-iozone-stress run-saintmode-haproxy run-saintmode-nginx run-unhealthy-haproxy run-saintmode-writes-nginx echo-finish -# simple stress test; don't run the 'error' tests since they assume a onebox for creating error conditions which don't occur on yolo endpoint -run-simple-stress-tests: echo-finish run-cltest run-statcacheprune run-dutest run-readrecursive run-readwhatwaswritten-stress run-readwhatwaswritten-unlink-stress run-continualwrites-unit run-trunc run-forensic-haven-cleanup run-iozone-stress echo-finish +# simple stress test; don't run the 'saintmode' tests since they assume a unified development environment for creating error conditions which don't generally occur in production environments. +run-simple-stress-tests: echo-start run-cltest run-urlencode run-statcacheprune run-dutest run-writefiles-create run-readrecursive run-writefiles-remove run-readwhatwaswritten-stress run-readwhatwaswritten-unlink-stress run-continualwrites-unit run-rename run-trunc run-iozone-stress echo-finish + +# I'm having difficulties running some tests in /files, and some just in . Separate these and +# handle on the command line. If someone can figure out the issues switching over file system boundaries, +# please make this better. For now, I run, from : +# make -f /root/pantheon/fusedav/tests/Makefile run-nonfiles-tests; (cd files; make -f /root/pantheon/fusedav/tests/Makefile) +run-nonfiles-tests: echo-start run-pfbackoff run-write-delete-checknegative run-forensic-haven-cleanup echo-finish # stress test is all test, but run the stress version if there is both a unit and a stress version. e.g. iozone # unlink test is creating increasing numbers of open files which never get closed. Remove for now. -# run-continual-tests: run-cltest run-statcacheprune run-readrecursive run-readwhatwaswritten-stress run-readwhatwaswritten-unlink-stress run-trunc run-iozone-continual -run-continual-tests: echo-start run-cltest run-statcacheprune run-dutest run-readrecursive run-readwhatwaswritten-stress run-readwhatwaswritten-unlink-stress run-trunc run-forensic-haven-cleanup run-iozone-continual echo-finish +# run-continual-tests: run-cltest run-urlencode run-statcacheprune run-writefiles-create run-readrecursive run-writefiles-remove run-readwhatwaswritten-stress run-readwhatwaswritten-unlink-stress run-trunc run-iozone-continual +run-continual-tests: echo-start run-cltest run-urlencode run-statcacheprune run-dutest run-writefiles-create run-readrecursive run-writefiles-remove run-readwhatwaswritten-stress run-readwhatwaswritten-unlink-stress run-trunc run-iozone-continual echo-finish # short stress test is all tests but iozone, but run the stress version if there is both a unit and a stress version. e.g. iozone -run-short-stress-tests: echo-start run-cltest run-statcacheprune run-dutest run-readrecursive run-readwhatwaswritten-stress run-readwhatwaswritten-unlink-stress run-trunc echo-finish +run-short-stress-tests: echo-start run-cltest run-urlencode run-statcacheprune run-dutest run-writefiles-create run-readrecursive run-writefiles-remove run-readwhatwaswritten-stress run-readwhatwaswritten-unlink-stress run-continualwrites-unit run-rename run-trunc echo-finish # run this to test the system under error. To do this: # use the fusedav client inject error mechanism. Use the writewrite_test @@ -147,20 +185,43 @@ run-write-errors: run-continualwrites-unit run-forensic-haven-test: run-forensic-haven-unit echo-start: - @ echo "Start: "; date + @ echo "Start: "; date; echo "Current Directory: $(curdir)" +.PHONY: echo-finish echo-finish: @ echo "Finish: "; date run-cltest: $(cltest) $(cltest-flags) +run-urlencode: + $(urlencode) $(urlencode-flags) + run-statcacheprune: $(statcacheprune) $(statcacheprune-dirs) $(statcacheprune-flags) run-dutest: $(dutest) $(dutest-flags) +run-writefiles-create: + $(writefiles-create) $(writefiles-create-flags) + +run-writefiles-remove: + $(writefiles-remove) $(writefiles-remove-flags) + +.PHONY: run-write-delete-checknegative +run-write-delete-checknegative: + $(write-delete-checknegative) $(write-delete-checknegative-flags) + +.PHONY: run-forensic-haven-cleanup +run-forensic-haven-cleanup: + $(forensic-haven-cleanup) $(forensic-haven-flags) + +# Seems .PHONY is needed for this one; not sure why +.PHONY: run-pfbackoff +run-pfbackoff: + $(pfbackoff) $(pfbackoff-flags) + run-iozone-unit: $(iozone) -Ra $(iozone-unit-flags) @@ -203,6 +264,12 @@ run-continualwrites-unit: $(continualwrites) $(continualwrites): $(testdir)/continualwrites.c cc $< -std=c99 -g -o $@ +run-rename: $(rename) + $(rename) $(rename-flags) + +$(rename): $(testdir)/rename.c + cc $< -std=c99 -g -o $@ + run-one-open-many-writes-unit: $(one-open-many-writes) $(one-open-many-writes) $(one-open-many-writes-flags) @@ -249,6 +316,3 @@ run-perfanalysis-read: $(perfanalysis-read) $(perfanalysis-read): $(testdir)/perfanalysis-writeread.c cc $< -std=c99 -g -o $@ - -run-forensic-haven-cleanup: - $(forensic-haven-cleanup) $(forensic-haven-flags) diff --git a/tests/README b/tests/README new file mode 100644 index 00000000..851d79a0 --- /dev/null +++ b/tests/README @@ -0,0 +1,159 @@ +Setup: +Install the fusedav repository from github +If you install it in: /root/pantheon/fusedav; + then will be "/root/pantheon/fusedav/tests" + +NB. If you install it elsewhere, you may need to add +"testdir=" to the call to make, since some tests use that variable +to find other tests. + +A. The Basic Tests: + +1. The Regular Version: (will run "run-simple-stress-tests") +cd to a files directory, e.g. /srv/bindings//files +execute: make -f /Makefile + +2. The Short Version: (will run "run-unit-tests") +These are roughly the same set of tests as the Basic version above; +however, some of the tests are run with parameters to make them +do less work and finish more quickly. +cd to a files directory, e.g. /srv/bindings//files +execute: make -f /Makefile run-unit-tests + +3. The Long Version: (will run "run-stress-tests") +These are a superset of the Basic Tests, they include the "saintmode" tests. +These saintmode tests really only work in certain specially-configured, unified +development environments, since they attempt to disable various functionality +on the path to the fileserver, i.e. nginx and haproxy. +cd to a files directory, e.g. /srv/bindings//files +execute: make -f /Makefile run-stress-tests + +4. The Truncated Stress Version: (will run "run-short-stress-tests") +Same as #3, but omits iozone in order to get a shorter execution time. + +Individual Tests in the above suites: +cltest + - command line tests, cp, mv, rm, etc. +urlencode + - cltest, except that the filenames get coded to ensure we can urlencode correctly +statcacheprune + - creates a bunch of directories and files + - designed as stress test, run simulaneously on multiple bindings with differnt flags + which will create different file names on different fusedav bindings, and test + the ability to not get confused, and to keep up + - not sure why it's called statcacheprune, which is something rather different + - Previously used to trigger "Too Many Events" exception +dutest + - Regression test to check for zero-length files. + - Inadequate as tests because it has to hardcode the files it expects + to have zero-length +iozone + - Third party file system performance test. + - Mostly used as test for file system correctness, and for stress. + - The version we run has a slight modification, since there is one + POSIX feature we don't support +readrecursive + - Reads all files in the file system +openunlinkclose + - I forget what it's called, but this tests writing to a bare file descriptor +readwhatwaswritten + - write some files, read them back and ensure the content read is the same as was written +continualwrites + - Similar to readwhatwaswritten, but is designed to tally file system errors. + - Can be run in conjunction with fusedav error injection + - See instructions in continualwrites.c for more +rename + - Test renaming files +one-open-many-writes + - Hmm. "...derived from continualwrites.c. In the middle of the test, + stop the fileserver and see what happens." +forensichaventest + - Run in conjunction with test errors to ensure error'ed writes + go to the forensic haven +trunc + - tests truncating files on open, I think +pfbackoff + - test that non-existent files properly cause or avoid propfinds depending on + how many times they have been tried +saintmode-haproxy + - In a unified environment, partially or fully disables the fileserver in the + middle of the test by messing with haproxy. Tests that saintmode works correctly. +saintmode-nginx + - In a unified environment, partially or fully disables the fileserver in the + middle of the test by messing with nginx. Tests that saintmode works correctly. +saintmode-writes-nginx + - Checks that writes and removes fail when in saintmode +unhealthy-haproxy + - runs the short version of the basic tests (make -f Makefile above) while taking + selectively disabling haproxy. Perhaps a forerunner of saintmode-haproxy? + - Needs work to actually run +timestamptest + - Requires a binding id to be passed in + - Run on two fusedav bindings simultaneously +perfanalysis-write +perfanalysis-read + - See perfanalysis-writeread.c in Other Tests below +forensic-haven-cleanup + - The forensic haven needs to restrain the number of files it contains. + - This tests a number of scenarios to ensure that files are deleted as needed +forensic-haven-test + - run this test in conjunction with filecache_forensic_haven_test in + util.c while injecting errors (make INJECT_ERRORS=1) + - Run overnight or so; if there are no catastrophic failures (e.g. segv) + consider it a pass. + - NB: this test needs to create an errors file in <...>/files directory + but often fails because we are injecting errors. It may need to be + started several times before it actually takes. If the errors file + cannot be created, the program exits. + +B. Other Tests +1. continualtest.sh + Calls the Makefile in a loop and runs "run-continual-tests" set of tests. + It dumps heap and compares memory growth over time (hours, days, ...) + This was used when fusedav had a memory leak via curl and the nsf library +2. dual-binding-tests.sh + dual-binding-test.sh + basic-ops.sh + A somewhat failed experiment to design a flexible mechanism to + run tests against environments with multiple fusedav bindings. + The script dual-binding-test.sh can take different programs/scripts + one for each binding, and pass in some parameters to them. + The script dual-binding-tests.sh (tests plural) calls + dual-binding-test.sh (test singular), passing in basic-ops.sh + as the script for both, and runs a series of tests. +3. perfanalysis-writeread.c + Tests how long it takes before a write on one fusedav binding + is available on a different fusedav binding on the same environment. + One binding runs the program in write mode, the other in read mode. + These can be run via "make -f Makefile. + Somewhat complicated to run. +4. "gerror" tests + Not part of the tests directory itself. + After "make clean" on fusedav binary, recompile with: + "make INJECT_ERRORS=1" + Configure fusedav/src/util.c with the errors you want to simulate. + It will inject errors depending on the configuration, to test + the "gerror" mechanism. + Since it is hard to configure a system to cause the errors you + might want to track, and to ensure that the error reporting did + not itself introduce errors (Don't you hate it when reporting + an error causes the program to crash due to an errant pointer?) + this was originally created to inject errors to trigger those + gerror messages. + Somewhat complicated to run. See fusedav/src/util.c for + instructions. + +C. Other Tests and Miscellaneous Scripts +1. create-many-files.sh + Creates many files in the current directory. + Not part of testing, but can be used to create many files before testing + Often used to test propfind performance if a directory has many files +2. migrate-cassandra-data.sh + Not sure why it's here +3. test_fusedav_stress.py + A python mechanism for invoking the Basic Test, Regular Version + Not used +4. test_dav.py + Canonical unit tests called from python + Not used + diff --git a/tests/basic-ops.sh b/tests/basic-ops.sh new file mode 100755 index 00000000..5a8a8b50 --- /dev/null +++ b/tests/basic-ops.sh @@ -0,0 +1,311 @@ +#! /bin/bash +set +e + +echo "ENTER: basic-ops.sh $@" +usage() +{ +cat << EOF +usage: $0 options + +This script runs the basic ls test (for the dual-bindings.sh test) + +OPTIONS: + -h Show this message + -i Number of iterations + -b Binding dir and id + -c Command line args + -r Add -R to ls + -v Verbose +EOF +} + +iters=0 +verbose=0 +binding="none" +basedir="basic-ops" +testdir="basic-ops-dir" +dir=$basedir/$testdir +file="basic-ops-file" +cmd="none" +declare -i ret + +while getopts "hri:b:c:d:v" OPTION +do + case $OPTION in + h) + usage + exit 1 + ;; + i) + iters=$OPTARG + ;; + b) + binding=$OPTARG + ;; + c) + cmd=$OPTARG + ;; + d) + dir=$OPTARG + ;; + v) + verbose=1 + ;; + ?) + usage + exit + ;; + esac +done + +if [ $binding == "none" ]; then + echo "Binding (with dir and id) is required. Exiting ..." + exit +fi + +if [ $iters -eq 0 ]; then + iters=1 +fi + +list() { + echo "list: ls -al $1/$2" + ls -al $1/$2 + ret=$? + return $ret +} + +listR() { + echo "listR: ls -alR $1/$2" + ls -alR $1/$2 + ret=$? + return $ret +} + +makedir() { + echo "makedir: mkdir $1/$2" + if [ ! -d $1 ]; then + mkdir $1 + fi + mkdir $1/$2 + ret=$? + return $ret +} + +readfile() { + echo "read: cat $$file > /dev/null" + cat $file > /dev/null + ret=$? + return $ret +} + +writefile() { + echo "writefile: head -c 67 /dev/urandom > $1/$2/$3-$4" + head -c 67 /dev/urandom > $1/$2/$3-$4 + ret=$? + return $ret +} + +removedir() { + echo "removedir: rmdir $1/$2" + rmdir $1/$2 + ret=$? + return $ret +} + +removefiles() { + echo "removefiles: rm -f $1/$2/*" + rm -f $1/$2/* + ret=$? + return $ret +} + +removefile() { + echo "removefiles: rm -f $1/$2/$3-$4" + rm $1/$2/$3-$4 + ret=$? + return $ret +} + +insertsleep() { + sleep $1 + ret=$? + return $ret +} + +# get commands from string and put in array +commands=(${cmd//;/ }) +if [ $verbose -eq 1 ]; then + echo "COMMANDS: $cmd :: ${commands[*]}" +fi + +pass=0 +fail=0 + +if [ $verbose -eq 1 ]; then + starttime=$(date +%s) +fi + +for cmd in "${commands[@]}"; do + result=0 + expect_failure=0 + if [ $cmd == "list" ]; then + list $binding $dir + ret=$? + elif [ $cmd == "listbase" ]; then + list $binding $basedir + ret=$? + elif [ $cmd == "flist" ]; then + expect_failure=1 + echo "--Expect Failure" + list $binding $dir + ret=$? + elif [ $cmd == "listR" ]; then + listR $binding $dir + ret=$? + elif [ $cmd == "listRbase" ]; then + listR $binding $basedir + ret=$? + elif [ $cmd == "flistR" ]; then + expect_failure=1 + echo "--Expect Failure" + listR $binding $dir + ret=$? + elif [ $cmd == "makedir" ]; then + makedir $binding $dir + ret=$? + elif [ $cmd == "fmakedir" ]; then + expect_failure=1 + echo "--Expect Failure" + makedir $binding $dir + ret=$? + elif [ $cmd == "writefile" ]; then + fail=0 + pass=0 + iter=1 + while [ $iter -le $iters ] + do + echo "iter: $iter" + writefile $binding $dir $file $iter + ret=$? + # We will also increment once more below, so one of the values will be off by one. + # Am I worried? + if [ "$ret" -ne 0 ]; then + fail=$((fail + 1)) + else + pass=$((pass + 1)) + fi + iter=$((iter + 1)) + done + elif [ $cmd == "fwritefile" ]; then + expect_failure=1 + echo "--Expect Failure" + fail=0 + pass=0 + while [ $iter -le $iters ] + do + echo "iter: $iter" + writefile $binding $dir $file $iter + ret=$? + # We will also increment once more below, so one of the values will be off by one. + # Am I worried? + # Reverse meaning of ret + if [ "$ret" -eq 0 ]; then + fail=$((fail + 1)) + else + pass=$((pass + 1)) + fi + iter=$((iter + 1)) + done + elif [ $cmd == "readfile" ]; then + for file in $binding/$dir; do + readfile $file + ret=$? + # We will also increment once more below, so one of the values will be off by one. + # Am I worried? + if [ "$ret" -ne 0 ]; then + fail=$((fail + 1)) + else + pass=$((pass + 1)) + fi + done + elif [ $cmd == "freadfile" ]; then + expect_failure=1 + echo "--Expect Failure" + for file in $binding/$dir; do + readfile $file + ret=$? + # We will also increment once more below, so one of the values will be off by one. + # Am I worried? + # Reverse meaning of ret + if [ "$ret" -eq 0 ]; then + fail=$((fail + 1)) + else + pass=$((pass + 1)) + fi + done + elif [ $cmd == "removefiles" ]; then + removefiles $binding $dir + ret=$? + elif [ $cmd == "fremovefiles" ]; then + expect_failure=1 + echo "--Expect Failure" + removefiles $binding $dir + ret=$? + elif [ $cmd == "removefile" ]; then + removefile $binding $dir $file 1 + ret=$? + elif [ $cmd == "fremovefile" ]; then + expect_failure=1 + echo "--Expect Failure" + removefile $binding $dir $file 1 + ret=$? + elif [ $cmd == "removedir" ]; then + removedir $binding $dir + ret=$? + elif [ $cmd == "fremovedir" ]; then + expect_failure=1 + echo "--Expect Failure" + removedir $binding $dir + ret=$? + elif [ $cmd == "sleep" ]; then + insertsleep 3 + ret=$? + else + echo "Unknowned command: $cmd" + ret=0 + fi + + # If this is an expect failure call, reverse meaning of ret + if [ $expect_failure -ne 0 ]; then + if [ $ret -eq 0 ]; then + ret=1 + else + ret=0 + fi + echo "EXPECTED FAILURE: $ret" + fi + + if [ "$ret" -ne 0 ]; then + fail=$((fail + 1)) + echo "FAIL" + else + pass=$((pass + 1)) + echo "PASS" + fi +done + + +if [ $verbose -eq 1 ]; then + endtime=$(date +%s) + elapsedtime=$(( $endtime - $starttime )) + echo "Elapsed time: $elapsedtime" +fi + +if [ $fail -ne 0 ]; then + echo "FAIL: times failed $fail; files passed $pass" +else + echo "PASS: times passed $pass" +fi + +echo "EXIT: basic-ops.sh" +exit $fail diff --git a/tests/cltest.sh b/tests/cltest.sh index eda7178d..4d4dd4df 100755 --- a/tests/cltest.sh +++ b/tests/cltest.sh @@ -63,6 +63,7 @@ if [ $verbose -eq 1 ]; then starttime=$(date +%s) fi +echo "Current directory: $(pwd)" # append; this also creates a file for later tests rm cltest.file > /dev/null 2>&1 rm cltest.file.save > /dev/null 2>&1 diff --git a/tests/cltest2.sh b/tests/cltest2.sh index f949650b..9c356b1f 100755 --- a/tests/cltest2.sh +++ b/tests/cltest2.sh @@ -1,6 +1,8 @@ #! /bin/bash set +e +# Obsolete. A better version exists as cltest.sh + start=1 # Skip to test $start, which can be passed as a parameter if [ $# -gt 0 ] @@ -11,7 +13,7 @@ fi starttime=$(date +%s) iters=1 - jters=1 + jters=10000 # append; this also creates a file for later tests test=1 rm -f cltest2.file > /dev/null 2>&1 diff --git a/tests/dual-binding-create.sh b/tests/dual-binding-create.sh new file mode 100755 index 00000000..d76163c7 --- /dev/null +++ b/tests/dual-binding-create.sh @@ -0,0 +1,187 @@ +#! /bin/bash +set +e + +usage() +{ +cat << EOF +usage: $0 options + +This script tests that a file created on one binding is immediately available when accessed +on a different binding in the environment. + +OPTIONS: + -h Show this message + -i Number of iterations + -v Verbose + -1 First binding id + -2 Second binding id +EOF +} + +iters=6 +verbose=0 +vverbose=0 +b1="none" +b2="none" +pass=0 +fail=0 + +echo "ENTER dual-binding-write" + +while getopts "hi:1:2:v" OPTION +do + case $OPTION in + h) + usage + exit 1 + ;; + i) + iters=$OPTARG + ;; + 1) + b1=$OPTARG + ;; + 2) + b2=$OPTARG + ;; + v) + verbose=1 + ;; + w) + vverbose=1 + ;; + ?) + usage + exit + ;; + esac +done + +if [ $b1 == "none" ]; then + echo "Binding 1 id is required. Exiting ..." + exit +fi + +if [ $b2 == "none" ]; then + echo "Binding 2 id is required. Exiting ..." + exit +fi + +bid1path=/srv/bindings/$b1 +bid2path=/srv/bindings/$b2 + +# directory for the file +filedir=files/dual-binding-create-dir +# name of file being created +createdfile=$filedir/dual-binding-create.file + +# The fibonacci sequence; if fewer than this many seconds have passed +# since last ENOENT propfind on the missing file, no propfind is generated +fibs=(0 1 2 3 5 8 13 21 34 55 89 144 233 377 610) + +if [ $verbose -eq 1 ]; then + starttime=$(date +%s) +fi + +#### Set up +# Cleanup whatever might be in there +rm -f $bid1path/$filedir/* +rmdir $bid1path/$filedir + +# Reset the state of the files to an initial state +if [ $verbose -eq 1 ]; then + btool invalidate srv-bindings-$b1-files.mount +else + btool invalidate srv-bindings-$b1-files.mount > /dev/null 2>&1 +fi + +# make the directory for the new file and put a seed file there +# (just to have a non-empty directory) +mkdir $bid1path/$filedir + +iter=0 +while [ $iter -lt $iters ] +do + sleeptime=${fibs[$iter]} + + if [ $verbose -eq 1 ]; then + echo "Sleeping $sleeptime seconds" + fi + sleep $sleeptime + + if [ $verbose -eq 1 ]; then + echo "$iter: cat $bid1path/$createdfile" + date '+%Y-%m-%d %H:%M:%S' + cat $bid1path/$createdfile + else + # We haven't created the file yet, so access should trigger fibonacci backoff + cat $bid1path/$createdfile > /dev/null 2>&1 + fi + + iter=$((iter + 1)) +done + +# Create file on binding two +# Binding one is now in fibonacci backoff for 8 seconds, create file on bid2 +echo "createdfile" > $bid2path/$createdfile + +# Access file on binding one; won't be found for 8 seconds +# We only increment on propfinds returning ENOENT +# We did 5 iters above, on the 5th, the backoff window gets set to 8 + +for iter in 1 2 3; do + if [ $verbose -eq 1 ]; then + echo "$iter: cat $bid1path/$createdfile should fail" + date '+%Y-%m-%d %H:%M:%S' + fi + + if [ $verbose -eq 1 ]; then + cat $bid1path/$createdfile + else + cat $bid1path/$createdfile > /dev/null 2>&1 + fi + # Still in fibonacci backoff window, so should fail, since this binding doesn't think the file exists + if [ $? -eq 0 ]; then + fail=$((fail + 1)) + echo "FAIL" + else + pass=$((pass + 1)) + echo "PASS" + fi + + # Sleep to use up part of the fibonacci backoff window + sleep 3 +done + +if [ $verbose -eq 1 ]; then + echo "$iter: cat $bid1path/$createdfile should succeed" + date '+%Y-%m-%d %H:%M:%S' +fi + +# We should have slept 9 seconds and have slipped out of the fibonacci backoff window. +# Expect this access to trigger a propfind, and return success on fail access +if [ $verbose -eq 1 ]; then + cat $bid1path/$createdfile +else + cat $bid1path/$createdfile > /dev/null 2>&1 +fi +if [ $? -ne 0 ]; then + fail=$((fail + 1)) + echo "FAIL" +else + pass=$((pass + 1)) + echo "PASS" +fi + +if [ $verbose -eq 1 ]; then + endtime=$(date +%s) + elapsedtime=$(( $endtime - $starttime )) + echo "Elapsed time: $elapsedtime" +fi + +if [ $fail -ne 0 ]; then + echo "FAIL: attempts failed $fail; attempts passed $pass" +else + echo "PASS: attempts passed $pass" +fi + diff --git a/tests/dual-binding-test.sh b/tests/dual-binding-test.sh new file mode 100755 index 00000000..9def836e --- /dev/null +++ b/tests/dual-binding-test.sh @@ -0,0 +1,149 @@ +#! /bin/bash +set +e + +usage() +{ +cat << EOF +usage: $0 options + +This script enables dual-binding tests + +OPTIONS: + -h Show this message + -i Number of iterations + -v Verbose + -1 First binding id + -2 Second binding id + -a First program + -b Second program + -c First program command line args + -d Second program command line args + Example: /root/pantheon/fusedav/tests/dual-binding-tests.sh -1 32fffe7694044da1be9c41cfd489185d -2 975b26cec42a4c1aa7976ad941aa54f9 -a basic-ops.sh -b basic-ops.sh -v -c "-v -c write" -d "-v -c read" +EOF +} + +iters=0 +verbose=0 +b1="none" +b2="none" +pa="none" +pb="none" +ca="none" +cb="none" + +echo "ENTER dual-binding-test" + +scriptdir=/root/pantheon/fusedav/tests + +while getopts "hi:1:2:a:b:c:d:v" OPTION +do + case $OPTION in + h) + usage + exit 1 + ;; + i) + iters=$OPTARG + ;; + 1) + b1=$OPTARG + ;; + 2) + b2=$OPTARG + ;; + a) + pa=$OPTARG + ;; + b) + pb=$OPTARG + ;; + c) + ca=$OPTARG + ;; + d) + cb=$OPTARG + ;; + s) + scriptdir=$OPTARG + ;; + v) + verbose=1 + ;; + ?) + usage + exit + ;; + esac +done + +if [ $b1 == "none" ]; then + echo "Binding 1 id is required. Exiting ..." + exit +fi + +if [ $b2 == "none" ]; then + echo "Binding 2 id is required. Exiting ..." + exit +fi + +if [ $pa == "none" ]; then + echo "Program a is required. Exiting ..." + exit +fi + +if [ $pb == "none" ]; then + echo "Program b is required. Exiting ..." + exit +fi + +pa=$scriptdir/$pa +pb=$scriptdir/$pb + +if [ $iters -eq 0 ]; then + iters=1 +fi + +bid1dir=/srv/bindings/$b1/files +bid2dir=/srv/bindings/$b2/files + +pass=0 +fail=0 + +if [ $verbose -eq 1 ]; then + starttime=$(date +%s) + echo "Program a on binding 1: $pa -b $bid1dir $ca" + echo "Program b on binding 2: $pb -b $bid2dir $cb" + echo "Script dir is $scriptdir" +fi + +iter=1 +while [ $iter -le $iters ] +do + if [ $verbose -eq 1 ]; then + echo "$iter: " + fi + $pa -b $bid1dir $ca + if [ $? -eq 0 ]; then + pass=$((pass + 1)) + else + fail=$((fail + 1)) + fi + $pb -b $bid2dir $cb + iter=$((iter + 1)) +done + +if [ $verbose -eq 1 ]; then + endtime=$(date +%s) + elapsedtime=$(( $endtime - $starttime )) + echo "Elapsed time: $elapsedtime" +fi + +if [ $fail -ne 0 ]; then + echo "FAIL: tests failed $fail; files passed $pass" +else + echo "PASS: tests passed $pass" +fi + +echo "EXIT dual-binding-tests" +exit $fail + diff --git a/tests/dual-binding-tests.sh b/tests/dual-binding-tests.sh new file mode 100755 index 00000000..d15e3947 --- /dev/null +++ b/tests/dual-binding-tests.sh @@ -0,0 +1,169 @@ +#! /bin/bash +set +e + +# This is a wrapper script. It calls dual-binding-test.sh for a variety of tests which can +# test how one binding should respond when a different binding sees a particular request. + +usage() +{ +cat << EOF +usage: $0 options + +This script runs a series of dual binding tests + +OPTIONS: + -h Show this message + -i Number of iterations + -d Test directory + -v Verbose +EOF +} + +iters=0 +verbose=0 +testdir=/root/pantheon/fusedav/tests/ +bid1=0 +bid2=0 + +while getopts "hi:d:1:2:v" OPTION +do + case $OPTION in + h) + usage + exit 1 + ;; + i) + iters=$OPTARG + ;; + d) + testdir=$OPTARG + ;; + 1) + bid1=$OPTARG + ;; + 2) + bid2=$OPTARG + ;; + v) + verbose=1 + ;; + ?) + usage + exit + ;; + esac +done + +if [ $iters -eq 0 ]; then + iters=1 +fi + +pass=0 +fail=0 + +if [ $verbose -eq 1 ]; then + starttime=$(date +%s) +fi + +# Just list the tests to be run +# basic ops are: +# list: ls -al +# listR: ls -alR +# makedir: mkdir +# writefile: head -c 67; also give it a number of iters to write many files +# readfile: cat +# removefiles: rm -f +# removedir: rmdir +# Each of the commands has an 'f' version, e.g. flist +# The 'f' version expects failure, so failure is counted as pass + +echo "ENTER dual-binding-tests" + +iter=1 +while [ $iter -le $iters ] +do + echo; echo "TEST 1"; echo + echo; echo "PRELIMINARY"; echo + + # Preliminary: remove files and dir to set a clean slate + $testdir/dual-binding-test.sh -1 $bid1 -2 $bid2 -a basic-ops.sh -b basic-ops.sh -c "-i 1 -c removefiles;removedir" -d "-c null" + + # On the first binding, make a directory, put some files in it, + # remove the files, then remove directory via the second binding + echo; echo "TEST"; echo + + # Run the real test + $testdir/dual-binding-test.sh -1 $bid1 -2 $bid2 -a basic-ops.sh -b basic-ops.sh -v -c "-v -i 1 -c sleep;makedir;writefile;removefiles" -d "-v -c removedir" + + ret=$? + if [ $ret -eq 0 ]; then + pass=$((pass + 1)) + else + fail=$((fail + 1)) + fi + +######################################################################### + echo; echo "TEST 2"; echo + echo; echo "PRELIMINARY"; echo + + # remove files and dir to set a clean slate + $testdir/dual-binding-test.sh -1 $bid1 -2 $bid2 -a basic-ops.sh -b basic-ops.sh -c "-i 1 -c removefiles;removedir" -d "-c null" + + # Add removefiles and removedir afterward, to clean up + echo; echo "TEST"; echo + + # On the first binding, make a directory, and put some files in it, then + # remove directory via the second binding, which should fail (use the 'f' version to pass on failure) + $testdir/dual-binding-test.sh -1 $bid1 -2 $bid2 -a basic-ops.sh -b basic-ops.sh -v -c "-v -i 1 -c sleep;makedir;writefile" -d "-v -c fremovedir;removefiles;removedir" + ret=$? + if [ $ret -eq 0 ]; then + pass=$((pass + 1)) + else + fail=$((fail + 1)) + fi + + iter=$((iter + 1)) + +######################################################################### + echo; echo "TEST 3"; echo + echo; echo "PRELIMINARY"; echo + + # remove files and dir to set a clean slate + $testdir/dual-binding-test.sh -1 $bid1 -2 $bid2 -a basic-ops.sh -b basic-ops.sh -c "-i 1 -c removefiles;removedir" -d "-c null" + + # Add removefiles and removedir afterward, to clean up + echo; echo "TEST"; echo + + # On the first binding, make a directory, and put some files in it, then + # ls the binding, then remove some files but leave others, then ls the binding + # and expect to get back only the files which weren't removed + $testdir/dual-binding-test.sh -1 $bid1 -2 $bid2 -a basic-ops.sh -b basic-ops.sh -v -c "-v -i 2 -c sleep;makedir;writefile" -d "-v -c list;removefile;list;removefiles;removedir" + echo "Check the two lists; one should be missing basic-ops-file-1" + ret=$? + if [ $ret -eq 0 ]; then + pass=$((pass + 1)) + else + fail=$((fail + 1)) + fi + + iter=$((iter + 1)) + +######################################################################### + + +done + +######################################################################### +if [ $verbose -eq 1 ]; then + endtime=$(date +%s) + elapsedtime=$(( $endtime - $starttime )) + echo "Elapsed time: $elapsedtime" +fi + +if [ $fail -ne 0 ]; then + echo "FAIL: tests failed $fail; files passed $pass" +else + echo "PASS: tests passed $pass" +fi + +echo "EXIT dual-binding-tests" diff --git a/tests/dual-binding-write.sh b/tests/dual-binding-write.sh new file mode 100755 index 00000000..fad61255 --- /dev/null +++ b/tests/dual-binding-write.sh @@ -0,0 +1,153 @@ +#! /bin/bash +set +e + +usage() +{ +cat << EOF +usage: $0 options + +This script tests that a file created on one binding is immediately available when accessed +on a different binding in the environment. + +OPTIONS: + -h Show this message + -i Number of iterations + -v Verbose + -1 First binding id + -2 Second binding id +EOF +} + +iters=16 +doubleiters=32 +verbose=0 +b1="none" +b2="none" + +echo "ENTER dual-binding-write" + +while getopts "hi:1:2:v" OPTION +do + case $OPTION in + h) + usage + exit 1 + ;; + i) + iters=$OPTARG + ;; + 1) + b1=$OPTARG + ;; + 2) + b2=$OPTARG + ;; + v) + verbose=1 + ;; + ?) + usage + exit + ;; + esac +done + +if [ $b1 == "none" ]; then + echo "Binding 1 id is required. Exiting ..." + exit +fi + +if [ $b2 == "none" ]; then + echo "Binding 2 id is required. Exiting ..." + exit +fi + +bid1path=/srv/bindings/$b1 +bid2path=/srv/bindings/$b2 +filedir=dual-binding-dir + +if [ $verbose -eq 1 ]; then + starttime=$(date +%s) +fi + +# We used to have a two-second window which if kept open, would trigger +# a 404 on one binding when a different binding had just created a file. +# Simulate that just to make sure we have solved the problem. + +repeated_ls(){ + while true; do + if [ $verbose -eq 1 ]; then + echo "ls $1" + fi + ls $1 + sleep 1 + done +} + +#### Set up +# Cleanup whatever might be in there +rm -f $bid1path/files/$filedir/* +rmdir $bid1path/files/$filedir + +# make the directory for the new file and put a seed file there +# (just to have a non-empty directory) +mkdir $bid1path/files/$filedir +echo "seedfile" > $bid1path/files/$filedir/seedfile.txt +# Keep accessing the directory on bid1 to trigger the +# 2-second propfind window which should no longer exist +repeated_ls $bid1path/files/$filedir & +# Save of the function pid to kill it later +lspid1=$! +repeated_ls $bid2path/files/$filedir & +# Save of the function pid to kill it later +lspid2=$! + +iter=0 +# Write several new files to bid2 and expect them to appear on bid1 without delay +while [ $iter -lt $doubleiters ]; do + inneriter=0 + while [ $inneriter -lt $iter ]; do + head -c 67 /dev/urandom > $bid2path/files/$filedir/file-$iter-$inneriter.txt + cat $bid1path/files/$filedir/file-$iter-$inneriter.txt > /dev/null 2>&1 + + if [ $? -eq 0 ]; then + pass=$((pass + 1)) + if [ $verbose -eq 1 ]; then + echo "iter $iter-$inneriter: pass" + fi + else + fail=$((fail + 1)) + if [ $verbose -eq 1 ]; then + echo "iter $iter-$inneriter: fail" + fi + fi + + # Sleep from 0 - iter seconds the first half, + # then just 1 second each time the second half + # Just testing that the sleep interval does not + # matter for the ability to pick up the new file + if [ $iter -lt $iters ]; then + sleep $iter + else + sleep 1 + fi + inneriter=$((inneriter + 1)) + done + iter=$((iter + 1)) +done + +kill $lspid1 +kill $lspid2 + +if [ $verbose -eq 1 ]; then + endtime=$(date +%s) + elapsedtime=$(( $endtime - $starttime )) + echo "Elapsed time: $elapsedtime" +fi + +if [ $fail -ne 0 ]; then + echo "FAIL: tests failed $fail; files passed $pass" +else + echo "PASS: tests passed $pass" +fi + diff --git a/tests/forensic-haven-cleanup.sh b/tests/forensic-haven-cleanup.sh index f7564e3b..887210a7 100755 --- a/tests/forensic-haven-cleanup.sh +++ b/tests/forensic-haven-cleanup.sh @@ -39,7 +39,7 @@ if [ -f ../fusedav.conf ]; then fi if [ ! -f fusedav.conf ]; then - echo "ERROR: Need to be in /srv/bindings/ directory" + echo "ERROR: Need to be in /srv/bindings/ directory: $(pwd)" exit fi diff --git a/tests/pfbackoff.sh b/tests/pfbackoff.sh new file mode 100755 index 00000000..8027e2c6 --- /dev/null +++ b/tests/pfbackoff.sh @@ -0,0 +1,249 @@ +#! /bin/bash +set +e + +usage() +{ +cat << EOF +usage: $0 options + +This script tests that non-existent files using a fibonacci backoff +properly suppress or allow a propfind. This first test accesses files in less time than +the fibonacci backoff value, so that no propfinds are generated. The second test +waits for the required fibonacci backoff to have passed, so that propfinds +are generated. + +This script calls journalctl to get log messages, and uses their content +to ascertain success or failure. The log entries required are those +which don't print under production configuration. So the binding they +are run on requires that verbose logging be enabled. The script will +modify fusedav.conf to contain the following values: + +log_level=6 +log_level_by_section=600070707000000000700007 + +OPTIONS: + -h Show this message + -v Verbose + -n Number of iterations. Default 5 makes test take about a minute. +EOF +} + +numattempts=6 +verbose=0 + +while getopts "hvn:" OPTION +do + case $OPTION in + h) + usage + exit 1 + ;; + n) + numattempts=$OPTARG + ;; + v) + verbose=1 + ;; + ?) + usage + exit 1 + ;; + esac +done + +# Most tests need to be in the files directory, but this one needs to be +# one up. +if [ -f ../fusedav.conf ]; then + cd .. +fi + +if [ ! -f fusedav.conf ]; then + echo "ERROR: Need to be in /srv/bindings/ directory: $(pwd)" + exit +fi + +# e.g. /srv/bindings/ +path=$(pwd) +# binding id +bid=${path##*/} +# output file for journalctl, from which are read results +outfile=/tmp/propfind-negative-entry-backoff.out +# name of non-existent file +missingfile=files/basic-ops/missing-file.file +# We could use ${##/} notation, but that would likely complicate it +basemissingfile=missing-file.file + +# The fibonacci sequence; if fewer than this many seconds have passed +# since last ENOENT propfind on the missing file, no propfind is generated +fibs=(0 1 2 3 5 8 13 21 34 55 89 144 233 377 610) + +if [ $verbose -eq 1 ]; then + starttime=$(date +%s) +fi + +numattempt=0 + +pass=0 +fail=0 + + +##### TEST 1 +# Access a missing file on propfind fibonacci boundaries. Expect that +# each access will cause a new propfind + +# For journalctl +since=$(date '+%Y-%m-%d %H:%M:%S') + +# Set fusedav.conf for logging needed to get results from journalctl to parse +mv /srv/bindings/$bid/fusedav.conf /srv/bindings/$bid/fusedav.conf.1 +sed 's/log_level=.*/log_level=6/' /srv/bindings/$bid/fusedav.conf.1 > /srv/bindings/$bid/fusedav.conf.2 +sed 's/log_level_by_section=.*/log_level_by_section=600070707000000000700007/' /srv/bindings/$bid/fusedav.conf.1 > /srv/bindings/$bid/fusedav.conf + +# Reset the state of the 'missing file' to first attempt. +if [ $verbose -eq 1 ]; then + btool invalidate srv-bindings-$bid-files.mount +else + btool invalidate srv-bindings-$bid-files.mount > /dev/null 2>&1 +fi + + +while [ $numattempt -lt $numattempts ] +do + if [ $verbose -eq 1 ]; then + echo "$numattempt: cat $missingfile" + date '+%Y-%m-%d %H:%M:%S' + fi + + sleeptime=${fibs[$numattempt]} + + if [ $verbose -eq 1 ]; then + echo "Sleeping $sleeptime seconds" + fi + sleep $sleeptime + + if [ $verbose -eq 1 ]; then + cat $missingfile + else + cat $missingfile > /dev/null 2>&1 + fi + + numattempt=$(( numattempt + 1 )) +done + +if [ $verbose -eq 1 ]; then + echo "journalctl -a -u srv-bindings-$bid-files.mount --since $since --no-pager > $outfile" +fi +journalctl -a -u srv-bindings-$bid-files.mount --since "$since" --no-pager > $outfile + +# If the log level is not high enough, we won't get any output. This is an error. +gjctl=$(grep "requires_propfind.*$basemissingfile" $outfile) +if [ $? -ne 0 ]; then + fail=$((fail + 1)) + echo "FAIL: TEST 1: gjctl" +else + pass=$((pass + 1)) + + if [ $verbose -eq 1 ]; then + echo "OUTPUT: $gjctl" + fi + + # If we see "no propfind needed", we have failed; + grep -q "no propfind needed" $outfile + + if [ $? -eq 0 ]; then + fail=$((fail + 1)) + echo "FAIL: TEST 1" + else + pass=$((pass + 1)) + echo "PASS: TEST 1" + fi +fi + +#### TEST 2 +# Access the missing file. Some should trigger propfind, others not, +# depending on where the access is in the fibonacci backoff +# Start with the state of the previous test. We should be in an +# 8-second window where propfinds won't be triggered + +# Create a gap for the new journalctl call +sleep 1 + +# For journalctl +since=$(date '+%Y-%m-%d %H:%M:%S') + +attempt=0 +attempts=3 +sleeptime=2 + +while [ $attempt -lt $attempts ] +do + if [ $verbose -eq 1 ]; then + echo "$attempt: cat $missingfile" + date '+%Y-%m-%d %H:%M:%S' + fi + + if [ $verbose -eq 1 ]; then + cat $missingfile + else + cat $missingfile > /dev/null 2>&1 + fi + + attempt=$(( attempt + 1 )) + + # Sleep 2 seconds. This should allow 3 attempts at the + # missing file while we are still in the fibonacci + # backoff window + if [ $verbose -eq 1 ]; then + echo "Sleeping $sleeptime seconds" + fi + sleep $sleeptime + +done + +echo "journalctl -a -u srv-bindings-$bid-files.mount --since $since --no-pager > $outfile" +journalctl -a -u srv-bindings-$bid-files.mount --since "$since" --no-pager > $outfile + +gjctl=$(grep "requires_propfind.*$basemissingfile" $outfile) +if [ $? -ne 0 ]; then + fail=$((fail + 1)) + echo "FAIL: TEST 2: gjctl" +else + pass=$((pass + 1)) + + if [ $verbose -eq 1 ]; then + echo "OUTPUT: $gjctl" + fi + + # If we see "new propfind for path", we have failed; + grep -q "new propfind for path" $outfile + + if [ $? -eq 0 ]; then + fail=$((fail + 1)) + echo "FAIL: TEST 2" + else + pass=$((pass + 1)) + echo "PASS: TEST 2" + fi +fi + +#### Clean Up +# Set fusedav.conf back to original and do a remount to invoke +mv /srv/bindings/$bid/fusedav.conf.1 /srv/bindings/$bid/fusedav.conf +rm -f /srv/bindings/$bid/fusedav.conf.2 +if [ $verbose -eq 1 ]; then + btool remount srv-bindings-$bid-files.mount +else + btool remount srv-bindings-$bid-files.mount > /dev/null 2>&1 +fi + +if [ $verbose -eq 1 ]; then + endtime=$(date +%s) + elapsedtime=$(( $endtime - $starttime )) + echo "Elapsed time: $elapsedtime" +fi + +if [ $fail -ne 0 ]; then + echo "FAIL: tests failed $fail; files passed $pass" +else + echo "PASS: tests passed $pass" +fi diff --git a/tests/rename.c b/tests/rename.c index c228a8c0..98948de7 100644 --- a/tests/rename.c +++ b/tests/rename.c @@ -84,7 +84,7 @@ int main(int argc, char *argv[]) { int opt; bool fail = false; - while ((opt = getopt (argc, argv, "uvhf:")) != -1) { + while ((opt = getopt (argc, argv, "uvh")) != -1) { switch (opt) { case 'v': diff --git a/tests/urlencode.sh b/tests/urlencode.sh index b0b9435f..535ce924 100755 --- a/tests/urlencode.sh +++ b/tests/urlencode.sh @@ -6,7 +6,9 @@ usage() cat << EOF usage: $0 options -This script runs the command line tests +This script runs the command line tests, but it does so by adding +special characters to the filename and ensuring that they are properly +processed by the backend OPTIONS: -h Show this message diff --git a/tests/write-delete-checknegative.sh b/tests/write-delete-checknegative.sh new file mode 100755 index 00000000..5030f0fe --- /dev/null +++ b/tests/write-delete-checknegative.sh @@ -0,0 +1,215 @@ +#! /bin/bash +set +e + +usage() +{ +cat << EOF +usage: $0 options + +This script tests that files written and deleted create a negative entry in +the stat cache and those written and not deleted don't. + +This script gets the pid of the binding, sends a SIGUSR2 signal which dumps +the stat cache, then calls journalctl to get log messages, and uses their content +to ascertain success or failure. + +OPTIONS: + -h Show this message + -v Verbose + -n Number of iterations. +EOF +} + +iters=16 +verbose=0 + +while getopts "hvn:" OPTION +do + case $OPTION in + h) + usage + exit 1 + ;; + n) + iters=$OPTARG + ;; + v) + verbose=1 + ;; + ?) + usage + exit 1 + ;; + esac +done + +if [ -f ../fusedav.conf ]; then + cd .. +fi + +if [ ! -f fusedav.conf ]; then + echo "ERROR: Need to be in /srv/bindings/ directory: $(pwd)" + exit +fi + +# e.g. /srv/bindings/ +path=$(pwd) +# binding id +bid=${path##*/} +# base name +bn=write-delete-checknegative +# base dir +bd=files/$bn-dir +# base file +bf=$bd/$bn +# output file for journalctl, from which are read results +outfile=/tmp/$bn.out + +if [ $verbose -eq 1 ]; then + starttime=$(date +%s) +fi + +iter=0 + +pass=0 +fail=0 + +##### TEST 1 +# Create a number of iles + +if [ $verbose -eq 1 ]; then + echo "mkdir $bd" +fi + +rm -f $bd/* +rmdir $bd + +mkdir $bd > /dev/null 2>&1 +if [ $? -ne 0 ]; then + echo "Failed to make directory $bd. Exiting..." + exit +fi + +# For journalctl +since=$(date '+%Y-%m-%d %H:%M:%S') + +# Reset the state of the files for the first attempts. +# If this test has already been run and the files still +# exist in the stat cache, the results are invalid +if [ $verbose -eq 1 ]; then + btool invalidate srv-bindings-$bid-files.mount +else + btool invalidate srv-bindings-$bid-files.mount > /dev/null 2>&1 +fi + +# PID of fusedav mount; needed later to send it a signal to dump stat cache +fdpid=$(ps -A -o pid,cmd | grep fusedav | grep $bid | grep fusedav.conf | awk '{print $1}') +if [ $verbose -eq 1 ]; then + echo "PID: $fdpid" +fi + +# Create the files ... +while [ $iter -lt $iters ] +do + if [ $verbose -eq 1 ]; then + echo "$iter: echo $bf-$iter.file > $bf-$iter.file" + fi + + echo "$bf-$iter.file" > $bf-$iter.file + + iter=$(( iter + 1 )) +done + +# Delete some files +iter=0 +while [ $iter -lt $iters ] +do + # Delete all files on iter % 3; do not delete the others + df=$(( iter % 3 )) + if [ $df -eq 0 ]; then + if [ $verbose -eq 1 ]; then + echo "$iter: rm -f $bf-$iter.file" + fi + rm -f $bf-$iter.file + fi + + iter=$(( iter + 1 )) +done + +# Send signal to dump stat cache to journalctl +kill -SIGUSR2 $fdpid + +# Sleep some time to make sure the dump completes +sleep 8 + +if [ $verbose -eq 1 ]; then + echo "journalctl -a -u srv-bindings-$bid-files.mount --since $since --no-pager > $outfile" +fi +journalctl -a -u srv-bindings-$bid-files.mount --since "$since" --no-pager > $outfile + +# Check for positive or negative for files +iter=0 +while [ $iter -lt $iters ] +do + if [ $verbose -eq 1 ]; then + echo "$iter: grep *stat_cache_walk:.*$bn-$iter.file.*positive" $outfile + fi + pn=$(grep "stat_cache_walk:.*$bn-$iter.file.*positive" $outfile) + if [ $? -eq 0 ]; then + pos=1 + else + if [ $verbose -eq 1 ]; then + echo "$iter: grep *stat_cache_walk:.*$bn-$iter.file.*negative" $outfile + fi + pn=$(grep "stat_cache_walk:.*$bn-$iter.file.*negative" $outfile) + if [ $? -eq 0 ]; then + neg=1 + fi + fi + if [ $verbose -eq 1 ]; then + echo "$iter: grep on $bn-$iter.file: $pn" + fi + df=$(( iter % 3 )) + if [ $df -eq 0 ]; then + # Should have been deleted, so we should not expect 'positive' in the grep + if [ $neg ]; then + pass=$((pass + 1)) + if [ $verbose -eq 1 ]; then + echo "Passed on $bn-$iter.file: did not get positive" + fi + else + fail=$((fail + 1)) + if [ $verbose -eq 1 ]; then + echo "Failed on $bn-$iter.file: expected negative, got positive" + fi + fi + else + # Should not have been deleted, so we should expect 'positive' in the grep + if [ $pos ]; then + pass=$((pass + 1)) + if [ $verbose -eq 1 ]; then + echo "Passed on $bn-$iter.file: got positive" + fi + else + fail=$((fail + 1)) + if [ $verbose -eq 1 ]; then + echo "Failed on $bn-$iter.file: expected positive but did not get it" + fi + fi + fi + + iter=$(( iter + 1 )) +done + +#### Clean Up +if [ $verbose -eq 1 ]; then + endtime=$(date +%s) + elapsedtime=$(( $endtime - $starttime )) + echo "Elapsed time: $elapsedtime" +fi + +if [ $fail -ne 0 ]; then + echo "FAIL: files failed $fail; files passed $pass" +else + echo "PASS: files passed $pass" +fi diff --git a/tests/writefiles.sh b/tests/writefiles-create.sh similarity index 83% rename from tests/writefiles.sh rename to tests/writefiles-create.sh index bdc4a1f1..e7a6b685 100755 --- a/tests/writefiles.sh +++ b/tests/writefiles-create.sh @@ -6,7 +6,7 @@ usage() cat << EOF usage: $0 options -This script runs the command line tests +This script creates a lot of files. OPTIONS: -h Show this message @@ -58,18 +58,28 @@ do esac done +# If no bid was passed in, see if we are in a directory where +# we can extract a valid bid if [ $bid == "none" ]; then - echo "-b is required. Exiting ..." - exit + if [ -f ../fusedav.conf ]; then + cd .. + fi + if [ ! -f fusedav.conf ]; then + echo "-b is required. Exiting ..." + exit + fi + curdir=$(pwd) + bid=${curdir##*/} fi + biddir=/srv/bindings/$bid/files if [ $numdirs -eq 0 ]; then - numdirs=100 + numdirs=10 fi if [ $numfiles -eq 0 ]; then - numfiles=1000 + numfiles=100 fi if [ $verbose -eq 1 ]; then diff --git a/tests/writefiles-remove.sh b/tests/writefiles-remove.sh new file mode 100755 index 00000000..e2a6fc46 --- /dev/null +++ b/tests/writefiles-remove.sh @@ -0,0 +1,120 @@ +#! /bin/bash +set +e + +usage() +{ +cat << EOF +usage: $0 options + +This script removes files created with the writefiles-create script + +OPTIONS: + -h Show this message + -b Binding uuid (required) + -f Number of files + -d Number of dirs + -s Start file number + -t Start dir number + -v Verbose +EOF +} + +numfiles=0 +numdirs=0 +verbose=0 +startnum=0 +startdir=0 +bid="none" + +while getopts "hb:d:f:s:t:v" OPTION +do + case $OPTION in + h) + usage + exit 1 + ;; + b) + bid=$OPTARG + ;; + f) + numfiles=$OPTARG + ;; + d) + numdirs=$OPTARG + ;; + s) + startnum=$OPTARG + ;; + t) + startdir=$OPTARG + ;; + v) + verbose=1 + ;; + ?) + usage + exit + ;; + esac +done + +# If no bid was passed in, see if we are in a directory where +# we can extract a valid bid +if [ $bid == "none" ]; then + if [ -f ../fusedav.conf ]; then + cd .. + fi + if [ ! -f fusedav.conf ]; then + echo "-b is required. Exiting ..." + exit + fi + curdir=$(pwd) + bid=${curdir##*/} +fi + +biddir=/srv/bindings/$bid/files + +if [ $numdirs -eq 0 ]; then + numdirs=10 +fi + +if [ $numfiles -eq 0 ]; then + numfiles=100 +fi + +if [ $verbose -eq 1 ]; then + starttime=$(date +%s) +fi + +iters=0 +numdir=1 +while [ $numdir -le $numdirs ] +do + dirnum=$(( $numdir + $startdir )) + dirname=$biddir/dir-$dirnum + + numfile=1 + while [ $numfile -le $numfiles ] + do + filenum=$(( $numfile + $startnum )) + filename=$dirname/file-$filenum + if [ $verbose -eq 1 ]; then + echo "$iters: rm -f $filename" + fi + rm -f $filename + numfile=$(( numfile + 1 )) + iters=$(( iters + 1 )) + done + + if [ $verbose -eq 1 ]; then + echo "$numdir: rmdir $dirname" + fi + rmdir $dirname + numdir=$(( numdir + 1 )) +done + +if [ $verbose -eq 1 ]; then + endtime=$(date +%s) + elapsedtime=$(( $endtime - $starttime )) + echo "Elapsed time: $elapsedtime" +fi