verbosity detail gives validation failures, but not boring algorithm logs.

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

diff --git a/doc/Changelog b/doc/Changelog
index 3d0d1322bfc3a5486df45c5c7f161cd3c79c748a..707d19b0176b97b5b27eae1eb6b6a4a4aedd208d 100644 (file)
--- a/doc/Changelog
+++ b/doc/Changelog
@@ -15,6 +15,9 @@
        - if the rrset is too big (64k exactly + large owner name) the
          canonicalization routine will fail if it does not fit in buffer.
        - faster verification for large sigsets.
+       - verb_detail mode reports validation failures, but not the entire
+         algorithm for validation. Key prime failures are reported as 
+         verb_ops level.
 
 27 August 2007: Wouter
        - do not garble the edns if a cache answer fails.

diff --git a/validator/val_sigcrypt.c b/validator/val_sigcrypt.c
index 6682af78088ffea3c0d85b36ccea19664e7ec5ae..ef848b99b625a05b1b5479db60469623d24e37aa 100644 (file)
--- a/validator/val_sigcrypt.c
+++ b/validator/val_sigcrypt.c
@@ -400,7 +400,7 @@ dnskeyset_verify_rrset(struct module_env* env, struct val_env* ve,
        rbtree_t* sortree = NULL;
        num = rrset_get_sigcount(rrset);
        if(num == 0) {
-               verbose(VERB_ALGO, "rrset failed to verify due to a lack of "
+               verbose(VERB_DETAIL, "rrset failed to verify due to a lack of "
                        "signatures");
                return sec_status_bogus;
        }
@@ -428,7 +428,7 @@ dnskey_verify_rrset(struct module_env* env, struct val_env* ve,
 
        num = rrset_get_sigcount(rrset);
        if(num == 0) {
-               verbose(VERB_ALGO, "rrset failed to verify due to a lack of "
+               verbose(VERB_DETAIL, "rrset failed to verify due to a lack of "
                        "signatures");
                return sec_status_bogus;
        }
@@ -477,7 +477,7 @@ dnskeyset_verify_rrset_sig(struct module_env* env, struct val_env* ve,
                        return sec;
        }
        if(numchecked == 0) {
-               verbose(VERB_ALGO, "could not find appropriate key");
+               verbose(VERB_DETAIL, "verify: could not find appropriate key");
                return sec_status_bogus;
        }
        return sec_status_bogus;
@@ -1054,7 +1054,7 @@ sigdate_error(const char* str, int32_t expi, int32_t incep, int32_t now)
        char now_buf[16];
        time_t te, ti, tn;
 
-       if(verbosity < VERB_ALGO)
+       if(verbosity < VERB_DETAIL)
                return;
        te = (time_t)expi;
        ti = (time_t)incep;
@@ -1179,7 +1179,7 @@ dsa_rrsig_to_dsa_sig(unsigned char* sig, unsigned int siglen)
 
        /* extract the R and S field from the sig buffer */
        if(siglen < 1 + SHA_DIGEST_LENGTH*2) {
-               verbose(VERB_ALGO, "verify: short DSA RRSIG");
+               verbose(VERB_DETAIL, "verify: short DSA RRSIG");
                return NULL;
        }
        t = sig[0];
@@ -1290,7 +1290,7 @@ setup_key_digest(int algo, EVP_PKEY* evp_key, const EVP_MD** digest_type,
 
                        break;
                default:
-                       verbose(VERB_ALGO, "verify: unknown algorithm %d", 
+                       verbose(VERB_DETAIL, "verify: unknown algorithm %d", 
                                algo);
                        return 0;
        }
@@ -1385,18 +1385,18 @@ dnskey_verify_rrset_sig(struct region* region, ldns_buffer* buf,
        rrset_get_rdata(rrset, rrnum + sig_idx, &sig, &siglen);
        /* min length of rdatalen, fixed rrsig, root signer, 1 byte sig */
        if(siglen < 2+20) {
-               verbose(VERB_ALGO, "verify: signature too short");
+               verbose(VERB_DETAIL, "verify: signature too short");
                return sec_status_bogus;
        }
 
        if(!(dnskey_get_flags(dnskey, dnskey_idx) & DNSKEY_BIT_ZSK)) {
-               verbose(VERB_ALGO, "verify: dnskey without ZSK flag");
+               verbose(VERB_DETAIL, "verify: dnskey without ZSK flag");
                return sec_status_bogus; 
        }
 
        if(dnskey_get_protocol(dnskey, dnskey_idx) != LDNS_DNSSEC_KEYPROTO) { 
                /* RFC 4034 says DNSKEY PROTOCOL MUST be 3 */
-               verbose(VERB_ALGO, "verify: dnskey has wrong key protocol");
+               verbose(VERB_DETAIL, "verify: dnskey has wrong key protocol");
                return sec_status_bogus;
        }
 
@@ -1404,46 +1404,46 @@ dnskey_verify_rrset_sig(struct region* region, ldns_buffer* buf,
        signer = sig+2+18;
        signer_len = dname_valid(signer, siglen-2-18);
        if(!signer_len) {
-               verbose(VERB_ALGO, "verify: malformed signer name");
+               verbose(VERB_DETAIL, "verify: malformed signer name");
                return sec_status_bogus; /* signer name invalid */
        }
        if(!dname_subdomain_c(rrset->rk.dname, signer)) {
-               verbose(VERB_ALGO, "verify: signer name is off-tree");
+               verbose(VERB_DETAIL, "verify: signer name is off-tree");
                return sec_status_bogus; /* signer name offtree */
        }
        sigblock = (unsigned char*)signer+signer_len;
        if(siglen < 2+18+signer_len+1) {
-               verbose(VERB_ALGO, "verify: too short, no signature data");
+               verbose(VERB_DETAIL, "verify: too short, no signature data");
                return sec_status_bogus; /* sig rdf is < 1 byte */
        }
        sigblock_len = (unsigned int)(siglen - 2 - 18 - signer_len);
 
        /* verify key dname == sig signer name */
        if(query_dname_compare(signer, dnskey->rk.dname) != 0) {
-               verbose(VERB_ALGO, "verify: wrong key for rrsig");
+               verbose(VERB_DETAIL, "verify: wrong key for rrsig");
                return sec_status_bogus;
        }
 
        /* verify covered type */
        /* memcmp works because type is in network format for rrset */
        if(memcmp(sig+2, &rrset->rk.type, 2) != 0) {
-               verbose(VERB_ALGO, "verify: wrong type covered");
+               verbose(VERB_DETAIL, "verify: wrong type covered");
                return sec_status_bogus;
        }
        /* verify keytag and sig algo (possibly again) */
        if((int)sig[2+2] != dnskey_get_algo(dnskey, dnskey_idx)) {
-               verbose(VERB_ALGO, "verify: wrong algorithm");
+               verbose(VERB_DETAIL, "verify: wrong algorithm");
                return sec_status_bogus;
        }
        ktag = htons(dnskey_calc_keytag(dnskey, dnskey_idx));
        if(memcmp(sig+2+16, &ktag, 2) != 0) {
-               verbose(VERB_ALGO, "verify: wrong keytag");
+               verbose(VERB_DETAIL, "verify: wrong keytag");
                return sec_status_bogus;
        }
 
        /* verify labels is in a valid range */
        if((int)sig[2+3] > dname_signame_label_count(rrset->rk.dname)) {
-               verbose(VERB_ALGO, "verify: labelcount out of range");
+               verbose(VERB_DETAIL, "verify: labelcount out of range");
                return sec_status_bogus;
        }
 
@@ -1468,7 +1468,7 @@ dnskey_verify_rrset_sig(struct region* region, ldns_buffer* buf,
        /* check that dnskey is available */
        dnskey_get_pubkey(dnskey, dnskey_idx, &key, &keylen);
        if(!key) {
-               verbose(VERB_ALGO, "verify: short DNSKEY RR");
+               verbose(VERB_DETAIL, "verify: short DNSKEY RR");
                return sec_status_unchecked;
        }
 

diff --git a/validator/val_utils.c b/validator/val_utils.c
index 239fc02bd307dfd69cf00382a4952ce78459290a..0590d0b705ac9437ec1fdbc53595c26e0a2996c7 100644 (file)
--- a/validator/val_utils.c
+++ b/validator/val_utils.c
@@ -246,7 +246,7 @@ val_find_signer(enum val_classification subtype, struct query_info* qinf,
                *signer_name = NULL;
                *signer_len = 0;
        } else {
-               verbose(VERB_ALGO, "find_signer: could not find signer name"
+               verbose(VERB_DETAIL, "find_signer: could not find signer name"
                        " for unknown type response");
                *signer_name = NULL;
                *signer_len = 0;
@@ -394,7 +394,7 @@ val_verify_new_DNSKEYs(struct region* region, struct module_env* env,
        if(dnskey_rrset->rk.dname_len != ds_rrset->rk.dname_len ||
                query_dname_compare(dnskey_rrset->rk.dname, ds_rrset->rk.dname)
                != 0) {
-               verbose(VERB_ALGO, "DNSKEY RRset did not match DS RRset "
+               verbose(VERB_DETAIL, "DNSKEY RRset did not match DS RRset "
                        "by name");
                return key_entry_create_bad(region, ds_rrset->rk.dname,
                        ds_rrset->rk.dname_len, 
@@ -436,7 +436,7 @@ val_verify_new_DNSKEYs(struct region* region, struct module_env* env,
                        rrset_get_ttl(ds_rrset));
        }
        /* If any were understandable, then it is bad. */
-       verbose(VERB_ALGO, "Failed to match any usable DS to a DNSKEY.");
+       verbose(VERB_DETAIL, "Failed to match any usable DS to a DNSKEY.");
        return key_entry_create_bad(region, ds_rrset->rk.dname,
                ds_rrset->rk.dname_len, ntohs(ds_rrset->rk.rrset_class));
 }
@@ -600,6 +600,11 @@ val_check_nonsecure(struct val_env* ve, struct reply_info* rep)
                         * But this rrset did not verify.
                         * Therefore the message is bogus.
                         */
+                       log_nametypeclass(VERB_DETAIL, "message is bogus, "
+                               "non secure rrset",
+                               rep->rrsets[i]->rk.dname, 
+                               ntohs(rep->rrsets[i]->rk.type),
+                               ntohs(rep->rrsets[i]->rk.rrset_class));
                        rep->security = sec_status_bogus;
                        return;
                }

diff --git a/validator/validator.c b/validator/validator.c
index 89eec213c3a380ec000acb5010365b64ac1556ae..f4af58f23e46298b2b1112f256d002294955aa06 100644 (file)
--- a/validator/validator.c
+++ b/validator/validator.c
@@ -334,8 +334,8 @@ validate_msg_signatures(struct module_env* env, struct val_env* ve,
                /* If the (answer) rrset failed to validate, then this 
                 * message is BAD. */
                if(sec != sec_status_secure) {
-                       log_nametypeclass(VERB_ALGO, "validator: response has "
-                               "failed ANSWER rrset: ", s->rk.dname,
+                       log_nametypeclass(VERB_DETAIL, "validator: response "
+                               "has failed ANSWER rrset: ", s->rk.dname,
                                ntohs(s->rk.type), ntohs(s->rk.rrset_class));
                        chase_reply->security = sec_status_bogus;
                        return 0;
@@ -357,8 +357,8 @@ validate_msg_signatures(struct module_env* env, struct val_env* ve,
                /* If anything in the authority section fails to be secure, 
                 * we have a bad message. */
                if(sec != sec_status_secure) {
-                       log_nametypeclass(VERB_ALGO, "validator: response has "
-                               "failed AUTHORITY rrset: ", s->rk.dname,
+                       log_nametypeclass(VERB_DETAIL, "validator: response "
+                               "has failed AUTHORITY rrset: ", s->rk.dname,
                                ntohs(s->rk.type), ntohs(s->rk.rrset_class));
                        chase_reply->security = sec_status_bogus;
                        return 0;
@@ -407,7 +407,7 @@ validate_positive_response(struct query_info* qchase,
                 * expansion. If so, an additional check will need to be 
                 * made in the authority section. */
                if(!val_rrset_wildcard(s, &wc)) {
-                       log_nametypeclass(VERB_ALGO, "Positive response has "
+                       log_nametypeclass(VERB_DETAIL, "Positive response has "
                                "inconsistent wildcard sigs: ", s->rk.dname,
                                ntohs(s->rk.type), ntohs(s->rk.rrset_class));
                        chase_reply->security = sec_status_bogus;
@@ -450,7 +450,7 @@ validate_positive_response(struct query_info* qchase,
        /* If after all this, we still haven't proven the positive wildcard
         * response, fail. */
        if(wc != NULL && !wc_NSEC_ok) {
-               verbose(VERB_ALGO, "positive response was wildcard "
+               verbose(VERB_DETAIL, "positive response was wildcard "
                        "expansion and did not prove original data "
                        "did not exist");
                chase_reply->security = sec_status_bogus;
@@ -533,7 +533,7 @@ validate_nodata_response(struct query_info* qchase,
        }
 
        if(!has_valid_nsec) {
-               verbose(VERB_ALGO, "NODATA response failed to prove NODATA "
+               verbose(VERB_DETAIL, "NODATA response failed to prove NODATA "
                        "status with NSEC/NSEC3");
                if(verbosity >= VERB_ALGO)
                        log_dns_msg("Failed NODATA", qchase, chase_reply);
@@ -585,14 +585,14 @@ validate_nameerror_response(struct query_info* qchase,
 
        /* If the message fails to prove either condition, it is bogus. */
        if(!has_valid_nsec) {
-               verbose(VERB_ALGO, "NameError response has failed to prove: "
+               verbose(VERB_DETAIL, "NameError response has failed to prove: "
                          "qname does not exist");
                chase_reply->security = sec_status_bogus;
                return;
        }
 
        if(!has_valid_wnsec) {
-               verbose(VERB_ALGO, "NameError response has failed to prove: "
+               verbose(VERB_DETAIL, "NameError response has failed to prove: "
                          "covering wildcard does not exist");
                chase_reply->security = sec_status_bogus;
                return;
@@ -696,7 +696,7 @@ validate_cname_response(struct query_info* qchase,
                 * expansion. If so, an additional check will need to be 
                 * made in the authority section. */
                if(!val_rrset_wildcard(s, &wc)) {
-                       log_nametypeclass(VERB_ALGO, "Cname response has "
+                       log_nametypeclass(VERB_DETAIL, "Cname response has "
                                "inconsistent wildcard sigs: ", s->rk.dname,
                                ntohs(s->rk.type), ntohs(s->rk.rrset_class));
                        chase_reply->security = sec_status_bogus;
@@ -709,7 +709,7 @@ validate_cname_response(struct query_info* qchase,
                if(qchase->qtype != LDNS_RR_TYPE_DNAME && 
                        ntohs(s->rk.type) == LDNS_RR_TYPE_DNAME &&
                        dname_is_wild(s->rk.dname)) {
-                       log_nametypeclass(VERB_ALGO, "cannot validate a "
+                       log_nametypeclass(VERB_DETAIL, "cannot validate a "
                                "wildcarded DNAME: ", s->rk.dname, 
                                ntohs(s->rk.type), ntohs(s->rk.rrset_class));
                        chase_reply->security = sec_status_bogus;
@@ -751,7 +751,7 @@ validate_cname_response(struct query_info* qchase,
        /* If after all this, we still haven't proven the positive wildcard
         * response, fail. */
        if(wc != NULL && !wc_NSEC_ok) {
-               verbose(VERB_ALGO, "CNAME response was wildcard "
+               verbose(VERB_DETAIL, "CNAME response was wildcard "
                        "expansion and did not prove original data "
                        "did not exist");
                chase_reply->security = sec_status_bogus;
@@ -832,7 +832,7 @@ validate_cname_noanswer_response(struct query_info* qchase,
        }
        
        if(nodata_valid_nsec && nxdomain_valid_nsec) {
-               verbose(VERB_ALGO, "CNAMEchain to noanswer proves that name "
+               verbose(VERB_DETAIL, "CNAMEchain to noanswer proves that name "
                        "exists and not exists, bogus");
                chase_reply->security = sec_status_bogus;
                return;
@@ -843,7 +843,7 @@ validate_cname_noanswer_response(struct query_info* qchase,
        }
 
        if(!nodata_valid_nsec && !nxdomain_valid_nsec) {
-               verbose(VERB_ALGO, "CNAMEchain to noanswer response failed "
+               verbose(VERB_DETAIL, "CNAMEchain to noanswer response failed "
                        "to prove status with NSEC/NSEC3");
                if(verbosity >= VERB_ALGO)
                        log_dns_msg("Failed CNAMEnoanswer", qchase, chase_reply);
@@ -993,7 +993,7 @@ processFindKey(struct module_qstate* qstate, struct val_qstate* vq, int id)
        size_t target_key_len, current_key_len;
        int strip_lab;
 
-       verbose(VERB_ALGO, "validator: FindKey");
+       log_query_info(VERB_ALGO, "validator: FindKey", &vq->qchase);
        /* We know that state.key_entry is not a null or bad key -- if it were,
         * then previous processing should have directed this event to 
         * a different state. */
@@ -1103,14 +1103,14 @@ processValidate(struct module_qstate* qstate, struct val_qstate* vq,
                                qstate->env->rrset_cache);
                        return 1;
                }
-               verbose(VERB_ALGO, "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_ALGO, "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;
@@ -1129,7 +1129,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_ALGO, "Validate: message contains bad rrsets");
+               verbose(VERB_DETAIL, "Validate: message contains bad rrsets");
                return 1;
        }
 
@@ -1234,7 +1234,7 @@ processFinished(struct module_qstate* qstate, struct val_qstate* vq,
                        vq->orig_msg->rep->security = sec_status_bogus;
                } else {
                        /* restart process for new qchase at rrset_skip */
-                       log_query_info(VERB_DETAIL, "validator: chased to",
+                       log_query_info(VERB_ALGO, "validator: chased to",
                                &vq->qchase);
                        vq->chase_reply->security = sec_status_unchecked;
                        vq->state = VAL_INIT_STATE;
@@ -1402,7 +1402,7 @@ primeResponseToKE(int rcode, struct dns_msg* msg, struct trust_anchor* ta,
                        ta->dclass);
        }
        if(!dnskey_rrset) {
-               log_query_info(VERB_ALGO, "failed to prime trust anchor -- "
+               log_query_info(VERB_OPS, "failed to prime trust anchor -- "
                        "could not fetch DNSKEY rrset", &msg->qinfo);
                kkey = key_entry_create_null(qstate->region, ta->name,
                        ta->namelen, ta->dclass, NULL_KEY_TTL);
@@ -1442,8 +1442,8 @@ primeResponseToKE(int rcode, struct dns_msg* msg, struct trust_anchor* ta,
        }
 
        if(sec != sec_status_secure) {
-               log_query_info(VERB_ALGO, "failed to prime trust anchor -- "
-                       "could not fetch DNSKEY rrset", &msg->qinfo);
+               log_query_info(VERB_OPS, "failed to prime trust anchor -- "
+                       "could not fetch secure DNSKEY rrset", &msg->qinfo);
                /* NOTE: in this case, we should probably reject the trust 
                 * anchor for longer, perhaps forever. */
                kkey = key_entry_create_null(qstate->region, ta->name,
@@ -1489,7 +1489,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_ALGO, "DS response was error, thus bogus");
+               verbose(VERB_DETAIL, "DS response was error, thus bogus");
                goto return_bogus;
        }
 
@@ -1510,7 +1510,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_ALGO, "DS rrset in DS response did "
+                       verbose(VERB_DETAIL, "DS rrset in DS response did "
                                "not verify");
                        goto return_bogus;
                }
@@ -1554,7 +1554,7 @@ ds_response_to_ke(struct module_qstate* qstate, struct val_qstate* vq,
                                *ke = NULL;
                                return 1;
                        case sec_status_bogus:
-                               verbose(VERB_ALGO, "NSEC RRset for the "
+                               verbose(VERB_DETAIL, "NSEC RRset for the "
                                        "referral did not prove no DS.");
                                goto return_bogus;
                        case sec_status_unchecked:
@@ -1567,13 +1567,13 @@ 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_ALGO, "DS ran out of options, so return bogus");
+               verbose(VERB_DETAIL, "DS ran out of options, so return bogus");
                goto return_bogus;
        } else if(subtype == VAL_CLASS_NAMEERROR) {
-               verbose(VERB_ALGO, "DS response was NAMEERROR, thus bogus.");
+               verbose(VERB_DETAIL, "DS response was NAMEERROR, thus bogus.");
                goto return_bogus;
        } else {
-               verbose(VERB_ALGO, "Encountered an unhandled type of "
+               verbose(VERB_DETAIL, "Encountered an unhandled type of "
                        "DS response, thus bogus.");
 return_bogus:
                *ke = key_entry_create_bad(qstate->region, qinfo->qname,
@@ -1604,7 +1604,7 @@ process_ds_response(struct module_qstate* qstate, struct val_qstate* vq,
 {
        struct key_entry_key* dske = NULL;
        if(!ds_response_to_ke(qstate, vq, id, rcode, msg, qinfo, &dske)) {
-                       log_err("malloc failure in DStoKE");
+                       log_err("malloc failure in process_ds_response");
                        vq->key_entry = NULL; /* make it error */
                        vq->state = VAL_VALIDATE_STATE;
                        return;
@@ -1660,7 +1660,7 @@ process_dnskey_response(struct module_qstate* qstate, struct val_qstate* vq,
 
        if(dnskey == NULL) {
                /* bad response */
-               verbose(VERB_ALGO, "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);
@@ -1689,7 +1689,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_ALGO, "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;