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

git-svn-id: file:///svn/unbound/trunk@560 be551aaa-1e26-0410-a405-d3ace91eadb9
This commit is contained in:
Wouter Wijngaards 2007-08-28 15:07:52 +00:00
parent e839035a7a
commit 824ceffedb
4 changed files with 60 additions and 52 deletions

View file

@ -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.

View file

@ -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;
}

View file

@ -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;
}

View file

@ -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;