log level 2.

git-svn-id: file:///svn/unbound/trunk@930 be551aaa-1e26-0410-a405-d3ace91eadb9

diff --git a/doc/Changelog b/doc/Changelog
index 9e766b6b036967eff9cb057494475893715bcdc6..27ff265ffa09550164c306b944d07e9413052f79 100644 (file)
--- 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 9453d9b5fae7e0d029c40587063ca46fd28d423f..49fc224548a17568fdec49ffa28ef3bc303bb426 100644 (file)
--- 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 153a433b64c6c806a230e8a5c8d0a9aa0e537096..536d1aa13678a326084f8323c8fffeb592d20d06 100644 (file)
--- 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 2cae040d535aace38e1b09e4836c7ad3e52f361c..2f2e0115a28955e7f5498528c3e0252704dfecf1 100644 (file)
--- 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);
 }
        
 /**