From: Wouter Wijngaards Date: Tue, 28 Aug 2007 15:07:52 +0000 (+0000) Subject: verbosity detail gives validation failures, but not boring algorithm logs. X-Git-Tag: release-0.5~81 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=824ceffedb254239057daa0c6ff4f834688676f6;p=thirdparty%2Funbound.git 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 3d0d1322b..707d19b01 100644 --- 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 6682af780..ef848b99b 100644 --- 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 239fc02bd..0590d0b70 100644 --- 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 89eec213c..f4af58f23 100644 --- 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;