From: Wouter Wijngaards Date: Thu, 7 Jun 2007 13:21:04 +0000 (+0000) Subject: Tested serval targets, with CNAME's and indirection for recursion and X-Git-Tag: release-0.4~92 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=019816dcf1c599f502ff411890be70605f9770c3;p=thirdparty%2Funbound.git Tested serval targets, with CNAME's and indirection for recursion and slumber list. git-svn-id: file:///svn/unbound/trunk@374 be551aaa-1e26-0410-a405-d3ace91eadb9 --- diff --git a/daemon/worker.c b/daemon/worker.c index de30e0daa..d75190f5c 100644 --- a/daemon/worker.c +++ b/daemon/worker.c @@ -132,9 +132,7 @@ qstate_free(struct worker* worker, struct module_qstate* qstate) module_subreq_remove(&qstate->subquery_first, s); s->parent = NULL; s->work_info = NULL; - s->subquery_next = worker->slumber_list; - s->subquery_prev = NULL; - worker->slumber_list = s; + module_subreq_insert(&worker->slumber_list, s); } verbose(VERB_ALGO, "worker: slumber list has %d entries", module_subreq_num(worker->slumber_list)); @@ -223,7 +221,8 @@ run_debug(struct module_qstate* p, int d) } buf[i++] = 'o'; buf[i] = 0; - log_nametypeclass(buf, p->qinfo.qname, p->qinfo.qtype, p->qinfo.qclass); + log_nametypeclass(VERB_ALGO, buf, p->qinfo.qname, p->qinfo.qtype, + p->qinfo.qclass); for(p = p->subquery_first; p; p = p->subquery_next) { run_debug(p, d+1); } @@ -248,7 +247,7 @@ static struct module_qstate* find_runnable(struct module_qstate* subq) { struct module_qstate* p = subq; - log_info("find runnable"); + verbose(VERB_ALGO, "find runnable"); if(p->subquery_next && p->subquery_next->ext_state[ p->subquery_next->curmod] == module_state_initial) return p->subquery_next; @@ -266,6 +265,7 @@ worker_process_query(struct worker* worker, struct work_query* w, struct outbound_entry* entry) { enum module_ext_state s; + verbose(VERB_DETAIL, "worker process handle event"); if(event == module_event_new) { qstate->curmod = 0; set_extstates_initial(worker, qstate); @@ -278,19 +278,27 @@ worker_process_query(struct worker* worker, struct work_query* w, region_free_all(worker->scratchpad); qstate->reply = NULL; s = qstate->ext_state[qstate->curmod]; - log_info("worker_process_query: module exit state is %s", - strextstate(s)); + verbose(VERB_ALGO, "worker_process_query: module " + "exit state is %s", strextstate(s)); + if(s == module_state_initial) { + log_err("module exit in initial state, " + "it loops; aborted"); + s = module_error; + } /* examine results, start further modules, etc. */ - if(s == module_wait_subquery) { - if(!qstate->subquery_first) { + if(s != module_error && s != module_finished) { + /* see if we can continue with other subrequests */ + struct module_qstate* nxt = find_runnable(qstate); + if(s == module_wait_subquery && !nxt) { log_err("module exit wait subq, but no subq"); s = module_error; - } else { + } + if(nxt) { /* start submodule */ - qstate = qstate->subquery_first; + qstate = nxt; set_extstates_initial(worker, qstate); - event = module_event_pass; entry = NULL; + event = module_event_pass; continue; } } @@ -312,16 +320,6 @@ worker_process_query(struct worker* worker, struct work_query* w, event = module_event_subq_done; continue; } - if(s != module_error && s != module_finished) { - /* see if we can continue with other subrequests */ - struct module_qstate* nxt = find_runnable(qstate); - if(nxt) { - qstate = nxt; - entry = NULL; - event = module_event_pass; - continue; - } - } break; } /* request done */ @@ -330,6 +328,7 @@ worker_process_query(struct worker* worker, struct work_query* w, replyerror(LDNS_RCODE_SERVFAIL, w); } qstate_free(worker, qstate); + verbose(VERB_DETAIL, "worker process suspend"); return; } if(s == module_finished) { @@ -340,9 +339,11 @@ worker_process_query(struct worker* worker, struct work_query* w, req_release(w); } qstate_free(worker, qstate); + verbose(VERB_DETAIL, "worker process suspend"); return; } /* suspend, waits for wakeup callback */ + verbose(VERB_DETAIL, "worker process suspend"); } /** process incoming replies from the network */ @@ -571,7 +572,7 @@ worker_handle_request(struct comm_point* c, void* arg, int error, edns.udp_size = 65535; /* max size for TCP replies */ if((e=slabhash_lookup(worker->env.msg_cache, h, &qinfo, 0))) { /* answer from cache - we have acquired a readlock on it */ - log_info("answer from the cache"); + verbose(VERB_DETAIL, "answer from the cache"); if(answer_from_cache(worker, e, *(uint16_t*)ldns_buffer_begin(c->buffer), ldns_buffer_read_u16_at(c->buffer, 2), repinfo, @@ -579,7 +580,7 @@ worker_handle_request(struct comm_point* c, void* arg, int error, lock_rw_unlock(&e->lock); return 1; } - log_info("answer from the cache -- data has timed out"); + verbose(VERB_DETAIL, "answer from the cache -- data has timed out"); lock_rw_unlock(&e->lock); } ldns_buffer_rewind(c->buffer); @@ -706,6 +707,7 @@ reqs_init(struct worker* worker) return 0; } q->state.env = &worker->env; + q->state.parent = NULL; q->state.work_info = q; q->next = worker->free_queries; worker->free_queries = q; diff --git a/doc/Changelog b/doc/Changelog index 4a4acf9d1..fadc70289 100644 --- a/doc/Changelog +++ b/doc/Changelog @@ -4,6 +4,13 @@ - nicer printout of outgoing port selection. - fixup cname target readout. - nicer debug output. + - fixup rrset counts when prepending CNAMEs to the answer. + - fixup rrset TTL for prepended CNAMEs. + - process better check for looping modules, and which submodule to + run next. + - subreq insertion code fixup for slumber list. + - VERB_DETAIL, verbosity: 2 level gives short but readable output. + VERB_ALGO, verbosity: 3 gives extensive output. 5 June 2007: Wouter - iterator state finished. diff --git a/iterator/iter_delegpt.c b/iterator/iter_delegpt.c index db907946e..e27328d4b 100644 --- a/iterator/iter_delegpt.c +++ b/iterator/iter_delegpt.c @@ -148,23 +148,65 @@ delegpt_add_addr(struct delegpt* dp, struct region* region, return 1; } +/** count NS and number missing */ +static void +delegpt_count_ns(struct delegpt* dp, size_t* numns, size_t* missing) +{ + struct delegpt_ns* ns; + *numns = 0; + *missing = 0; + for(ns = dp->nslist; ns; ns = ns->next) { + (*numns)++; + if(!ns->resolved) + (*missing)++; + } +} + +/** count addresses, and number in result and available lists */ +static void +delegpt_count_addr(struct delegpt* dp, size_t* numaddr, size_t* numres, + size_t* numavail) +{ + struct delegpt_addr* a; + *numaddr = 0; + *numres = 0; + *numavail = 0; + for(a = dp->target_list; a; a = a->next_target) { + (*numaddr)++; + } + for(a = dp->result_list; a; a = a->next_result) { + (*numres)++; + } + for(a = dp->usable_list; a; a = a->next_usable) { + (*numavail)++; + } +} + void delegpt_log(struct delegpt* dp) { char buf[LDNS_MAX_DOMAINLEN+1]; struct delegpt_ns* ns; struct delegpt_addr* a; + size_t missing=0, numns=0, numaddr=0, numres=0, numavail=0; dname_str(dp->name, buf); if(dp->nslist == NULL && dp->target_list == NULL) { log_info("DelegationPoint<%s>: empty", buf); return; } - log_info("DelegationPoint<%s>:", buf); - for(ns = dp->nslist; ns; ns = ns->next) { - dname_str(ns->name, buf); - log_info(" %s%s", buf, (ns->resolved?"*":"")); - } - for(a = dp->target_list; a; a = a->next_target) { - log_addr(" ", &a->addr, a->addrlen); + delegpt_count_ns(dp, &numns, &missing); + delegpt_count_addr(dp, &numaddr, &numres, &numavail); + log_info("DelegationPoint<%s>: %u names (%u missing), " + "%u addrs (%u result, %u avail)", + buf, (unsigned)numns, (unsigned)missing, + (unsigned)numaddr, (unsigned)numres, (unsigned)numavail); + if(verbosity >= VERB_ALGO) { + for(ns = dp->nslist; ns; ns = ns->next) { + dname_str(ns->name, buf); + log_info(" %s%s", buf, (ns->resolved?"*":"")); + } + for(a = dp->target_list; a; a = a->next_target) { + log_addr(" ", &a->addr, a->addrlen); + } } } @@ -286,8 +328,6 @@ delegpt_add_rrset_A(struct delegpt* dp, struct region* region, if(d->rr_len[i] != 2 + INET_SIZE) continue; memmove(&sa.sin_addr, d->rr_data[i]+2, INET_SIZE); - log_addr("adding A to deleg", (struct sockaddr_storage*)&sa, - len); if(!delegpt_add_target(dp, region, ak->rk.dname, ak->rk.dname_len, (struct sockaddr_storage*)&sa, len)) @@ -311,7 +351,6 @@ delegpt_add_rrset_AAAA(struct delegpt* dp, struct region* region, if(d->rr_len[i] != 2 + INET6_SIZE) /* rdatalen + len of IP6 */ continue; memmove(&sa.sin6_addr, d->rr_data[i]+2, INET6_SIZE); - log_addr("adding AAAA to deleg", (struct sockaddr_storage*)&sa, len); if(!delegpt_add_target(dp, region, ak->rk.dname, ak->rk.dname_len, (struct sockaddr_storage*)&sa, len)) diff --git a/iterator/iter_resptype.c b/iterator/iter_resptype.c index a5c15850b..fc2d7031b 100644 --- a/iterator/iter_resptype.c +++ b/iterator/iter_resptype.c @@ -159,9 +159,7 @@ response_type_from_server(struct dns_msg* msg, struct query_info* request, * it is relevant. */ if(ntohs(s->rk.type) == LDNS_RR_TYPE_CNAME && query_dname_compare(mname, s->rk.dname) == 0) { - log_nametypeclass("following CNAME from", mname, LDNS_RR_TYPE_CNAME, request->qclass); get_cname_target(s, &mname, &mname_len); - log_nametypeclass("following CNAME to", mname, request->qtype, request->qclass); } } /* if we encountered a CNAME (or a bunch of CNAMEs), and diff --git a/iterator/iter_scrub.c b/iterator/iter_scrub.c index 3ae248f78..3346ca701 100644 --- a/iterator/iter_scrub.c +++ b/iterator/iter_scrub.c @@ -56,11 +56,11 @@ static void remove_rrset(const char* str, ldns_buffer* pkt, struct msg_parse* msg, struct rrset_parse* prev, struct rrset_parse** rrset) { - if(verbosity >= VERB_ALGO + if(verbosity >= VERB_DETAIL && (*rrset)->dname_len <= LDNS_MAX_DOMAINLEN) { uint8_t buf[LDNS_MAX_DOMAINLEN+1]; dname_pkt_copy(pkt, buf, (*rrset)->dname); - log_nametypeclass(str, buf, + log_nametypeclass(VERB_DETAIL, str, buf, (*rrset)->type, ntohs((*rrset)->rrset_class)); } if(prev) @@ -453,7 +453,6 @@ scrub_sanitize(ldns_buffer* pkt, struct msg_parse* msg, uint8_t* zonename) struct rrset_parse* rrset, *prev; prev = NULL; rrset = msg->rrset_first; - log_nametypeclass("sanitize for", zonename, 0, 0); /* At this point, we brutally remove ALL rrsets that aren't * children of the originating zone. The idea here is that, @@ -486,12 +485,9 @@ int scrub_message(ldns_buffer* pkt, struct msg_parse* msg, struct query_info* qinfo, uint8_t* zonename, struct region* region) { - /* things to check: - * if qdcount > 0 : qinfo. - * from normalize() from NSclient. - * from sanitize() from iterator. - */ /* basic sanity checks */ + log_nametypeclass(VERB_ALGO, "scrub for", zonename, LDNS_RR_TYPE_NS, + qinfo->qclass); if(msg->qdcount > 1) return 0; if( !(msg->flags&BIT_QR) ) diff --git a/iterator/iter_utils.c b/iterator/iter_utils.c index 94fb6ec98..64ae6f918 100644 --- a/iterator/iter_utils.c +++ b/iterator/iter_utils.c @@ -247,14 +247,10 @@ iter_dns_store(struct module_env* env, struct dns_msg* msg, int is_referral) /* store rrsets */ struct rrset_ref ref; uint32_t now = time(NULL); - size_t i, j; + size_t i; for(i=0; irrset_count; i++) { - /* fixup rrset ttl */ - struct packed_rrset_data* data = (struct - packed_rrset_data*)rep->rrsets[i]->entry.data; - data->ttl += now; - for(j=0; jcount + data->rrsig_count; j++) - data->rr_ttl[j] += now; + packed_rrset_ttl_add((struct packed_rrset_data*) + rep->rrsets[i]->entry.data, now); ref.key = rep->rrsets[i]; ref.id = rep->rrsets[i]->id; /*ignore ret: it was in the cache, ref updated */ diff --git a/iterator/iterator.c b/iterator/iterator.c index ab70664c9..6ab1de975 100644 --- a/iterator/iterator.c +++ b/iterator/iterator.c @@ -254,7 +254,8 @@ static int error_response(struct module_qstate* qstate, int id, int rcode) { struct iter_qstate* iq = (struct iter_qstate*)qstate->minfo[id]; - log_info("err response %s", ldns_lookup_by_id(ldns_rcodes, rcode)? + verbose(VERB_DETAIL, "return error response %s", + ldns_lookup_by_id(ldns_rcodes, rcode)? ldns_lookup_by_id(ldns_rcodes, rcode)->name:"??"); if(iq && iq->orig_qname) { /* encode original query */ @@ -293,6 +294,7 @@ iter_prepend(struct iter_qstate* iq, struct dns_msg* msg, num++; if(num == 0) return 1; + verbose(VERB_ALGO, "prepending %d rrsets", (int)num); sets = region_alloc(region, (num+msg->rep->rrset_count) * sizeof(struct ub_packed_rrset_key*)); if(!sets) @@ -303,6 +305,8 @@ iter_prepend(struct iter_qstate* iq, struct dns_msg* msg, for(p = iq->prepend_list; p; p = p->next) { sets[num++] = p->rrset; } + msg->rep->rrset_count += num; + msg->rep->an_numrrsets += num; msg->rep->rrsets = sets; return 1; } @@ -320,7 +324,6 @@ iter_encode_respmsg(struct module_qstate* qstate, struct iter_qstate* iq, struct dns_msg* msg, int id) { struct query_info qinf = qstate->qinfo; - uint32_t now = time(NULL); struct edns_data edns; if(iq->orig_qname) { qinf.qname = iq->orig_qname; @@ -340,7 +343,7 @@ iter_encode_respmsg(struct module_qstate* qstate, struct iter_qstate* iq, edns.ext_rcode = 0; edns.bits = qstate->edns.bits & EDNS_DO; if(!reply_info_answer_encode(&qinf, msg->rep, 0, iq->orig_qflags, - qstate->buf, now, 1, qstate->scratch, qstate->edns.udp_size, + qstate->buf, 0, 1, qstate->scratch, qstate->edns.udp_size, &edns)) { /* encode servfail */ error_response(qstate, id, LDNS_RCODE_SERVFAIL); @@ -486,11 +489,7 @@ generate_sub_request(uint8_t* qname, size_t qnamelen, uint16_t qtype, subq->env = qstate->env; subq->work_info = qstate->work_info; subq->parent = qstate; - if(qstate->subquery_first) - qstate->subquery_first->subquery_prev = subq; - subq->subquery_next = qstate->subquery_first; - subq->subquery_prev = NULL; - qstate->subquery_first = subq; + module_subreq_insert(&qstate->subquery_first, subq); subiq = (struct iter_qstate*)subq->minfo[id]; memset(subiq, 0, sizeof(*subiq)); @@ -583,8 +582,8 @@ prime_stub(struct module_qstate* qstate, struct iter_qstate* iq, return 0; /* Otherwise, we need to (re)prime the stub. */ - log_nametypeclass("priming stub", stub_dp->name, LDNS_RR_TYPE_NS, - qclass); + log_nametypeclass(VERB_DETAIL, "priming stub", stub_dp->name, + LDNS_RR_TYPE_NS, qclass); /* Stub priming events start at the QUERYTARGETS state to avoid the * redundant INIT state processing. */ @@ -637,7 +636,7 @@ processInitRequest(struct module_qstate* qstate, struct iter_qstate* iq, size_t delnamelen; struct dns_msg* msg; - log_nametypeclass("resolving", qstate->qinfo.qname, + log_nametypeclass(VERB_DETAIL, "resolving", qstate->qinfo.qname, qstate->qinfo.qtype, qstate->qinfo.qclass); /* check effort */ @@ -673,6 +672,7 @@ processInitRequest(struct module_qstate* qstate, struct iter_qstate* iq, /* handle positive cache response */ enum response_type type = response_type_from_cache(msg, &qstate->qinfo); + log_dns_msg("msg from cache lookup", &msg->qinfo, msg->rep); if(type == RESPONSE_TYPE_CNAME) { uint8_t* sname = 0; @@ -797,8 +797,8 @@ static int processInitRequest2(struct module_qstate* qstate, struct iter_qstate* iq, struct iter_env* ie, int id) { - log_nametypeclass("resolving (init part 2): ", qstate->qinfo.qname, - qstate->qinfo.qtype, qstate->qinfo.qclass); + log_nametypeclass(VERB_DETAIL, "resolving (init part 2): ", + qstate->qinfo.qname, qstate->qinfo.qtype, qstate->qinfo.qclass); /* Check to see if we need to prime a stub zone. */ if(prime_stub(qstate, iq, ie, id, qstate->qinfo.qname, @@ -824,8 +824,8 @@ processInitRequest2(struct module_qstate* qstate, struct iter_qstate* iq, static int processInitRequest3(struct module_qstate* qstate, struct iter_qstate* iq) { - log_nametypeclass("resolving (init part 3): ", qstate->qinfo.qname, - qstate->qinfo.qtype, qstate->qinfo.qclass); + log_nametypeclass(VERB_DETAIL, "resolving (init part 3): ", + qstate->qinfo.qname, qstate->qinfo.qtype, qstate->qinfo.qclass); /* If the RD flag wasn't set, then we just finish with the * cached referral as the response. */ if(!(qstate->query_flags & BIT_RD)) { @@ -872,7 +872,7 @@ generate_target_query(struct module_qstate* qstate, struct iter_qstate* iq, free(subq); return 0; } - log_nametypeclass("new target", name, qtype, qclass); + log_nametypeclass(VERB_DETAIL, "new target", name, qtype, qclass); delegpt_log(subiq->dp); return 1; } @@ -915,8 +915,8 @@ query_for_targets(struct module_qstate* qstate, struct iter_qstate* iq, * FIXME: at this point, this *may* be resolvable, so * perhaps we should issue the query anyway and let it fail.*/ if(dname_subdomain_c(ns->name, iq->dp->name)) { - log_nametypeclass("skipping target name because " - "it should have been glue", ns->name, + log_nametypeclass(VERB_DETAIL, "skipping target name " + "because it should have been glue", ns->name, LDNS_RR_TYPE_NS, qstate->qinfo.qclass); continue; } @@ -945,6 +945,8 @@ query_for_targets(struct module_qstate* qstate, struct iter_qstate* iq, break; } *num = query_count; + if(query_count > 0) + qstate->ext_state[id] = module_wait_subquery; return 1; } @@ -977,8 +979,8 @@ processQueryTargets(struct module_qstate* qstate, struct iter_qstate* iq, * needs to send a query to. That is, at least one per referral, * more if some targets timeout or return throwaway answers. */ - log_nametypeclass("processQueryTargets:", qstate->qinfo.qname, - qstate->qinfo.qtype, qstate->qinfo.qclass); + log_nametypeclass(VERB_DETAIL, "processQueryTargets:", + qstate->qinfo.qname, qstate->qinfo.qtype, qstate->qinfo.qclass); verbose(VERB_ALGO, "processQueryTargets: targetqueries %d, " "currentqueries %d", iq->num_target_queries, iq->num_current_queries); @@ -986,7 +988,7 @@ processQueryTargets(struct module_qstate* qstate, struct iter_qstate* iq, /* Make sure that we haven't run away */ /* FIXME: is this check even necessary? */ if(iq->referral_count > MAX_REFERRAL_COUNT) { - verbose(VERB_ALGO, "request has exceeded the maximum " + verbose(VERB_DETAIL, "request has exceeded the maximum " "number of referrrals with %d", iq->referral_count); return error_response(qstate, id, LDNS_RCODE_SERVFAIL); } @@ -1044,7 +1046,7 @@ processQueryTargets(struct module_qstate* qstate, struct iter_qstate* iq, /* Since a target query might have been made, we * need to check again. */ if(iq->num_target_queries == 0) { - verbose(VERB_ALGO, "out of query targets -- " + verbose(VERB_DETAIL, "out of query targets -- " "returning SERVFAIL"); /* fail -- no more targets, no more hope * of targets, no hope of a response. */ @@ -1071,9 +1073,10 @@ processQueryTargets(struct module_qstate* qstate, struct iter_qstate* iq, } /* We have a valid target. */ - log_nametypeclass("sending query:", qstate->qinfo.qname, + log_nametypeclass(VERB_DETAIL, "sending query:", qstate->qinfo.qname, qstate->qinfo.qtype, qstate->qinfo.qclass); - log_addr("sending to target:", &target->addr, target->addrlen); + log_name_addr(VERB_DETAIL, "sending to target:", iq->dp->name, + &target->addr, target->addrlen); outq = (*qstate->env->send_query)( qstate->qinfo.qname, qstate->qinfo.qname_len, qstate->qinfo.qtype, qstate->qinfo.qclass, @@ -1118,7 +1121,7 @@ processQueryResponse(struct module_qstate* qstate, struct iter_qstate* iq, if(type == RESPONSE_TYPE_ANSWER) { /* ANSWER type responses terminate the query algorithm, * so they sent on their */ - verbose(VERB_ALGO, "query response was ANSWER"); + verbose(VERB_DETAIL, "query response was ANSWER"); /* FIXME: there is a question about whether this gets * stored under the original query or most recent query. @@ -1133,7 +1136,7 @@ processQueryResponse(struct module_qstate* qstate, struct iter_qstate* iq, } else if(type == RESPONSE_TYPE_REFERRAL) { /* REFERRAL type responses get a reset of the * delegation point, and back to the QUERYTARGETS_STATE. */ - verbose(VERB_ALGO, "query response was REFERRAL"); + verbose(VERB_DETAIL, "query response was REFERRAL"); /* Store the referral under the current query */ if(!iter_dns_store(qstate->env, iq->response, 1)) @@ -1164,7 +1167,8 @@ processQueryResponse(struct module_qstate* qstate, struct iter_qstate* iq, /* CNAME type responses get a query restart (i.e., get a * reset of the query state and go back to INIT_REQUEST_STATE). */ - verbose(VERB_ALGO, "query response was CNAME"); + verbose(VERB_DETAIL, "query response was CNAME"); + log_dns_msg("cname msg", &iq->response->qinfo, iq->response->rep); /* Process the CNAME response. */ if(!iq->orig_qname) { iq->orig_qname = qstate->qinfo.qname; @@ -1197,7 +1201,7 @@ processQueryResponse(struct module_qstate* qstate, struct iter_qstate* iq, return next_state(qstate, iq, INIT_REQUEST_STATE); } else if(type == RESPONSE_TYPE_LAME) { /* Cache the LAMEness. */ - verbose(VERB_ALGO, "query response was LAME"); + verbose(VERB_DETAIL, "query response was LAME"); if(!infra_set_lame(qstate->env->infra_cache, &qstate->reply->addr, qstate->reply->addrlen, iq->dp->name, iq->dp->namelen, time(NULL))) @@ -1207,7 +1211,7 @@ processQueryResponse(struct module_qstate* qstate, struct iter_qstate* iq, * In this case, the event is just sent directly back to * the QUERYTARGETS_STATE without resetting anything, * because, clearly, the next target must be tried. */ - verbose(VERB_ALGO, "query response was THROWAWAY"); + verbose(VERB_DETAIL, "query response was THROWAWAY"); } else { log_warn("A query response came back with an unknown type: %d", (int)type); @@ -1261,8 +1265,8 @@ processPrimeResponse(struct module_qstate* qstate, struct iter_qstate* iq, return error_response(qstate, id, LDNS_RCODE_SERVFAIL); } - log_nametypeclass("priming successful for", qstate->qinfo.qname, - qstate->qinfo.qtype, qstate->qinfo.qclass); + log_nametypeclass(VERB_DETAIL, "priming successful for", + qstate->qinfo.qname, qstate->qinfo.qtype, qstate->qinfo.qclass); delegpt_log(dp); foriq = (struct iter_qstate*)forq->minfo[id]; foriq->dp = dp; @@ -1369,8 +1373,8 @@ static int processFinished(struct module_qstate* qstate, struct iter_qstate* iq, int id) { - log_nametypeclass("finishing processing for", qstate->qinfo.qname, - qstate->qinfo.qtype, qstate->qinfo.qclass); + log_nametypeclass(VERB_DETAIL, "finishing processing for", + qstate->qinfo.qname, qstate->qinfo.qtype, qstate->qinfo.qclass); if(!iq->response) { verbose(VERB_ALGO, "No response is set, servfail"); @@ -1527,8 +1531,11 @@ process_response(struct module_qstate* qstate, struct iter_qstate* iq, iq->response = dns_alloc_msg(pkt, prs, qstate->region); if(!iq->response) goto handle_it; - log_dns_msg("incoming scrubbed packet", &iq->response->qinfo, - iq->response->rep); + log_name_addr(VERB_DETAIL, "incoming packet from target:", iq->dp->name, + &qstate->reply->addr, qstate->reply->addrlen); + if(verbosity >= VERB_ALGO) + log_dns_msg("incoming scrubbed packet:", &iq->response->qinfo, + iq->response->rep); handle_it: outbound_list_remove(&iq->outlist, outbound); @@ -1584,17 +1591,16 @@ iter_operate(struct module_qstate* qstate, enum module_ev event, int id, { struct iter_env* ie = (struct iter_env*)qstate->env->modinfo[id]; struct iter_qstate* iq = (struct iter_qstate*)qstate->minfo[id]; - verbose(VERB_ALGO, "iterator[module %d] operate: extstate:%s event:%s", + verbose(VERB_DETAIL, "iterator[module %d] operate: extstate:%s event:%s", id, strextstate(qstate->ext_state[id]), strmodulevent(event)); - if(iq) log_nametypeclass("for qstate", qstate->qinfo.qname, - qstate->qinfo.qtype, qstate->qinfo.qclass); + if(iq) log_nametypeclass(VERB_DETAIL, "iterator operate: query", + qstate->qinfo.qname, qstate->qinfo.qtype, qstate->qinfo.qclass); if(ie->fwd_addrlen != 0) { perform_forward(qstate, event, id, outbound); return; } /* perform iterator state machine */ if(event == module_event_new && iq == NULL) { - log_info("iter state machine"); if(!iter_new(qstate, id)) { (void)error_response(qstate, id, LDNS_RCODE_SERVFAIL); return; diff --git a/services/outside_network.c b/services/outside_network.c index 8a02c4cd7..508ab43fd 100644 --- a/services/outside_network.c +++ b/services/outside_network.c @@ -244,7 +244,7 @@ outnet_tcp_cb(struct comm_point* c, void* arg, int error, struct outside_network* outnet = pend->query->outnet; verbose(VERB_ALGO, "outnettcp cb"); if(error != NETEVENT_NOERROR) { - log_info("outnettcp got tcp error %d", error); + verbose(VERB_DETAIL, "outnettcp got tcp error %d", error); /* pass error below and exit */ } else { /* check ID */ @@ -271,11 +271,11 @@ outnet_udp_cb(struct comm_point* c, void* arg, int error, verbose(VERB_ALGO, "answer cb"); if(error != NETEVENT_NOERROR) { - log_info("outnetudp got udp error %d", error); + verbose(VERB_DETAIL, "outnetudp got udp error %d", error); return 0; } if(ldns_buffer_limit(c->buffer) < LDNS_HEADER_SIZE) { - log_info("outnetudp udp too short"); + verbose(VERB_DETAIL, "outnetudp udp too short"); return 0; } log_assert(reply_info); @@ -284,9 +284,9 @@ outnet_udp_cb(struct comm_point* c, void* arg, int error, key.id = LDNS_ID_WIRE(ldns_buffer_begin(c->buffer)); memcpy(&key.addr, &reply_info->addr, reply_info->addrlen); key.addrlen = reply_info->addrlen; - verbose(VERB_ALGO, "Incoming reply id=%4.4x addr=", key.id); + verbose(VERB_ALGO, "Incoming reply id = %4.4x", key.id); if(verbosity >= VERB_ALGO) { - log_addr("Incoming reply addr=", &reply_info->addr, reply_info->addrlen); + log_addr("Incoming reply addr =", &reply_info->addr, reply_info->addrlen); } /* find it, see if this thing is a valid query response */ @@ -979,7 +979,7 @@ serviced_udp_send(struct serviced_query* sq, ldns_buffer* buff) log_err("gettimeofday: %s", strerror(errno)); return 0; } - verbose(VERB_DETAIL, "serviced query UDP timeout=%d msec", rtt); + verbose(VERB_ALGO, "serviced query UDP timeout=%d msec", rtt); sq->pending = pending_udp_query(sq->outnet, buff, &sq->addr, sq->addrlen, rtt, serviced_udp_callback, sq, sq->outnet->rnd); if(!sq->pending) @@ -1105,7 +1105,7 @@ serviced_udp_callback(struct comm_point* c, void* arg, int error, /* convert from microseconds to milliseconds */ int roundtime = (now.tv_sec - sq->last_sent_time.tv_sec)*1000 + ((int)now.tv_usec - (int)sq->last_sent_time.tv_usec)/1000; - log_info("measured roundtrip at %d msec", roundtime); + verbose(VERB_ALGO, "measured roundtrip at %d msec", roundtime); if(!infra_rtt_update(outnet->infra, &sq->addr, sq->addrlen, roundtime, (time_t)now.tv_sec)) log_err("out of memory noting rtt."); diff --git a/util/data/packed_rrset.c b/util/data/packed_rrset.c index 3d8a45cbb..e153934b1 100644 --- a/util/data/packed_rrset.c +++ b/util/data/packed_rrset.c @@ -212,3 +212,13 @@ get_cname_target(struct ub_packed_rrset_key* rrset, uint8_t** dname, *dname = d->rr_data[0]+sizeof(uint16_t); *dname_len = len; } + +void +packed_rrset_ttl_add(struct packed_rrset_data* data, uint32_t add) +{ + size_t i; + size_t total = data->count + data->rrsig_count; + data->ttl += add; + for(i=0; irr_ttl[i] += add; +} diff --git a/util/data/packed_rrset.h b/util/data/packed_rrset.h index 6af63d916..a2df77a9c 100644 --- a/util/data/packed_rrset.h +++ b/util/data/packed_rrset.h @@ -297,6 +297,13 @@ hashvalue_t rrset_key_hash(struct packed_rrset_key* key); */ void packed_rrset_ptr_fixup(struct packed_rrset_data* data); +/** + * Fixup TTLs in fixed data packed_rrset_data blob. + * @param data: rrset data structure. Otherwise correctly filled in. + * @param add: how many seconds to add, pass time(0) for example. + */ +void packed_rrset_ttl_add(struct packed_rrset_data* data, uint32_t add); + /** * Utility procedure to extract CNAME target name from its rdata. * Failsafes; it will change passed dname to a valid dname or do nothing. diff --git a/util/module.c b/util/module.c index 7d53b7359..a5ba45541 100644 --- a/util/module.c +++ b/util/module.c @@ -86,6 +86,16 @@ module_subreq_remove(struct module_qstate** head, struct module_qstate* sub) sub->subquery_prev = NULL; } +void +module_subreq_insert(struct module_qstate** head, struct module_qstate* sub) +{ + if(*head) + (*head)->subquery_prev = sub; + sub->subquery_next = *head; + sub->subquery_prev = NULL; + *head = sub; +} + int module_subreq_depth(struct module_qstate* sub) { diff --git a/util/module.h b/util/module.h index 12ac880df..ab29ed5d6 100644 --- a/util/module.h +++ b/util/module.h @@ -279,12 +279,20 @@ const char* strmodulevent(enum module_ev e); * Remove subqrequest from list. * @param head: List head. pointer to start of subquery_next/prev sibling list. * mostly reference to the parent subquery_first. - * @param sub: subrequest. Parent pointer used to access list. - * It is snipped off. + * @param sub: subrequest. It is snipped off. */ void module_subreq_remove(struct module_qstate** head, struct module_qstate* sub); +/** + * Insert subqrequest in list. You must set the parent ptr of sub correctly. + * @param head: List head. pointer to start of subquery_next/prev sibling list. + * mostly reference to the parent subquery_first. + * @param sub: subrequest. It is added to the list. + */ +void module_subreq_insert(struct module_qstate** head, + struct module_qstate* sub); + /** * Calculate depth of subrequest * @param sub: the subrequest. parent point is used. diff --git a/util/net_help.c b/util/net_help.c index 10e258a46..3ef69ecbb 100644 --- a/util/net_help.c +++ b/util/net_help.c @@ -179,12 +179,14 @@ ipstrtoaddr(const char* ip, int port, struct sockaddr_storage* addr, } void -log_nametypeclass(const char* str, uint8_t* name, uint16_t type, - uint16_t dclass) +log_nametypeclass(enum verbosity_value v, const char* str, uint8_t* name, + uint16_t type, uint16_t dclass) { char buf[LDNS_MAX_DOMAINLEN+1]; char t[12], c[12]; const char *ts, *cs; + if(verbosity < v) + return; dname_str(name, buf); if(ldns_rr_descript(type) && ldns_rr_descript(type)->_name) ts = ldns_rr_descript(type)->_name; @@ -202,6 +204,37 @@ log_nametypeclass(const char* str, uint8_t* name, uint16_t type, log_info("%s <%s %s %s>", str, buf, ts, cs); } +void log_name_addr(enum verbosity_value v, const char* str, uint8_t* zone, + struct sockaddr_storage* addr, socklen_t addrlen) +{ + uint16_t port; + const char* family = "unknown_family "; + char namebuf[LDNS_MAX_DOMAINLEN+1]; + char dest[100]; + int af = (int)((struct sockaddr_in*)addr)->sin_family; + void* sinaddr = &((struct sockaddr_in*)addr)->sin_addr; + if(verbosity < v) + return; + switch(af) { + case AF_INET: family=""; break; + case AF_INET6: family=""; + sinaddr = &((struct sockaddr_in6*)addr)->sin6_addr; + break; + case AF_UNIX: family="unix_family "; break; + default: break; + } + if(inet_ntop(af, sinaddr, dest, (socklen_t)sizeof(dest)) == 0) { + strncpy(dest, "(inet_ntop error)", sizeof(dest)); + } + port = ntohs(((struct sockaddr_in*)addr)->sin_port); + dname_str(zone, namebuf); + if(af != AF_INET && af != AF_INET6) + verbose(VERB_DETAIL, "%s <%s> %s%s#%d (addrlen %d)", + str, namebuf, family, dest, (int)port, (int)addrlen); + else verbose(VERB_DETAIL, "%s <%s> %s%s#%d", + str, namebuf, family, dest, (int)port); +} + int addr_is_ip6(struct sockaddr_storage* addr) { diff --git a/util/net_help.h b/util/net_help.h index af37ceabd..aa76e6e25 100644 --- a/util/net_help.h +++ b/util/net_help.h @@ -41,6 +41,7 @@ #ifndef NET_HELP_H #define NET_HELP_H +#include "util/log.h" /** DNS constants for uint16_t style flag manipulation. host byteorder. */ /** AA flag */ @@ -127,6 +128,17 @@ void* memdup(void* data, size_t len); void log_addr(const char* str, struct sockaddr_storage* addr, socklen_t addrlen); +/** + * Prints zone name and sockaddr in readable format with log_info. Debug. + * @param v: at what verbosity level to print this. + * @param str: descriptive string printed with it. + * @param zone: DNS domain name, uncompressed wireformat. + * @param addr: the sockaddr to print. Can be ip4 or ip6. + * @param addrlen: length of addr. + */ +void log_name_addr(enum verbosity_value v, const char* str, uint8_t* zone, + struct sockaddr_storage* addr, socklen_t addrlen); + /** * Convert ip address string and port to sockaddr. * @param ip: ip4 or ip6 address string. @@ -140,13 +152,14 @@ int ipstrtoaddr(const char* ip, int port, struct sockaddr_storage* addr, /** * Print string with neat domain name, type and class. + * @param v: at what verbosity level to print this. * @param str: string of message. * @param name: domain name uncompressed wireformat. * @param type: host format RR type. * @param dclass: host format RR class. */ -void log_nametypeclass(const char* str, uint8_t* name, uint16_t type, - uint16_t dclass); +void log_nametypeclass(enum verbosity_value v, const char* str, + uint8_t* name, uint16_t type, uint16_t dclass); /** * Checkout address family.