From eb3eb4f25008e9c5b76ac125a1d8c7a7af0480b7 Mon Sep 17 00:00:00 2001 From: Wouter Wijngaards Date: Tue, 1 Sep 2009 12:45:10 +0000 Subject: [PATCH] randomise probe time. git-svn-id: file:///svn/unbound/trunk@1798 be551aaa-1e26-0410-a405-d3ace91eadb9 --- doc/Changelog | 1 + testcode/fake_event.c | 36 +++++++++++++++++--- testcode/replay.c | 67 ++++++++++++++++++++++++++++++------- testcode/replay.h | 15 +++++++-- testdata/autotrust_init.rpl | 9 +++-- validator/autotrust.c | 64 +++++++++++++++++++++++++++++++---- 6 files changed, 165 insertions(+), 27 deletions(-) diff --git a/doc/Changelog b/doc/Changelog index a57a3532c..26568d2f9 100644 --- a/doc/Changelog +++ b/doc/Changelog @@ -1,5 +1,6 @@ 1 September 2009: Wouter - testbound variable arithmetic. + - autotrust probe time is randomised. 31 August 2009: Wouter - testbound variable processing. diff --git a/testcode/fake_event.c b/testcode/fake_event.c index 6ff0f775f..e6a80b970 100644 --- a/testcode/fake_event.c +++ b/testcode/fake_event.c @@ -132,6 +132,7 @@ repevt_string(enum replay_event_type t) case repevt_back_query: return "CHECK_OUT_QUERY"; case repevt_autotrust_check: return "CHECK_AUTOTRUST"; case repevt_error: return "ERROR"; + case repevt_assign: return "ASSIGN"; default: return "UNKNOWN"; } } @@ -439,6 +440,21 @@ fake_pending_callback(struct replay_runtime* runtime, ldns_buffer_free(c.buffer); } +/** pass time */ +static void +moment_assign(struct replay_runtime* runtime, struct replay_moment* mom) +{ + char* value = macro_process(runtime->vars, runtime, mom->string); + if(!value) + fatal_exit("could not process macro step %d", mom->time_step); + log_info("assign %s = %s", mom->variable, value); + if(!macro_assign(runtime->vars, mom->variable, value)) + fatal_exit("out of memory storing macro"); + free(value); + if(verbosity >= VERB_ALGO) + macro_print_debug(runtime->vars); +} + /** pass time */ static void time_passes(struct replay_runtime* runtime, struct replay_moment* mom) @@ -462,11 +478,12 @@ time_passes(struct replay_runtime* runtime, struct replay_moment* mom) /** check autotrust file contents */ static void -autotrust_check(struct replay_moment* mom) +autotrust_check(struct replay_runtime* runtime, struct replay_moment* mom) { char name[1024], line[1024]; FILE *in; int lineno = 0, oke=1; + char* expanded; struct config_strlist* p; line[sizeof(line)-1] = 0; log_assert(mom->autotrust_id); @@ -482,13 +499,20 @@ autotrust_check(struct replay_moment* mom) fatal_exit("autotrust_check failed"); } if(line[0]) line[strlen(line)-1] = 0; /* remove newline */ - if(strcmp(p->str, line) != 0) { + expanded = macro_process(runtime->vars, runtime, p->str); + if(!expanded) + fatal_exit("could not expand macro line %d", lineno); + if(verbosity >= VERB_ALGO && strcmp(p->str, expanded) != 0) + log_info("expanded '%s' to '%s'", p->str, expanded); + if(strcmp(expanded, line) != 0) { log_err("mismatch in file %s, line %d", name, lineno); log_err("file has : %s", line); - log_err("should be: %s", p->str); + log_err("should be: %s", expanded); + free(expanded); oke = 0; continue; } + free(expanded); fprintf(stderr, "%s:%2d ok : %s\n", name, lineno, line); } if(fgets(line, (int)sizeof(line)-1, in)) { @@ -573,7 +597,11 @@ do_moment_and_advance(struct replay_runtime* runtime) advance_moment(runtime); break; case repevt_autotrust_check: - autotrust_check(runtime->now); + autotrust_check(runtime, runtime->now); + advance_moment(runtime); + break; + case repevt_assign: + moment_assign(runtime, runtime->now); advance_moment(runtime); break; default: diff --git a/testcode/replay.c b/testcode/replay.c index 933c0cc53..f620f4f11 100644 --- a/testcode/replay.c +++ b/testcode/replay.c @@ -103,6 +103,8 @@ replay_moment_delete(struct replay_moment* mom) delete_entry(mom->match); } free(mom->autotrust_id); + free(mom->string); + free(mom->variable); config_delstrlist(mom->file_content); free(mom); } @@ -229,6 +231,26 @@ read_file_content(FILE* in, int* lineno, struct replay_moment* mom) fatal_exit("no FILE_END in input file"); } +/** read assign step info */ +static void +read_assign_step(char* remain, struct replay_moment* mom) +{ + char buf[1024]; + char eq; + int skip; + buf[sizeof(buf)-1]=0; + if(sscanf(remain, " %1023s %c %n", buf, &eq, &skip) != 2) + fatal_exit("cannot parse assign: %s", remain); + mom->variable = strdup(buf); + if(eq != '=') + fatal_exit("no = in assign: %s", remain); + remain += skip; + if(remain[0]) remain[strlen(remain)-1]=0; /* remove newline */ + mom->string = strdup(remain); + if(!mom->variable || !mom->string) + fatal_exit("out of memory"); +} + /** * Read a replay moment 'STEP' from file. * @param remain: Rest of line (after STEP keyword). @@ -286,9 +308,13 @@ replay_moment_read(char* remain, FILE* in, const char* name, int* lineno, if(strlen(remain)>0 && remain[strlen(remain)-1]=='\n') remain[strlen(remain)-1] = 0; mom->autotrust_id = strdup(remain); + if(!mom->autotrust_id) fatal_exit("out of memory"); read_file_content(in, lineno, mom); } else if(parse_keyword(&remain, "ERROR")) { mom->evt_type = repevt_error; + } else if(parse_keyword(&remain, "ASSIGN")) { + mom->evt_type = repevt_assign; + read_assign_step(remain, mom); } else { log_err("%d: unknown event type %s", *lineno, remain); free(mom); @@ -449,23 +475,30 @@ replay_scenario_delete(struct replay_scenario* scen) free(scen); } -struct fake_timer* -replay_get_oldest_timer(struct replay_runtime* runtime) +static struct fake_timer* +first_timer(struct replay_runtime* runtime) { struct fake_timer* p, *res = NULL; for(p=runtime->timer_list; p; p=p->next) { if(!p->enabled) continue; - if(timeval_smaller(&p->tv, &runtime->now_tv)) { - if(!res) - res = p; - else if(timeval_smaller(&p->tv, &res->tv)) - res = p; - } + if(!res) + res = p; + else if(timeval_smaller(&p->tv, &res->tv)) + res = p; } return res; } +struct fake_timer* +replay_get_oldest_timer(struct replay_runtime* runtime) +{ + struct fake_timer* t = first_timer(runtime); + if(t && timeval_smaller(&t->tv, &runtime->now_tv)) + return t; + return NULL; +} + int replay_var_compare(const void* a, const void* b) { @@ -668,7 +701,7 @@ do_macro_arith(char* at, size_t remain, char** arithstart) } /* put result back in buffer */ - snprintf(buf, sizeof(buf), "%g", result); + snprintf(buf, sizeof(buf), "%.12g", result); if(!do_buf_insert(at, remain, at+skip, buf)) return NULL; @@ -694,13 +727,15 @@ macro_expand(rbtree_t* store, struct replay_runtime* runtime, char** text) /* check for functions */ if(strcmp(buf, "time") == 0) { snprintf(buf, sizeof(buf), "%u", (unsigned)runtime->now_secs); + *text += len; return strdup(buf); } else if(strcmp(buf, "timeout") == 0) { uint32_t res = 0; - struct fake_timer* t = replay_get_oldest_timer(runtime); - if(t && (uint32_t)t->tv.tv_sec <= runtime->now_secs) - res = runtime->now_secs - (uint32_t)t->tv.tv_sec; + struct fake_timer* t = first_timer(runtime); + if(t && (uint32_t)t->tv.tv_sec >= runtime->now_secs) + res = (uint32_t)t->tv.tv_sec - runtime->now_secs; snprintf(buf, sizeof(buf), "%u", (unsigned)res); + *text += len; return strdup(buf); } else if(strncmp(buf, "ctime ", 6) == 0 || strncmp(buf, "ctime\t", 6) == 0) { @@ -773,6 +808,14 @@ macro_lookup(rbtree_t* store, char* name) return strdup(x->value); } +void macro_print_debug(rbtree_t* store) +{ + struct replay_var* x; + RBTREE_FOR(x, struct replay_var*, store) { + log_info("%s = %s", x->name, x->value); + } +} + int macro_assign(rbtree_t* store, char* name, char* value) { diff --git a/testcode/replay.h b/testcode/replay.h index 9390b6d3e..4237643ce 100644 --- a/testcode/replay.h +++ b/testcode/replay.h @@ -70,13 +70,14 @@ * o TIME_PASSES ELAPSE [seconds] - increase 'now' time counter, can be * a floating point number. * o CHECK_AUTOTRUST [id] - followed by FILE_BEGIN [to match] FILE_END. + * The file contents is macro expanded before match. * o ERROR * ; following entry starts on the next line, ENTRY_BEGIN. * ; more STEP items * SCENARIO_END * * Calculations, a macro-like system: ${$myvar + 3600} - * STEP 10 ASSIGN $myvar = 3600 + * STEP 10 ASSIGN myvar = 3600 * ; ASSIGN event. '=' is syntactic sugar here. 3600 is some expression. * ${..} is macro expanded from its expression. Text substitution. * o $var replaced with its value. var is identifier [azAZ09_]* @@ -183,7 +184,9 @@ struct replay_moment { /** check autotrust key file */ repevt_autotrust_check, /** an error happens to outbound query */ - repevt_error + repevt_error, + /** assignment to a variable */ + repevt_assign } /** variable with what is to happen this moment */ evt_type; @@ -205,6 +208,11 @@ struct replay_moment { */ ldns_rr* qname; + /** macro name, for assign. */ + char* variable; + /** string argument, for assign. */ + char* string; + /** the autotrust file id to check */ char* autotrust_id; /** file contents to match, one string per line */ @@ -420,6 +428,9 @@ char* macro_lookup(rbtree_t* store, char* name); */ int macro_assign(rbtree_t* store, char* name, char* value); +/** Print macro variables stored as debug info */ +void macro_print_debug(rbtree_t* store); + /** testbounds self test */ void testbound_selftest(void); diff --git a/testdata/autotrust_init.rpl b/testdata/autotrust_init.rpl index 3663a9b65..56a93fab1 100644 --- a/testdata/autotrust_init.rpl +++ b/testdata/autotrust_init.rpl @@ -98,15 +98,18 @@ RANGE_END ; set date/time to Aug 24 09:46:40 (2009). STEP 5 TIME_PASSES ELAPSE 1251100000 +STEP 6 ASSIGN t0 = ${time} +STEP 7 ASSIGN probe = ${timeout} + ; the auto probing should have been done now. -STEP 7 CHECK_AUTOTRUST example.com +STEP 8 CHECK_AUTOTRUST example.com FILE_BEGIN ; autotrust trust anchor file ;;id: example.com. 1 ;;last_queried: 1251100000 ;;Mon Aug 24 09:46:40 2009 ;;last_success: 1251100000 ;;Mon Aug 24 09:46:40 2009 -;;next_probe_time: 1251105400 ;;Mon Aug 24 11:16:40 2009 +;;next_probe_time: ${$t0 + $probe} ;;${ctime $t0 + $probe} ;;query_failed: 0 ;;query_interval: 5400 ;;retry_time: 3600 @@ -146,7 +149,7 @@ FILE_BEGIN ;;id: example.com. 1 ;;last_queried: 1251100000 ;;Mon Aug 24 09:46:40 2009 ;;last_success: 1251100000 ;;Mon Aug 24 09:46:40 2009 -;;next_probe_time: 1251105400 ;;Mon Aug 24 11:16:40 2009 +;;next_probe_time: ${$t0 + $probe} ;;${ctime $t0 + $probe} ;;query_failed: 0 ;;query_interval: 5400 ;;retry_time: 3600 diff --git a/validator/autotrust.c b/validator/autotrust.c index cb14c0920..5e8e5ee6f 100644 --- a/validator/autotrust.c +++ b/validator/autotrust.c @@ -54,6 +54,7 @@ #include "util/random.h" #include "util/data/msgparse.h" #include "services/mesh.h" +#include "daemon/worker.h" /** number of times a key must be seen before it can become valid */ #define MIN_PENDINGCOUNT 2 @@ -1446,10 +1447,41 @@ autr_cleanup_keys(struct trust_anchor* tp) static time_t calc_next_probe(struct module_env* env, uint32_t wait) { - /* TODO (how test?) make it random, 90-100% */ + /* make it random, 90-100% */ + uint32_t rnd, rest; if(wait < 3600) wait = 3600; - return (time_t)(*env->now + wait); + rnd = wait/10; + rest = wait-rnd; + rnd = (uint32_t)ub_random(env->rnd) % rnd; + return (time_t)(*env->now + rest + rnd); +} + +/** what is first probe time (anchors must be locked) */ +static time_t +wait_probe_time(struct val_anchors* anchors) +{ + rbnode_t* t = rbtree_first(&anchors->autr->probe); + if(t) return ((struct trust_anchor*)t->key)->autr->next_probe_time; + return 0; +} + +/** reset worker timer */ +static void +reset_worker_timer(struct module_env* env) +{ + struct worker* worker = env->worker; + struct timeval tv; + uint32_t next = (uint32_t)wait_probe_time(env->anchors); + /* in case this is libunbound, no timer */ + if(!worker || !worker->probe_timer) + return; + if(next > *env->now) + tv.tv_sec = (time_t)(next - *env->now); + else tv.tv_sec = 0; + tv.tv_usec = 0; + comm_timer_set(worker->probe_timer, &tv); + verbose(VERB_ALGO, "scheduled next probe in %d sec", (int)tv.tv_sec); } /** set next probe for trust anchor */ @@ -1458,6 +1490,7 @@ set_next_probe(struct module_env* env, struct trust_anchor* tp, struct ub_packed_rrset_key* dnskey_rrset) { struct trust_anchor key, *tp2; + time_t mold, mnew; /* use memory allocated in rrset for temporary name storage */ key.node.key = &key; key.name = dnskey_rrset->rk.dname; @@ -1478,14 +1511,19 @@ set_next_probe(struct module_env* env, struct trust_anchor* tp, lock_basic_lock(&tp->lock); /* schedule */ + mold = wait_probe_time(env->anchors); (void)rbtree_delete(&env->anchors->autr->probe, tp); tp->autr->next_probe_time = calc_next_probe(env, tp->autr->query_interval); (void)rbtree_insert(&env->anchors->autr->probe, &tp->autr->pnode); + mnew = wait_probe_time(env->anchors); lock_basic_unlock(&env->anchors->lock); verbose(VERB_ALGO, "next probe set in %d seconds", (int)tp->autr->next_probe_time - (int)*env->now); + if(mold != mnew) { + reset_worker_timer(env); + } return 1; } @@ -1495,6 +1533,7 @@ autr_tp_remove(struct module_env* env, struct trust_anchor* tp) { struct trust_anchor key; struct autr_point_data pd; + time_t mold, mnew; /* save name */ memset(&key, 0, sizeof(key)); memset(&pd, 0, sizeof(pd)); @@ -1518,11 +1557,16 @@ autr_tp_remove(struct module_env* env, struct trust_anchor* tp) /* take from tree. It could be deleted by someone else. */ lock_basic_lock(&env->anchors->lock); (void)rbtree_delete(env->anchors->tree, &key); + mold = wait_probe_time(env->anchors); (void)rbtree_delete(&env->anchors->autr->probe, &key); + mnew = wait_probe_time(env->anchors); anchors_init_parents_locked(env->anchors); lock_basic_unlock(&env->anchors->lock); /* delete */ autr_point_delete(tp); + if(mold != mnew) { + reset_worker_timer(env); + } } int autr_process_prime(struct module_env* env, struct val_env* ve, @@ -1684,14 +1728,22 @@ autr_debug_print(struct val_anchors* anchors) lock_basic_unlock(&anchors->lock); } -void probe_answer_cb(void* ATTR_UNUSED(arg), int ATTR_UNUSED(rcode), +void probe_answer_cb(void* arg, int ATTR_UNUSED(rcode), ldns_buffer* ATTR_UNUSED(buf), enum sec_status ATTR_UNUSED(sec)) { /* retry was set before the query was done, - * re-querytime is set when query succeeded. - * So, nothing to do now. */ - /*struct module_env* env = (struct module_env*)arg;*/ + * re-querytime is set when query succeeded, but that may not + * have reset this timer because the query could have been + * handled by another thread. In that case, this callback would + * get called after the original timeout is done. + * By not resetting the timer, it may probe more often, but not + * less often. + * Unless the new lookup resulted in smaller TTLs and thus smaller + * timeout values. In that case one old TTL could be mistakenly done. + */ + struct module_env* env = (struct module_env*)arg; verbose(VERB_ALGO, "autotrust probe answer cb"); + reset_worker_timer(env); } /** probe a trust anchor DNSKEY and unlocks tp */ -- 2.47.3