From f3525b2081bf19548dda216c08ad02396567a1f3 Mon Sep 17 00:00:00 2001 From: Wouter Wijngaards Date: Thu, 7 Feb 2008 11:04:56 +0000 Subject: [PATCH] log level 2. git-svn-id: file:///svn/unbound/trunk@930 be551aaa-1e26-0410-a405-d3ace91eadb9 --- doc/Changelog | 1 + iterator/iterator.c | 21 +++++++------- util/net_help.c | 4 +-- validator/validator.c | 64 ++++++++++++++++++++++++++++++------------- 4 files changed, 59 insertions(+), 31 deletions(-) diff --git a/doc/Changelog b/doc/Changelog index 9e766b6b0..27ff265ff 100644 --- a/doc/Changelog +++ b/doc/Changelog @@ -2,6 +2,7 @@ - moved up all current level 2 to be level 3. And 3 to 4. to make room for new debug level 2 for detailed information for operators. + - verbosity level 2. Describes recursion and validation. 6 February 2008: Wouter - clearer explanation of threading configure options. diff --git a/iterator/iterator.c b/iterator/iterator.c index 9453d9b5f..49fc22454 100644 --- a/iterator/iterator.c +++ b/iterator/iterator.c @@ -503,7 +503,7 @@ prime_root(struct module_qstate* qstate, struct iter_qstate* iq, { struct delegpt* dp; struct module_qstate* subq; - verbose(VERB_ALGO, "priming . NS %s", + verbose(VERB_DETAIL, "priming . %s NS", ldns_lookup_by_id(ldns_rr_classes, (int)qclass)? ldns_lookup_by_id(ldns_rr_classes, (int)qclass)->name:"??"); dp = hints_lookup_root(ie->hints, qclass); @@ -566,7 +566,7 @@ prime_stub(struct module_qstate* qstate, struct iter_qstate* iq, return 0; /* Otherwise, we need to (re)prime the stub. */ - log_nametypeclass(VERB_QUERY, "priming stub", stub_dp->name, + 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 @@ -656,7 +656,7 @@ processInitRequest(struct module_qstate* qstate, struct iter_qstate* iq, size_t delnamelen; struct dns_msg* msg; - log_query_info(VERB_QUERY, "resolving", &qstate->qinfo); + log_query_info(VERB_DETAIL, "resolving", &qstate->qinfo); /* check effort */ /* We enforce a maximum number of query restarts. This is primarily a @@ -1239,7 +1239,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_QUERY, "query response was ANSWER"); + verbose(VERB_DETAIL, "query response was ANSWER"); if(!iter_dns_store(qstate->env, &iq->response->qinfo, iq->response->rep, 0)) return error_response(qstate, id, LDNS_RCODE_SERVFAIL); @@ -1254,7 +1254,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_QUERY, "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->qinfo, @@ -1296,7 +1296,7 @@ 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_QUERY, "query response was CNAME"); + verbose(VERB_DETAIL, "query response was CNAME"); if(verbosity >= VERB_ALGO) log_dns_msg("cname msg", &iq->response->qinfo, iq->response->rep); @@ -1335,7 +1335,7 @@ processQueryResponse(struct module_qstate* qstate, struct iter_qstate* iq, return next_state(iq, INIT_REQUEST_STATE); } else if(type == RESPONSE_TYPE_LAME) { /* Cache the LAMEness. */ - verbose(VERB_QUERY, "query response was %sLAME", + verbose(VERB_DETAIL, "query response was %sLAME", dnsseclame?"DNSSEC ":""); if(qstate->reply) { /* need addr for lameness cache, but we may have @@ -1352,7 +1352,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_QUERY, "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); @@ -1394,7 +1394,7 @@ prime_supers(struct module_qstate* qstate, int id, struct module_qstate* forq) return; } - log_query_info(VERB_QUERY, "priming successful for", &qstate->qinfo); + log_query_info(VERB_DETAIL, "priming successful for", &qstate->qinfo); delegpt_log(VERB_ALGO, dp); foriq->dp = dp; foriq->deleg_msg = dns_copy_msg(qstate->return_msg, forq->region); @@ -1728,7 +1728,8 @@ 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_name_addr(VERB_QUERY, "incoming packet from target:", iq->dp->name, + log_query_info(VERB_DETAIL, "reponse for", &qstate->qinfo); + log_name_addr(VERB_DETAIL, "reply from", iq->dp->name, &qstate->reply->addr, qstate->reply->addrlen); if(verbosity >= VERB_ALGO) log_dns_msg("incoming scrubbed packet:", &iq->response->qinfo, diff --git a/util/net_help.c b/util/net_help.c index 153a433b6..536d1aa13 100644 --- a/util/net_help.c +++ b/util/net_help.c @@ -318,9 +318,9 @@ void log_name_addr(enum verbosity_value v, const char* str, uint8_t* zone, port = ntohs(((struct sockaddr_in*)addr)->sin_port); dname_str(zone, namebuf); if(af != AF_INET && af != AF_INET6) - verbose(VERB_QUERY, "%s <%s> %s%s#%d (addrlen %d)", + verbose(v, "%s <%s> %s%s#%d (addrlen %d)", str, namebuf, family, dest, (int)port, (int)addrlen); - else verbose(VERB_QUERY, "%s <%s> %s%s#%d", + else verbose(v, "%s <%s> %s%s#%d", str, namebuf, family, dest, (int)port); } diff --git a/validator/validator.c b/validator/validator.c index 2cae040d5..2f2e0115a 100644 --- a/validator/validator.c +++ b/validator/validator.c @@ -1183,7 +1183,7 @@ processInit(struct module_qstate* qstate, struct val_qstate* vq, if(vq->key_entry == NULL || dname_strict_subdomain_c( vq->trust_anchor->name, vq->key_entry->name)) { /* fire off a trust anchor priming query. */ - verbose(VERB_ALGO, "prime trust anchor"); + verbose(VERB_DETAIL, "prime trust anchor"); if(!prime_trust_anchor(qstate, vq, id, vq->trust_anchor)) return val_error(qstate, id); /* and otherwise, don't continue processing this event. @@ -1353,7 +1353,7 @@ processValidate(struct module_qstate* qstate, struct val_qstate* vq, /* Unsigned responses must be underneath a "null" key entry.*/ if(key_entry_isnull(vq->key_entry)) { - verbose(VERB_ALGO, "Verified that %sresponse is INSECURE", + verbose(VERB_DETAIL, "Verified that %sresponse is INSECURE", vq->signer_name?"":"unsigned "); vq->chase_reply->security = sec_status_insecure; val_mark_insecure(vq->chase_reply, vq->key_entry, @@ -1366,14 +1366,14 @@ processValidate(struct module_qstate* qstate, struct val_qstate* vq, if(vq->signer_name == NULL) { log_query_info(VERB_ALGO, "processValidate: state has no " "signer name", &vq->qchase); - verbose(VERB_QUERY, "Could not establish validation of " + verbose(VERB_DETAIL, "Could not establish validation of " "INSECURE status of unsigned response."); vq->chase_reply->security = sec_status_bogus; return 1; } if(key_entry_isbad(vq->key_entry)) { - log_nametypeclass(VERB_QUERY, "Could not establish a chain " + log_nametypeclass(VERB_DETAIL, "Could not establish a chain " "of trust to keys for", vq->key_entry->name, LDNS_RR_TYPE_DNSKEY, vq->key_entry->key_class); vq->chase_reply->security = sec_status_bogus; @@ -1384,7 +1384,7 @@ processValidate(struct module_qstate* qstate, struct val_qstate* vq, * answer and authority must be valid, additional is only checked. */ if(!validate_msg_signatures(qstate->env, ve, &vq->qchase, vq->chase_reply, vq->key_entry)) { - verbose(VERB_QUERY, "Validate: message contains bad rrsets"); + verbose(VERB_DETAIL, "Validate: message contains bad rrsets"); return 1; } @@ -1395,24 +1395,36 @@ processValidate(struct module_qstate* qstate, struct val_qstate* vq, verbose(VERB_ALGO, "Validating a positive response"); validate_positive_response(qstate->env, ve, &vq->qchase, vq->chase_reply, vq->key_entry); + verbose(VERB_DETAIL, "validate(positive): %s", + sec_status_to_string( + vq->chase_reply->security)); break; case VAL_CLASS_NODATA: verbose(VERB_ALGO, "Validating a nodata response"); validate_nodata_response(qstate->env, ve, &vq->qchase, vq->chase_reply, vq->key_entry); + verbose(VERB_DETAIL, "validate(nodata): %s", + sec_status_to_string( + vq->chase_reply->security)); break; case VAL_CLASS_NAMEERROR: verbose(VERB_ALGO, "Validating a nxdomain response"); validate_nameerror_response(qstate->env, ve, &vq->qchase, vq->chase_reply, vq->key_entry); + verbose(VERB_DETAIL, "validate(nxdomain): %s", + sec_status_to_string( + vq->chase_reply->security)); break; case VAL_CLASS_CNAME: verbose(VERB_ALGO, "Validating a cname response"); validate_cname_response(qstate->env, ve, &vq->qchase, vq->chase_reply, vq->key_entry); + verbose(VERB_DETAIL, "validate(cname): %s", + sec_status_to_string( + vq->chase_reply->security)); break; case VAL_CLASS_CNAMENOANSWER: @@ -1420,11 +1432,17 @@ processValidate(struct module_qstate* qstate, struct val_qstate* vq, "response"); validate_cname_noanswer_response(qstate->env, ve, &vq->qchase, vq->chase_reply, vq->key_entry); + verbose(VERB_DETAIL, "validate(cname_noanswer): %s", + sec_status_to_string( + vq->chase_reply->security)); break; case VAL_CLASS_REFERRAL: verbose(VERB_ALGO, "Validating a referral response"); validate_referral_response(vq->chase_reply); + verbose(VERB_DETAIL, "validate(referral): %s", + sec_status_to_string( + vq->chase_reply->security)); break; case VAL_CLASS_ANY: @@ -1432,6 +1450,9 @@ processValidate(struct module_qstate* qstate, struct val_qstate* vq, "response"); validate_any_response(qstate->env, ve, &vq->qchase, vq->chase_reply, vq->key_entry); + verbose(VERB_DETAIL, "validate(positive_any): %s", + sec_status_to_string( + vq->chase_reply->security)); break; default: @@ -1510,6 +1531,8 @@ processFinished(struct module_qstate* qstate, struct val_qstate* vq, * that are not secure (if clean-additional option is set) */ /* this may cause the msg to be marked bogus */ val_check_nonsecure(ve, vq->orig_msg->rep); + log_query_info(VERB_DETAIL, "validation success", + &qstate->qinfo); } /* if the result is bogus - set message ttl to bogus ttl to avoid @@ -1689,12 +1712,14 @@ primeResponseToKE(int rcode, struct dns_msg* msg, struct trust_anchor* ta, sec = sec_status_secure; else sec = sec_status_bogus; - verbose(VERB_ALGO, "priming DS result %s", + verbose(VERB_DETAIL, "validate keys with anchor(DS): %s", sec_status_to_string(sec)); } if(sec != sec_status_secure && ta->dnskey_rrset) { sec = val_verify_rrset(qstate->env, ve, dnskey_rrset, ta->dnskey_rrset); + verbose(VERB_DETAIL, "validate keys with anchor(DNSKEY): %s", + sec_status_to_string(sec)); if(sec == sec_status_secure) { kkey = key_entry_create_rrset(qstate->region, ta->name, ta->namelen, ta->dclass, @@ -1725,7 +1750,7 @@ primeResponseToKE(int rcode, struct dns_msg* msg, struct trust_anchor* ta, return kkey; } - log_nametypeclass(VERB_ALGO, "Successfully primed trust anchor", + log_nametypeclass(VERB_DETAIL, "Successfully primed trust anchor", ta->name, LDNS_RR_TYPE_DNSKEY, ta->dclass); /* store the freshly primed entry in the cache */ key_cache_insert(ve->kcache, kkey); @@ -1758,7 +1783,7 @@ ds_response_to_ke(struct module_qstate* qstate, struct val_qstate* vq, enum val_classification subtype; if(rcode != LDNS_RCODE_NOERROR) { /* errors here pretty much break validation */ - verbose(VERB_QUERY, "DS response was error, thus bogus"); + verbose(VERB_DETAIL, "DS response was error, thus bogus"); goto return_bogus; } @@ -1779,7 +1804,7 @@ ds_response_to_ke(struct module_qstate* qstate, struct val_qstate* vq, sec = val_verify_rrset_entry(qstate->env, ve, ds, vq->key_entry); if(sec != sec_status_secure) { - verbose(VERB_QUERY, "DS rrset in DS response did " + verbose(VERB_DETAIL, "DS rrset in DS response did " "not verify"); goto return_bogus; } @@ -1796,7 +1821,7 @@ ds_response_to_ke(struct module_qstate* qstate, struct val_qstate* vq, } /* Otherwise, we return the positive response. */ - log_query_info(VERB_ALGO, "DS rrset was good.", qinfo); + log_query_info(VERB_DETAIL, "validated DS", qinfo); *ke = key_entry_create_rrset(qstate->region, qinfo->qname, qinfo->qname_len, qinfo->qclass, ds); return (*ke) != NULL; @@ -1817,19 +1842,19 @@ ds_response_to_ke(struct module_qstate* qstate, struct val_qstate* vq, &proof_ttl); switch(sec) { case sec_status_secure: - verbose(VERB_ALGO, "NSEC RRset for the " + verbose(VERB_DETAIL, "NSEC RRset for the " "referral proved no DS."); *ke = key_entry_create_null(qstate->region, qinfo->qname, qinfo->qname_len, qinfo->qclass, proof_ttl); return (*ke) != NULL; case sec_status_insecure: - verbose(VERB_ALGO, "NSEC RRset for the " + verbose(VERB_DETAIL, "NSEC RRset for the " "referral proved not a delegation point"); *ke = NULL; return 1; case sec_status_bogus: - verbose(VERB_QUERY, "NSEC RRset for the " + verbose(VERB_DETAIL, "NSEC RRset for the " "referral did not prove no DS."); goto return_bogus; case sec_status_unchecked: @@ -1843,19 +1868,19 @@ ds_response_to_ke(struct module_qstate* qstate, struct val_qstate* vq, msg->rep->ns_numrrsets, qinfo, vq->key_entry); switch(sec) { case sec_status_secure: - verbose(VERB_ALGO, "NSEC3s for the " + verbose(VERB_DETAIL, "NSEC3s for the " "referral proved no DS."); *ke = key_entry_create_null(qstate->region, qinfo->qname, qinfo->qname_len, qinfo->qclass, proof_ttl); return (*ke) != NULL; case sec_status_indeterminate: - verbose(VERB_ALGO, "NSEC3s for the " + verbose(VERB_DETAIL, "NSEC3s for the " "referral proved no delegation"); *ke = NULL; return 1; case sec_status_bogus: - verbose(VERB_QUERY, "NSEC3s for the " + verbose(VERB_DETAIL, "NSEC3s for the " "referral did not prove no DS."); goto return_bogus; case sec_status_insecure: @@ -1867,7 +1892,7 @@ ds_response_to_ke(struct module_qstate* qstate, struct val_qstate* vq, /* Apparently, no available NSEC/NSEC3 proved NODATA, so * this is BOGUS. */ - verbose(VERB_QUERY, "DS %s ran out of options, so return " + verbose(VERB_DETAIL, "DS %s ran out of options, so return " "bogus", val_classification_to_string(subtype)); goto return_bogus; } else { @@ -1967,7 +1992,7 @@ process_dnskey_response(struct module_qstate* qstate, struct val_qstate* vq, if(dnskey == NULL) { /* bad response */ - verbose(VERB_QUERY, "Missing DNSKEY RRset in response to " + verbose(VERB_DETAIL, "Missing DNSKEY RRset in response to " "DNSKEY query."); vq->key_entry = key_entry_create_bad(qstate->region, qinfo->qname, qinfo->qname_len, qinfo->qclass); @@ -1996,7 +2021,7 @@ process_dnskey_response(struct module_qstate* qstate, struct val_qstate* vq, * state. */ if(!key_entry_isgood(vq->key_entry)) { if(key_entry_isbad(vq->key_entry)) - verbose(VERB_QUERY, "Did not match a DS to a DNSKEY, " + verbose(VERB_DETAIL, "Did not match a DS to a DNSKEY, " "thus bogus."); vq->state = VAL_VALIDATE_STATE; return; @@ -2006,6 +2031,7 @@ process_dnskey_response(struct module_qstate* qstate, struct val_qstate* vq, key_cache_insert(ve->kcache, vq->key_entry); /* If good, we stay in the FINDKEY state. */ + log_query_info(VERB_DETAIL, "validated DNSKEY", qinfo); } /** -- 2.47.2