std::vector<std::shared_ptr<RRSIGRecordContent>> wcSignatures;
if (g_recCache->get(now, wildcardName, type, MemRecursorCache::RequireAuth, &wcSet, ComboAddress("127.0.0.1"), boost::none, doDNSSEC ? &wcSignatures : nullptr, nullptr, nullptr, &cachedState) <= 0 || cachedState != vState::Secure) {
- VLOG(log, "Unfortunately we don't have a valid entry for " << wildcardName << ", so we cannot synthesize from that wildcard" << endl);
+ VLOG(log, name << ": Unfortunately we don't have a valid entry for " << wildcardName << ", so we cannot synthesize from that wildcard" << endl);
return false;
}
addRecordToRRSet(now, nextCloser.d_owner, QType::NSEC3, nextCloser.d_ttd - now, nextCloser.d_record, nextCloser.d_signatures, doDNSSEC, ret);
/* and of course we won't deny the wildcard either */
- VLOG(log, "Synthesized valid answer from NSEC3s and wildcard!" << endl);
+ VLOG(log, name << ": Synthesized valid answer from NSEC3s and wildcard!" << endl);
++d_nsec3WildcardHits;
return true;
}
std::vector<std::shared_ptr<RRSIGRecordContent>> wcSignatures;
if (g_recCache->get(now, wildcardName, type, MemRecursorCache::RequireAuth, &wcSet, ComboAddress("127.0.0.1"), boost::none, doDNSSEC ? &wcSignatures : nullptr, nullptr, nullptr, &cachedState) <= 0 || cachedState != vState::Secure) {
- VLOG(log, "Unfortunately we don't have a valid entry for " << wildcardName << ", so we cannot synthesize from that wildcard" << endl);
+ VLOG(log, name << ": Unfortunately we don't have a valid entry for " << wildcardName << ", so we cannot synthesize from that wildcard" << endl);
return false;
}
addToRRSet(now, wcSet, wcSignatures, name, doDNSSEC, ret, DNSResourceRecord::ANSWER);
addRecordToRRSet(now, nsec.d_owner, QType::NSEC, nsec.d_ttd - now, nsec.d_record, nsec.d_signatures, doDNSSEC, ret);
- VLOG(log, "Synthesized valid answer from NSECs and wildcard!" << endl);
+ VLOG(log, name << ": Synthesized valid answer from NSECs and wildcard!" << endl);
++d_nsecWildcardHits;
return true;
}
ZoneEntry::CacheEntry exactNSEC3;
if (getNSEC3(now, zoneEntry, nameHash, exactNSEC3)) {
- VLOG(log, "Found a direct NSEC3 match for " << nameHash);
+ VLOG(log, name << ": Found a direct NSEC3 match for " << nameHash);
auto nsec3 = std::dynamic_pointer_cast<NSEC3RecordContent>(exactNSEC3.d_record);
if (!nsec3 || nsec3->d_iterations != iterations || nsec3->d_salt != salt) {
- VLOG(log, " but the content is not valid, or has a different salt or iterations count" << endl);
+ VLOG_NO_PREFIX(log, " but the content is not valid, or has a different salt or iterations count" << endl);
return false;
}
if (!isTypeDenied(nsec3, type)) {
- VLOG(log, " but the requested type (" << type.toString() << ") does exist" << endl);
+ VLOG_NO_PREFIX(log, " but the requested type (" << type.toString() << ") does exist" << endl);
return false;
}
that (original) owner name other than DS RRs, and all RRs below that
owner name regardless of type.
*/
- VLOG(log, " but this is an ancestor delegation NSEC3" << endl);
+ VLOG_NO_PREFIX(log, " but this is an ancestor delegation NSEC3" << endl);
return false;
}
if (type == QType::DS && !name.isRoot() && signer == name) {
- VLOG(log, " but this NSEC3 comes from the child zone and cannot be used to deny a DS");
+ VLOG_NO_PREFIX(log, " but this NSEC3 comes from the child zone and cannot be used to deny a DS");
return false;
}
return true;
}
- VLOG(log, "No direct NSEC3 match found for " << nameHash << ", looking for closest encloser" << endl);
+ VLOG(log, name << ": No direct NSEC3 match found for " << nameHash << ", looking for closest encloser" << endl);
DNSName closestEncloser(name);
bool found = false;
ZoneEntry::CacheEntry closestNSEC3;
auto closestHash = DNSName(toBase32Hex(hashQNameWithSalt(salt, iterations, closestEncloser))) + zone;
if (getNSEC3(now, zoneEntry, closestHash, closestNSEC3)) {
- VLOG(log, "Found closest encloser at " << closestEncloser << " (" << closestHash << ")" << endl);
+ VLOG(log, name << ": Found closest encloser at " << closestEncloser << " (" << closestHash << ")" << endl);
auto nsec3 = std::dynamic_pointer_cast<NSEC3RecordContent>(closestNSEC3.d_record);
if (!nsec3 || nsec3->d_iterations != iterations || nsec3->d_salt != salt) {
- VLOG(log, " but the content is not valid, or has a different salt or iterations count" << endl);
+ VLOG_NO_PREFIX(log, " but the content is not valid, or has a different salt or iterations count" << endl);
break;
}
that (original) owner name other than DS RRs, and all RRs below that
owner name regardless of type.
*/
- VLOG(log, " but this is an ancestor delegation NSEC3" << endl);
+ VLOG_NO_PREFIX(log, " but this is an ancestor delegation NSEC3" << endl);
break;
}
if (type == QType::DS && !name.isRoot() && signer == name) {
- VLOG(log, " but this NSEC3 comes from the child zone and cannot be used to deny a DS");
+ VLOG_NO_PREFIX(log, " but this NSEC3 comes from the child zone and cannot be used to deny a DS");
return false;
}
}
if (!found) {
- VLOG(log, "Nothing found for the closest encloser in NSEC3 aggressive cache either" << endl);
+ VLOG(log, name << ": Nothing found for the closest encloser in NSEC3 aggressive cache either" << endl);
return false;
}
DNSName nextCloser(closestEncloser);
nextCloser.prependRawLabel(name.getRawLabel(labelIdx - 1));
auto nextCloserHash = toBase32Hex(hashQNameWithSalt(salt, iterations, nextCloser));
- VLOG(log, "Looking for a NSEC3 covering the next closer " << nextCloser << " (" << nextCloserHash << ")" << endl);
+ VLOG(log, name << ": Looking for a NSEC3 covering the next closer " << nextCloser << " (" << nextCloserHash << ")" << endl);
ZoneEntry::CacheEntry nextCloserEntry;
if (!getNSECBefore(now, zoneEntry, DNSName(nextCloserHash) + zone, nextCloserEntry)) {
- VLOG(log, "Nothing found for the next closer in NSEC3 aggressive cache" << endl);
+ VLOG(log, name << ": Nothing found for the next closer in NSEC3 aggressive cache" << endl);
return false;
}
if (!isCoveredByNSEC3Hash(DNSName(nextCloserHash) + zone, nextCloserEntry.d_owner, nextCloserEntry.d_next)) {
- VLOG(log, "No covering record found for the next closer in NSEC3 aggressive cache" << endl);
+ VLOG(log, name << ": No covering record found for the next closer in NSEC3 aggressive cache" << endl);
return false;
}
auto nextCloserNsec3 = std::dynamic_pointer_cast<NSEC3RecordContent>(nextCloserEntry.d_record);
if (!nextCloserNsec3 || nextCloserNsec3->d_iterations != iterations || nextCloserNsec3->d_salt != salt) {
- VLOG(log, "The NSEC3 covering the next closer is not valid, or has a different salt or iterations count, bailing out" << endl);
+ VLOG(log, name << ": The NSEC3 covering the next closer is not valid, or has a different salt or iterations count, bailing out" << endl);
return false;
}
name (we don't insert opt-out NSEC3s into the cache). */
DNSName wildcard(g_wildcarddnsname + closestEncloser);
auto wcHash = toBase32Hex(hashQNameWithSalt(salt, iterations, wildcard));
- VLOG(log, "Looking for a NSEC3 covering the wildcard " << wildcard << " (" << wcHash << ")" << endl);
+ VLOG(log, name << ": Looking for a NSEC3 covering the wildcard " << wildcard << " (" << wcHash << ")" << endl);
ZoneEntry::CacheEntry wcEntry;
if (!getNSECBefore(now, zoneEntry, DNSName(wcHash) + zone, wcEntry)) {
- VLOG(log, "Nothing found for the wildcard in NSEC3 aggressive cache" << endl);
+ VLOG(log, name << ": Nothing found for the wildcard in NSEC3 aggressive cache" << endl);
return false;
}
if ((DNSName(wcHash) + zone) == wcEntry.d_owner) {
- VLOG(log, "Found an exact match for the wildcard");
+ VLOG(log, name << ": Found an exact match for the wildcard");
auto nsec3 = std::dynamic_pointer_cast<NSEC3RecordContent>(wcEntry.d_record);
if (!nsec3 || nsec3->d_iterations != iterations || nsec3->d_salt != salt) {
- VLOG(log, " but the content is not valid, or has a different salt or iterations count" << endl);
+ VLOG_NO_PREFIX(log, " but the content is not valid, or has a different salt or iterations count" << endl);
return false;
}
that (original) owner name other than DS RRs, and all RRs below that
owner name regardless of type.
*/
- VLOG(log, " but the NSEC3 covering the wildcard is an ancestor delegation NSEC3, bailing out" << endl);
+ VLOG_NO_PREFIX(log, " but the NSEC3 covering the wildcard is an ancestor delegation NSEC3, bailing out" << endl);
return false;
}
if (type == QType::DS && !name.isRoot() && wcSigner == name) {
- VLOG(log, " but this wildcard NSEC3 comes from the child zone and cannot be used to deny a DS");
+ VLOG_NO_PREFIX(log, " but this wildcard NSEC3 comes from the child zone and cannot be used to deny a DS");
return false;
}
if (!isTypeDenied(nsec3, type)) {
- VLOG(log, " but the requested type (" << type.toString() << ") does exist" << endl);
+ VLOG_NO_PREFIX(log, " but the requested type (" << type.toString() << ") does exist" << endl);
return synthesizeFromNSEC3Wildcard(now, name, type, ret, res, doDNSSEC, nextCloserEntry, wildcard, log);
}
}
else {
if (!isCoveredByNSEC3Hash(DNSName(wcHash) + zone, wcEntry.d_owner, wcEntry.d_next)) {
- VLOG(log, "No covering record found for the wildcard in aggressive cache" << endl);
+ VLOG(log, name << ": No covering record found for the wildcard in aggressive cache" << endl);
return false;
}
auto nsec3 = std::dynamic_pointer_cast<NSEC3RecordContent>(wcEntry.d_record);
if (!nsec3 || nsec3->d_iterations != iterations || nsec3->d_salt != salt) {
- VLOG(log, "The content of the NSEC3 covering the wildcard is not valid, or has a different salt or iterations count" << endl);
+ VLOG(log, name << ": The content of the NSEC3 covering the wildcard is not valid, or has a different salt or iterations count" << endl);
return false;
}
const DNSName wcSigner = getSigner(wcEntry.d_signatures);
if (type == QType::DS && !name.isRoot() && wcSigner == name) {
- VLOG(log, " but this wildcard NSEC3 comes from the child zone and cannot be used to deny a DS");
+ VLOG_NO_PREFIX(log, " but this wildcard NSEC3 comes from the child zone and cannot be used to deny a DS");
return false;
}
addRecordToRRSet(now, wcEntry.d_owner, QType::NSEC3, wcEntry.d_ttd - now, wcEntry.d_record, wcEntry.d_signatures, doDNSSEC, ret);
}
- VLOG(log, "Found valid NSEC3s covering the requested name and type!" << endl);
+ VLOG(log, name << ": Found valid NSEC3s covering the requested name and type!" << endl);
++d_nsec3Hits;
return true;
}
std::vector<std::shared_ptr<RRSIGRecordContent>> soaSignatures;
/* we might not actually need the SOA if we find a matching wildcard, but let's not bother for now */
if (g_recCache->get(now, zone, QType::SOA, MemRecursorCache::RequireAuth, &soaSet, who, routingTag, doDNSSEC ? &soaSignatures : nullptr, nullptr, nullptr, &cachedState) <= 0 || cachedState != vState::Secure) {
- VLOG(log, "No valid SOA found for " << zone << ", which is the best match for " << name << endl);
+ VLOG(log, name << ": No valid SOA found for " << zone << ", which is the best match for " << name << endl);
return false;
}
bool covered = false;
bool needWildcard = false;
- VLOG(log, "Looking for a NSEC before " << name);
+ VLOG(log, name << ": Looking for a NSEC before " << name);
if (!getNSECBefore(now, zoneEntry, name, entry)) {
- VLOG(log, ": nothing found in the aggressive cache" << endl);
+ VLOG_NO_PREFIX(log, ": nothing found in the aggressive cache" << endl);
return false;
}
return false;
}
- VLOG(log, ": found a possible NSEC at " << entry.d_owner << " ");
+ VLOG_NO_PREFIX(log, ": found a possible NSEC at " << entry.d_owner << " ");
// note that matchesNSEC() takes care of ruling out ancestor NSECs for us
auto denial = matchesNSEC(name, type.getCode(), entry.d_owner, content, entry.d_signatures, log);
if (denial == dState::NODENIAL || denial == dState::INCONCLUSIVE) {
- VLOG(log, " but it does no cover us" << endl);
+ VLOG_NO_PREFIX(log, " but it does no cover us" << endl);
return false;
}
else if (denial == dState::NXQTYPE) {
covered = true;
- VLOG(log, " and it proves that the type does not exist" << endl);
+ VLOG_NO_PREFIX(log, " and it proves that the type does not exist" << endl);
res = RCode::NoError;
}
else if (denial == dState::NXDOMAIN) {
- VLOG(log, " and it proves that the name does not exist" << endl);
+ VLOG_NO_PREFIX(log, " and it proves that the name does not exist" << endl);
DNSName closestEncloser = getClosestEncloserFromNSEC(name, entry.d_owner, entry.d_next);
DNSName wc = g_wildcarddnsname + closestEncloser;
- VLOG(log, "Now looking for a NSEC before the wildcard " << wc);
+ VLOG(log, name << ": Now looking for a NSEC before the wildcard " << wc);
if (!getNSECBefore(now, zoneEntry, wc, wcEntry)) {
- VLOG(log, ": nothing found in the aggressive cache" << endl);
+ VLOG_NO_PREFIX(log, ": nothing found in the aggressive cache" << endl);
return false;
}
- VLOG(log, ": found a possible NSEC at " << wcEntry.d_owner << " ");
+ VLOG_NO_PREFIX(log, ": found a possible NSEC at " << wcEntry.d_owner << " ");
auto nsecContent = std::dynamic_pointer_cast<NSECRecordContent>(wcEntry.d_record);
if (denial == dState::NODENIAL || denial == dState::INCONCLUSIVE) {
if (wcEntry.d_owner == wc) {
- VLOG(log, " proving that the wildcard does exist" << endl);
+ VLOG_NO_PREFIX(log, " proving that the wildcard does exist" << endl);
return synthesizeFromNSECWildcard(now, name, type, ret, res, doDNSSEC, entry, wc, log);
}
- VLOG(log, " but it does no cover us" << endl);
+ VLOG_NO_PREFIX(log, " but it does no cover us" << endl);
return false;
}
else if (denial == dState::NXQTYPE) {
- VLOG(log, " and it proves that there is a matching wildcard, but the type does not exist" << endl);
+ VLOG_NO_PREFIX(log, " and it proves that there is a matching wildcard, but the type does not exist" << endl);
covered = true;
res = RCode::NoError;
}
else if (denial == dState::NXDOMAIN) {
- VLOG(log, " and it proves that there is no matching wildcard" << endl);
+ VLOG_NO_PREFIX(log, " and it proves that there is no matching wildcard" << endl);
covered = true;
res = RCode::NXDomain;
}
addRecordToRRSet(now, wcEntry.d_owner, QType::NSEC, wcEntry.d_ttd - now, wcEntry.d_record, wcEntry.d_signatures, doDNSSEC, ret);
}
- VLOG(log, "Found valid NSECs covering the requested name and type!" << endl);
+ VLOG(log, name << ": Found valid NSECs covering the requested name and type!" << endl);
++d_nsecHits;
return true;
}
dr.d_place = DNSResourceRecord::AUTHORITY;
records.push_back(dr);
}
- else {
- // cerr<<qname<<": can't find SOA record '"<<getName()<<"' in our zone!"<<endl;
- }
}
bool SyncRes::AuthDomain::operator==(const AuthDomain& rhs) const
if (!records.empty()) {
/* We have found an exact match, we're done */
- // cerr<<qname<<": exact match in zone '"<<getName()<<"'"<<endl;
return result;
}
if (somedata) {
/* We have records for that name, but not of the wanted qtype */
- // cerr<<qname<<": found record in '"<<getName()<<"', but nothing of the right type, sending SOA"<<endl;
addSOA(records);
return result;
}
- // cerr<<qname<<": nothing found so far in '"<<getName()<<"', trying wildcards"<<endl;
DNSName wcarddomain(qname);
while (wcarddomain != getName() && wcarddomain.chopOff()) {
- // cerr<<qname<<": trying '*."<<wcarddomain<<"' in "<<getName()<<endl;
range = d_records.equal_range(std::make_tuple(g_wildcarddnsname + wcarddomain));
if (range.first == range.second)
continue;
addSOA(records);
}
- // cerr<<qname<<": in '"<<getName()<<"', had wildcard match on '*."<<wcarddomain<<"'"<<endl;
return result;
}
}
if (records.empty()) {
- // cerr<<qname<<": no NS match in zone '"<<getName()<<"' either, handing out SOA"<<endl;
addSOA(records);
result = RCode::NXDomain;
}
DNSName authdomain(qname);
domainmap_t::const_iterator iter = getBestAuthZone(&authdomain);
if (iter == t_sstorage.domainmap->end() || !iter->second.isAuth()) {
- LOG(prefix << qname << ": auth storage has no zone for this query!" << endl);
+ LOG(prefix << qname << ": Auth storage has no zone for this query!" << endl);
return false;
}
- LOG(prefix << qname << ": auth storage has data, zone='" << authdomain << "'" << endl);
+ LOG(prefix << qname << ": Auth storage has data, zone='" << authdomain << "'" << endl);
return doOOBResolve(iter->second, qname, qtype, ret, res);
}
{
auto prefix = getPrefix(depth);
- LOG(prefix << qname << ": Wants " << (d_doDNSSEC ? "" : "NO ") << "DNSSEC processing, " << (d_requireAuthData ? "" : "NO ") << "auth data in query for " << qtype << endl);
+ LOG(prefix << qname << ": Wants " << (d_doDNSSEC ? "" : "NO ") << "DNSSEC processing, " << (d_requireAuthData ? "" : "NO ") << "auth data required by query for " << qtype << endl);
if (s_maxdepth > 0 && depth > s_maxdepth) {
string msg = "More than " + std::to_string(s_maxdepth) + " (max-recursion-depth) levels of recursion needed while resolving " + qname.toLogString();
if (d_cacheonly) {
if (iter != t_sstorage.domainmap->end()) {
if (iter->second.isAuth()) {
- LOG(prefix << qname << ": cache only lookup for '" << qname << "|" << qtype << "', in auth zone" << endl);
+ LOG(prefix << qname << ": Cache only lookup for '" << qname << "|" << qtype << "', in auth zone" << endl);
ret.clear();
d_wasOutOfBand = doOOBResolve(qname, qtype, ret, depth, prefix, res);
if (fromCache != nullptr) {
return 0;
}
- LOG(prefix << qname << ": failed (res=" << res << ")" << endl);
+ LOG(prefix << qname << ": Failed (res=" << res << ")" << endl);
if (res >= 0) {
break;
}
}
if (doLog()) {
- LOG(prefix << "Nameserver " << qname << " IPs: ");
+ LOG(prefix << qname << ": Nameserver " << qname << " IPs: ");
bool first = true;
for (const auto& addr : ret) {
if (first) {
auto nrr = getRR<NSRecordContent>(dr);
if (nrr && (!nrr->getNS().isPartOf(subdomain) || g_recCache->get(d_now.tv_sec, nrr->getNS(), nsqt, flags, doLog() ? &aset : 0, d_cacheRemote, d_routingTag) > 0)) {
bestns.push_back(dr);
- LOG(prefix << qname << ": NS (with ip, or non-glue) in cache for '" << subdomain << "' -> '" << nrr->getNS() << "'" << endl);
- LOG(prefix << qname << ": within bailiwick: " << nrr->getNS().isPartOf(subdomain));
+ LOG(prefix << qname << ": NS (with ip, or non-glue) in cache for '" << subdomain << "' -> '" << nrr->getNS() << "'");
+ LOG(", within bailiwick: " << nrr->getNS().isPartOf(subdomain));
if (!aset.empty()) {
- LOG(", in cache, ttl=" << (unsigned int)(((time_t)aset.begin()->d_ttl - d_now.tv_sec)) << endl);
+ LOG(", in cache, ttl=" << (unsigned int)(((time_t)aset.begin()->d_ttl - d_now.tv_sec)) << endl);
}
else {
LOG(", not in cache / did not look at cache" << endl);
if (doLog())
for (set<GetBestNSAnswer>::const_iterator j = beenthere.begin(); j != beenthere.end(); ++j) {
bool neo = (j == insertionPair.first);
- LOG(prefix << qname << ": beenthere" << (neo ? "*" : "") << ": " << j->qname << "|" << DNSRecordContent::NumberToType(j->qtype) << " (" << (unsigned int)j->bestns.size() << ")" << endl);
+ LOG(prefix << qname << ": Beenthere" << (neo ? "*" : "") << ": " << j->qname << "|" << DNSRecordContent::NumberToType(j->qtype) << " (" << (unsigned int)j->bestns.size() << ")" << endl);
}
bestns.clear();
}
}
}
}
- LOG(prefix << qname << ": no valid/useful NS in cache for '" << subdomain << "'" << endl);
+ LOG(prefix << qname << ": No valid/useful NS in cache for '" << subdomain << "'" << endl);
if (subdomain.isRoot() && !brokeloop) {
// We lost the root NS records
primeHints();
- LOG(prefix << qname << ": reprimed the root" << endl);
+ LOG(prefix << qname << ": Reprimed the root" << endl);
/* let's prevent an infinite loop */
if (!d_updatingRootNS) {
auto log = g_slog->withName("housekeeping");
// So queries that get NS for authOrForwDomain itself go to the forwarder
if (authOrForwDomain.isPartOf(nsFromCacheDomain)) {
if (doLog()) {
- LOG(prefix << qname << ": using forwarder as NS" << endl);
+ LOG(prefix << qname << ": Using forwarder as NS" << endl);
}
nsset.insert({DNSName(), {iter->second.d_servers, false}});
return authOrForwDomain;
}
else {
if (doLog()) {
- LOG(prefix << qname << ": using NS from cache" << endl);
+ LOG(prefix << qname << ": Using NS from cache" << endl);
}
}
}
bool SyncRes::doCNAMECacheCheck(const DNSName& qname, const QType qtype, vector<DNSRecord>& ret, unsigned int depth, const string& prefix, int& res, Context& context, bool wasAuthZone, bool wasForwardRecurse)
{
if ((depth > 9 && d_outqueries > 10 && d_throttledqueries > 5) || depth > 15) {
- LOG(prefix << qname << ": recursing (CNAME or other indirection) too deep, depth=" << depth << endl);
+ LOG(prefix << qname << ": Recursing (CNAME or other indirection) too deep, depth=" << depth << endl);
res = RCode::ServFail;
return true;
}
vState recordState = getValidationStatus(foundName, !signatures.empty(), qtype == QType::DS, depth, prefix);
if (recordState == vState::Secure) {
- LOG(prefix << qname << ": got vState::Indeterminate state from the " << foundQT.toString() << " cache, validating.." << endl);
+ LOG(prefix << qname << ": Got vState::Indeterminate state from the " << foundQT.toString() << " cache, validating.." << endl);
context.state = SyncRes::validateRecordsWithSigs(depth, prefix, qname, qtype, foundName, foundQT, cset, signatures);
if (context.state != vState::Indeterminate) {
- LOG(prefix << qname << ": got vState::Indeterminate state from the " << foundQT.toString() << " cache, new validation result is " << context.state << endl);
+ LOG(prefix << qname << ": Got vState::Indeterminate state from the " << foundQT.toString() << " cache, new validation result is " << context.state << endl);
if (vStateIsBogus(context.state)) {
capTTL = s_maxbogusttl;
}
}
if (qname == newTarget) {
- string msg = "got a CNAME referral (from cache) to self";
+ string msg = "Got a CNAME referral (from cache) to self";
LOG(prefix << qname << ": " << msg << endl);
throw ImmediateServFailException(msg);
}
if (newTarget.isPartOf(qname)) {
// a.b.c. CNAME x.a.b.c will go to great depths with QM on
- string msg = "got a CNAME referral (from cache) to child, disabling QM";
+ string msg = "Got a CNAME referral (from cache) to child, disabling QM";
LOG(prefix << qname << ": " << msg << endl);
setQNameMinimization(false);
}
// Check to see if we already have seen the new target as a previous target
if (scanForCNAMELoop(newTarget, ret)) {
string msg = "got a CNAME referral (from cache) that causes a loop";
- LOG(prefix << qname << ": status=" << msg << endl);
+ LOG(prefix << qname << ": Status=" << msg << endl);
throw ImmediateServFailException(msg);
}
// Be aware that going out on the network might be disabled (cache-only), for example because we are in QM Step0,
// so you can't trust that a real lookup will have been made.
res = doResolve(newTarget, qtype, ret, depth + 1, beenthere, cnameContext);
- LOG(prefix << qname << ": updating validation state for response to " << qname << " from " << context.state << " with the state from the DNAME/CNAME quest: " << cnameContext.state << endl);
- updateValidationState(context.state, cnameContext.state, prefix);
+ LOG(prefix << qname << ": Updating validation state for response to " << qname << " from " << context.state << " with the state from the DNAME/CNAME quest: " << cnameContext.state << endl);
+ updateValidationState(qname, context.state, cnameContext.state, prefix);
return true;
}
}
if (recordState != vState::Indeterminate && recordState != state) {
- updateValidationState(state, recordState, prefix);
+ updateValidationState(qname, state, recordState, prefix);
if (state != vState::Secure) {
break;
}
vState neValidationState = ne.d_validationState;
dState expectedState = res == RCode::NXDomain ? dState::NXDOMAIN : dState::NXQTYPE;
dState denialState = getDenialValidationState(ne, expectedState, false, prefix);
- updateDenialValidationState(neValidationState, ne.d_name, state, denialState, expectedState, qtype == QType::DS, depth, prefix);
+ updateDenialValidationState(qname, neValidationState, ne.d_name, state, denialState, expectedState, qtype == QType::DS, depth, prefix);
}
if (state != vState::Indeterminate) {
/* validation succeeded, let's update the cache entry so we don't have to validate again */
giveNegative = true;
cachedState = ne.d_validationState;
if (ne.d_qtype.getCode()) {
- LOG(prefix << qname << ": " << qtype << " is negatively cached via '" << ne.d_auth << "' for another " << sttl << " seconds" << endl);
+ LOG(prefix << qname << "|" << qtype << ": Is negatively cached via '" << ne.d_auth << "' for another " << sttl << " seconds" << endl);
res = RCode::NoError;
if (s_addExtendedResolutionDNSErrors) {
context.extendedError = EDNSExtendedError{0, "Result from negative cache"};
context.state = cachedState;
if (!wasAuthZone && shouldValidate() && context.state == vState::Indeterminate) {
- LOG(prefix << qname << ": got vState::Indeterminate state for records retrieved from the negative cache, validating.." << endl);
+ LOG(prefix << qname << ": Got vState::Indeterminate state for records retrieved from the negative cache, validating.." << endl);
computeNegCacheValidationStatus(ne, qname, qtype, res, context.state, depth, prefix);
if (context.state != cachedState && vStateIsBogus(context.state)) {
addTTLModifiedRecords(ne.DNSSECRecords.signatures, sttl, ret);
}
- LOG(prefix << qname << ": updating validation state with negative cache content for " << qname << " to " << context.state << endl);
+ LOG(prefix << qname << ": Updating validation state with negative cache content for " << qname << " to " << context.state << endl);
return true;
}
vState recordState = getValidationStatus(qname, !signatures.empty(), qtype == QType::DS, depth, prefix);
if (recordState == vState::Secure) {
- LOG(prefix << sqname << ": got vState::Indeterminate state from the cache, validating.." << endl);
+ LOG(prefix << sqname << ": Got vState::Indeterminate state from the cache, validating.." << endl);
if (sqt == QType::DNSKEY && sqname == getSigner(signatures)) {
cachedState = validateDNSKeys(sqname, cset, signatures, depth, prefix);
}
}
if (cachedState != vState::Indeterminate) {
- LOG(prefix << qname << ": got vState::Indeterminate state from the cache, validation result is " << cachedState << endl);
+ LOG(prefix << qname << ": Got vState::Indeterminate state from the cache, validation result is " << cachedState << endl);
if (vStateIsBogus(cachedState)) {
capTTL = s_maxbogusttl;
}
if (found && !expired) {
if (!giveNegative)
res = 0;
- LOG(prefix << qname << ": updating validation state with cache content for " << qname << " to " << cachedState << endl);
+ LOG(prefix << qname << ": Updating validation state with cache content for " << qname << " to " << cachedState << endl);
context.state = cachedState;
return true;
}
else
- LOG(prefix << qname << ": cache had only stale entries" << endl);
+ LOG(prefix << qname << ": Cache had only stale entries" << endl);
}
/* let's check if we have a NSEC covering that record */
}
};
-inline std::vector<std::pair<DNSName, float>> SyncRes::shuffleInSpeedOrder(NsSet& tnameservers, const string& prefix)
+std::vector<std::pair<DNSName, float>> SyncRes::shuffleInSpeedOrder(const DNSName& qname, NsSet& tnameservers, const string& prefix)
{
std::vector<std::pair<DNSName, float>> rnameservers;
rnameservers.reserve(tnameservers.size());
stable_sort(rnameservers.begin(), rnameservers.end(), so);
if (doLog()) {
- LOG(prefix << "Nameservers: ");
+ LOG(prefix << qname << ": Nameservers: ");
for (auto i = rnameservers.begin(); i != rnameservers.end(); ++i) {
if (i != rnameservers.begin()) {
LOG(", ");
return rnameservers;
}
-inline vector<ComboAddress> SyncRes::shuffleForwardSpeed(const vector<ComboAddress>& rnameservers, const string& prefix, const bool wasRd)
+vector<ComboAddress> SyncRes::shuffleForwardSpeed(const DNSName &qname, const vector<ComboAddress>& rnameservers, const string& prefix, const bool wasRd)
{
vector<ComboAddress> nameservers = rnameservers;
map<ComboAddress, float> speeds;
stable_sort(nameservers.begin(), nameservers.end(), so);
if (doLog()) {
- LOG(prefix << "Nameservers: ");
+ LOG(prefix << qname << ": Nameservers: ");
for (vector<ComboAddress>::const_iterator i = nameservers.cbegin(); i != nameservers.cend(); ++i) {
if (i != nameservers.cbegin()) {
LOG(", ");
}
if (d_appliedPolicy.d_type != DNSFilterEngine::PolicyType::None) {
- LOG(prefix << qname << "|" << qtype << d_appliedPolicy.getLogString() << endl);
+ LOG(prefix << qname << "|" << qtype << ':' << d_appliedPolicy.getLogString() << endl);
}
switch (d_appliedPolicy.d_kind) {
LOG(endl);
sendRDQuery = nameservers[tns->first].second;
- result = shuffleForwardSpeed(nameservers[tns->first].first, doLog() ? (prefix + qname.toString() + ": ") : string(), sendRDQuery);
+ result = shuffleForwardSpeed(qname, nameservers[tns->first].first, prefix, sendRDQuery);
pierceDontQuery = true;
}
return result;
bool SyncRes::throttledOrBlocked(const std::string& prefix, const ComboAddress& remoteIP, const DNSName& qname, const QType qtype, bool pierceDontQuery)
{
if (isThrottled(d_now.tv_sec, remoteIP)) {
- LOG(prefix << qname << ": server throttled " << endl);
+ LOG(prefix << qname << ": Server throttled " << endl);
t_Counters.at(rec::Counter::throttledqueries)++;
d_throttledqueries++;
return true;
}
else if (isThrottled(d_now.tv_sec, remoteIP, qname, qtype)) {
- LOG(prefix << qname << ": query throttled " << remoteIP.toString() << ", " << qname << "; " << qtype << endl);
+ LOG(prefix << qname << ": Query throttled " << remoteIP.toString() << ", " << qname << "; " << qtype << endl);
t_Counters.at(rec::Counter::throttledqueries)++;
d_throttledqueries++;
return true;
DNSName forwardCandidate(qname);
auto it = getBestAuthZone(&forwardCandidate);
if (it == t_sstorage.domainmap->end()) {
- LOG(prefix << qname << ": not sending query to " << remoteIP.toString() << ", blocked by 'dont-query' setting" << endl);
+ LOG(prefix << qname << ": Not sending query to " << remoteIP.toString() << ", blocked by 'dont-query' setting" << endl);
t_Counters.at(rec::Counter::dontqueries)++;
return true;
}
// The name (from the cache) is forwarded, but is it forwarded to an IP in known forwarders?
const auto& ips = it->second.d_servers;
if (std::find(ips.cbegin(), ips.cend(), remoteIP) == ips.cend()) {
- LOG(prefix << qname << ": not sending query to " << remoteIP.toString() << ", blocked by 'dont-query' setting" << endl);
+ LOG(prefix << qname << ": Not sending query to " << remoteIP.toString() << ", blocked by 'dont-query' setting" << endl);
t_Counters.at(rec::Counter::dontqueries)++;
return true;
}
else {
- LOG(prefix << qname << ": sending query to " << remoteIP.toString() << ", blocked by 'dont-query' but a forwarding/auth case" << endl);
+ LOG(prefix << qname << ": Sending query to " << remoteIP.toString() << ", blocked by 'dont-query' but a forwarding/auth case" << endl);
}
}
}
return lowestTTD;
}
-void SyncRes::updateValidationState(vState& state, const vState stateUpdate, const string& prefix)
+void SyncRes::updateValidationState(const DNSName& qname, vState& state, const vState stateUpdate, const string& prefix)
{
- LOG(prefix << "validation state was " << state << ", state update is " << stateUpdate);
+ LOG(prefix << qname << ": Validation state was " << state << ", state update is " << stateUpdate);
updateDNSSECValidationState(state, stateUpdate);
LOG(", validation state is now " << state << endl);
}
auto luaLocal = g_luaconfs.getLocal();
if (luaLocal->dsAnchors.empty()) {
- LOG(prefix << ": No trust anchors configured, everything is Insecure" << endl);
+ LOG(prefix << zone << ": No trust anchors configured, everything is Insecure" << endl);
/* We have no TA, everything is insecure */
return vState::Insecure;
}
std::string reason;
if (haveNegativeTrustAnchor(luaLocal->negAnchors, zone, reason)) {
- LOG(prefix << ": got NTA for '" << zone << "'" << endl);
+ LOG(prefix << zone << ": Got NTA" << endl);
return vState::NTA;
}
if (getTrustAnchor(luaLocal->dsAnchors, zone, ds)) {
- LOG(prefix << ": got TA for '" << zone << "'" << endl);
+ if (!zone.isRoot()) {
+ LOG(prefix << zone << ": Got TA" << endl);
+ }
return vState::TA;
}
- else {
- LOG(prefix << ": no TA found for '" << zone << "' among " << luaLocal->dsAnchors.size() << endl);
- }
if (zone.isRoot()) {
/* No TA for the root */
return context.state;
}
- LOG(prefix << ": returning Bogus state from " << __func__ << "(" << zone << ")" << endl);
+ LOG(prefix << zone << ": Returning Bogus state from " << __func__ << "(" << zone << ")" << endl);
return vState::BogusUnableToGetDSs;
}
{
const auto& it = d_cutStates.find(subdomain);
if (it != d_cutStates.cend()) {
- LOG(prefix << ": got status " << it->second << " for name " << subdomain << endl);
+ LOG(prefix << name << ": Got status " << it->second << " for name " << subdomain << endl);
return it->second;
}
}
if (it != d_cutStates.cend()) {
result = it->second;
if (vStateIsBogus(result) || result == vState::Insecure) {
- LOG(prefix << ": got status " << result << " for name " << best << endl);
+ LOG(prefix << name << ": Got status " << result << " for name " << best << endl);
return result;
}
break;
we will if we don't have a signature, or if the signer doesn't match what we expect */
if (!wouldBeValid && best != subdomain) {
/* no signatures or Bogus, we likely missed a cut, let's try to find it */
- LOG(prefix << ": no or invalid signature/proof for " << name << ", we likely missed a cut between " << best << " and " << subdomain << ", looking for it" << endl);
+ LOG(prefix << name << ": No or invalid signature/proof for " << name << ", we likely missed a cut between " << best << " and " << subdomain << ", looking for it" << endl);
DNSName ds(best);
std::vector<string> labelsToAdd = subdomain.makeRelative(ds).getRawLabels();
ds.prependRawLabel(labelsToAdd.back());
labelsToAdd.pop_back();
- LOG(prefix << ": - Looking for a DS at " << ds << endl);
+ LOG(prefix << name << ": - Looking for a DS at " << ds << endl);
bool foundCut = false;
dsmap_t results;
vState dsState = getDSRecords(ds, results, false, depth, prefix, false, &foundCut);
if (foundCut) {
- LOG(prefix << ": - Found cut at " << ds << endl);
- LOG(prefix << ": New state for " << ds << " is " << dsState << endl);
+ LOG(prefix << name << ": - Found cut at " << ds << endl);
+ LOG(prefix << name << ": New state for " << ds << " is " << dsState << endl);
d_cutStates[ds] = dsState;
if (dsState != vState::Secure) {
{
dsmap_t ds;
if (signatures.empty()) {
- LOG(prefix << ": we have " << std::to_string(dnskeys.size()) << " DNSKEYs but no signature, going Bogus!" << endl);
+ LOG(prefix << zone << ": We have " << std::to_string(dnskeys.size()) << " DNSKEYs but no signature, going Bogus!" << endl);
return vState::BogusNoRRSIG;
}
}
}
else {
- LOG(prefix << ": we have " << std::to_string(dnskeys.size()) << " DNSKEYs but the zone (" << zone << ") is not part of the signer (" << signer << "), check that we did not miss a zone cut" << endl);
+ LOG(prefix << zone << ": We have " << std::to_string(dnskeys.size()) << " DNSKEYs but the zone (" << zone << ") is not part of the signer (" << signer << "), check that we did not miss a zone cut" << endl);
/* try again to get the missed cuts, harder this time */
auto zState = getValidationStatus(zone, false, false, depth, prefix);
if (zState == vState::Secure) {
/* too bad */
- LOG(prefix << ": after checking the zone cuts again, we still have " << std::to_string(dnskeys.size()) << " DNSKEYs and the zone (" << zone << ") is still not part of the signer (" << signer << "), going Bogus!" << endl);
+ LOG(prefix << zone << ": After checking the zone cuts again, we still have " << std::to_string(dnskeys.size()) << " DNSKEYs and the zone (" << zone << ") is still not part of the signer (" << signer << "), going Bogus!" << endl);
return vState::BogusNoValidRRSIG;
}
else {
}
}
- LOG(prefix << ": trying to validate " << std::to_string(tentativeKeys.size()) << " DNSKEYs with " << std::to_string(ds.size()) << " DS" << endl);
+ LOG(prefix << zone << ": Trying to validate " << std::to_string(tentativeKeys.size()) << " DNSKEYs with " << std::to_string(ds.size()) << " DS" << endl);
skeyset_t validatedKeys;
auto state = validateDNSKeysAgainstDS(d_now.tv_sec, zone, ds, tentativeKeys, toSign, signatures, validatedKeys, LogObject(prefix));
- LOG(prefix << ": we now have " << std::to_string(validatedKeys.size()) << " DNSKEYs" << endl);
+ LOG(prefix << zone << ": We now have " << std::to_string(validatedKeys.size()) << " DNSKEYs" << endl);
/* if we found at least one valid RRSIG covering the set,
all tentative keys are validated keys. Otherwise it means
we haven't found at least one DNSKEY and a matching RRSIG
covering this set, this looks Bogus. */
if (validatedKeys.size() != tentativeKeys.size()) {
- LOG(prefix << ": let's check whether we missed a zone cut before returning a Bogus state from " << __func__ << "(" << zone << ")" << endl);
+ LOG(prefix << zone << ": Let's check whether we missed a zone cut before returning a Bogus state from " << __func__ << "(" << zone << ")" << endl);
/* try again to get the missed cuts, harder this time */
auto zState = getValidationStatus(zone, false, false, depth, prefix);
if (zState == vState::Secure) {
/* too bad */
- LOG(prefix << ": after checking the zone cuts we are still in a Secure zone, returning Bogus state from " << __func__ << "(" << zone << ")" << endl);
+ LOG(prefix << zone << ": After checking the zone cuts we are still in a Secure zone, returning Bogus state from " << __func__ << "(" << zone << ")" << endl);
return state;
}
else {
{
std::vector<DNSRecord> records;
std::set<GetBestNSAnswer> beenthere;
- LOG(prefix << "Retrieving DNSKeys for " << signer << endl);
+ LOG(prefix << signer << ": Retrieving DNSKeys" << endl);
Context context;
}
}
}
- LOG(prefix << "Retrieved " << keys.size() << " DNSKeys for " << signer << ", state is " << context.state << endl);
+ LOG(prefix << signer << ": Retrieved " << keys.size() << " DNSKeys, state is " << context.state << endl);
return context.state;
}
return context.state;
}
- LOG(prefix << "Returning Bogus state from " << __func__ << "(" << signer << ")" << endl);
+ LOG(prefix << signer << ": Returning Bogus state from " << __func__ << "(" << signer << ")" << endl);
return vState::BogusUnableToGetDNSKEYs;
}
{
skeyset_t keys;
if (signatures.empty()) {
- LOG(prefix << "Bogus!" << endl);
+ LOG(prefix << qname << ": Bogus!" << endl);
return vState::BogusNoRRSIG;
}
/* Unless we are getting the DS of the root zone, we should never see a
DS (or a denial of a DS) signed by the DS itself, since we should be
requesting it from the parent zone. Something is very wrong */
- LOG(prefix << "The DS for " << qname << " is signed by itself" << endl);
+ LOG(prefix << qname << ": The DS for " << qname << " is signed by itself" << endl);
state = vState::BogusSelfSignedDS;
dsFailed = true;
}
}
}
else {
- LOG(prefix << "Unable to get the DS for " << signer << endl);
+ LOG(prefix << qname << ": Unable to get the DS for " << signer << endl);
state = vState::BogusUnableToGetDNSKEYs;
dsFailed = true;
}
/* return immediately since looking at the cuts is not going to change the
fact that we are looking at a signature done with the key we are trying to
obtain */
- LOG(prefix << "we are looking at a signature done with the key we are trying to obtain " << signer << endl);
+ LOG(prefix << qname << ": We are looking at a signature done with the key we are trying to obtain " << signer << endl);
return vState::Indeterminate;
}
}
}
bool servFailOccurred = false;
if (state == vState::Secure) {
- LOG(prefix << "retrieving the DNSKEYs for " << signer << endl);
+ LOG(prefix << signer << ": Retrieving the DNSKEYs" << endl);
state = getDNSKeys(signer, keys, servFailOccurred, depth, prefix);
}
return state;
}
/* try again to get the missed cuts, harder this time */
- LOG(prefix << "checking whether we missed a zone cut for " << signer << " before returning a Bogus state for " << name << "|" << type.toString() << endl);
+ LOG(prefix << signer << ": Checking whether we missed a zone cut for " << signer << " before returning a Bogus state for " << name << "|" << type.toString() << endl);
auto zState = getValidationStatus(signer, false, dsFailed, depth, prefix);
if (zState == vState::Secure) {
if (state == vState::BogusUnableToGetDNSKEYs && servFailOccurred) {
throw ImmediateServFailException("Server Failure while retrieving DNSKEY records for " + signer.toLogString());
}
/* too bad */
- LOG(prefix << "we are still in a Secure zone, returning " << vStateToString(state) << endl);
+ LOG(prefix << signer << ": We are still in a Secure zone, returning " << vStateToString(state) << endl);
return state;
}
else {
recordcontents.insert(record.d_content);
}
- LOG(prefix << "Going to validate " << recordcontents.size() << " record contents with " << signatures.size() << " sigs and " << keys.size() << " keys for " << name << "|" << type.toString() << endl);
+ LOG(prefix << name << ": Going to validate " << recordcontents.size() << " record contents with " << signatures.size() << " sigs and " << keys.size() << " keys for " << name << "|" << type.toString() << endl);
vState state = validateWithKeySet(d_now.tv_sec, name, recordcontents, signatures, keys, LogObject(prefix), false);
if (state == vState::Secure) {
- LOG(prefix << "Secure!" << endl);
+ LOG(prefix << name << ": Secure!" << endl);
return vState::Secure;
}
LOG(prefix << vStateToString(state) << "!" << endl);
/* try again to get the missed cuts, harder this time */
auto zState = getValidationStatus(name, false, type == QType::DS, depth, prefix);
- LOG(prefix << "checking whether we missed a zone cut before returning a Bogus state" << endl);
+ LOG(prefix << name << ": Checking whether we missed a zone cut before returning a Bogus state" << endl);
if (zState == vState::Secure) {
/* too bad */
- LOG(prefix << "we are still in a Secure zone, returning " << vStateToString(state) << endl);
+ LOG(prefix << name << ": We are still in a Secure zone, returning " << vStateToString(state) << endl);
return state;
}
else {
if (rec.d_place == DNSResourceRecord::ANSWER && (rec.d_type == qtype || rec.d_type == QType::CNAME || qtype == QType::ANY) && rec.d_name == qname && rec.d_name.isPartOf(auth)) {
/* This is clearly an answer to the question we were asking, from an authoritative server that is allowed to send it.
We are going to assume this server is broken and does not know it should set the AA bit, even though it is DNS 101 */
- LOG(prefix << "Received a record for " << rec.d_name << "|" << DNSRecordContent::NumberToType(rec.d_type) << " in the answer section from " << auth << ", without the AA bit set. Assuming this server is clueless and setting the AA bit." << endl);
+ LOG(prefix << qname << ": Received a record for " << rec.d_name << "|" << DNSRecordContent::NumberToType(rec.d_type) << " in the answer section from " << auth << ", without the AA bit set. Assuming this server is clueless and setting the AA bit." << endl);
lwr.d_aabit = true;
return;
}
}
if (rec->d_class != QClass::IN) {
- LOG(prefix << "Removing non internet-classed data received from " << auth << endl);
+ LOG(prefix << qname << ": Removing non internet-classed data received from " << auth << endl);
rec = lwr.d_records.erase(rec);
continue;
}
if (rec->d_type == QType::ANY) {
- LOG(prefix << "Removing 'ANY'-typed data received from " << auth << endl);
+ LOG(prefix << qname << ": Removing 'ANY'-typed data received from " << auth << endl);
rec = lwr.d_records.erase(rec);
continue;
}
if (!rec->d_name.isPartOf(auth)) {
- LOG(prefix << "Removing record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the " << (int)rec->d_place << " section received from " << auth << endl);
+ LOG(prefix << qname << ": Removing record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the " << (int)rec->d_place << " section received from " << auth << endl);
rec = lwr.d_records.erase(rec);
continue;
}
/* for now we allow a CNAME for the exact qname in ANSWER with AA=0, because Amazon DNS servers
are sending such responses */
if (!(rec->d_type == QType::CNAME && qname == rec->d_name)) {
- LOG(prefix << "Removing record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the answer section without the AA bit set received from " << auth << endl);
+ LOG(prefix << qname << ": Removing record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the answer section without the AA bit set received from " << auth << endl);
rec = lwr.d_records.erase(rec);
continue;
}
}
if (rec->d_type == QType::DNAME && (rec->d_place != DNSResourceRecord::ANSWER || !qname.isPartOf(rec->d_name))) {
- LOG(prefix << "Removing invalid DNAME record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the " << (int)rec->d_place << " section received from " << auth << endl);
+ LOG(prefix << qname << ": Removing invalid DNAME record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the " << (int)rec->d_place << " section received from " << auth << endl);
rec = lwr.d_records.erase(rec);
continue;
}
if (rec->d_place == DNSResourceRecord::ANSWER && (qtype != QType::ANY && rec->d_type != qtype.getCode() && s_redirectionQTypes.count(rec->d_type) == 0 && rec->d_type != QType::SOA && rec->d_type != QType::RRSIG)) {
- LOG(prefix << "Removing irrelevant record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the ANSWER section received from " << auth << endl);
+ LOG(prefix << qname << ": Removing irrelevant record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the ANSWER section received from " << auth << endl);
rec = lwr.d_records.erase(rec);
continue;
}
/* dealing with the records in authority */
if (rec->d_place == DNSResourceRecord::AUTHORITY && rec->d_type != QType::NS && rec->d_type != QType::DS && rec->d_type != QType::SOA && rec->d_type != QType::RRSIG && rec->d_type != QType::NSEC && rec->d_type != QType::NSEC3) {
- LOG(prefix << "Removing irrelevant record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the AUTHORITY section received from " << auth << endl);
+ LOG(prefix << qname << ": Removing irrelevant record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the AUTHORITY section received from " << auth << endl);
rec = lwr.d_records.erase(rec);
continue;
}
if (rec->d_place == DNSResourceRecord::AUTHORITY && rec->d_type == QType::SOA) {
if (!qname.isPartOf(rec->d_name)) {
- LOG(prefix << "Removing irrelevant SOA record '" << rec->d_name << "|" << rec->d_content->getZoneRepresentation() << "' in the AUTHORITY section received from " << auth << endl);
+ LOG(prefix << qname << ": Removing irrelevant SOA record '" << rec->d_name << "|" << rec->d_content->getZoneRepresentation() << "' in the AUTHORITY section received from " << auth << endl);
rec = lwr.d_records.erase(rec);
continue;
}
if (!(lwr.d_aabit || wasForwardRecurse)) {
- LOG(prefix << "Removing irrelevant record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the AUTHORITY section received from " << auth << endl);
+ LOG(prefix << qname << ": Removing irrelevant record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the AUTHORITY section received from " << auth << endl);
rec = lwr.d_records.erase(rec);
continue;
}
* because they are somewhat easy to insert into a large, fragmented UDP response
* for an off-path attacker by injecting spoofed UDP fragments. So do not add these to allowedAdditionals.
*/
- LOG(prefix << "Removing NS record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the " << (int)rec->d_place << " section of a " << (isNXDomain ? "NXD" : "NXQTYPE") << " response received from " << auth << endl);
+ LOG(prefix << qname << ": Removing NS record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the " << (int)rec->d_place << " section of a " << (isNXDomain ? "NXD" : "NXQTYPE") << " response received from " << auth << endl);
rec = lwr.d_records.erase(rec);
continue;
}
* We don't want to pick up root NS records in AUTHORITY and their associated ADDITIONAL sections of random queries.
* So don't add them to allowedAdditionals.
*/
- LOG(prefix << "Removing NS record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the " << (int)rec->d_place << " section of a response received from " << auth << endl);
+ LOG(prefix << qname << ": Removing NS record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the " << (int)rec->d_place << " section of a response received from " << auth << endl);
rec = lwr.d_records.erase(rec);
continue;
}
/* dealing with the records in additional */
if (rec->d_place == DNSResourceRecord::ADDITIONAL && rec->d_type != QType::A && rec->d_type != QType::AAAA && rec->d_type != QType::RRSIG) {
- LOG(prefix << "Removing irrelevant record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the ADDITIONAL section received from " << auth << endl);
+ LOG(prefix << qname << ": Removing irrelevant record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the ADDITIONAL section received from " << auth << endl);
rec = lwr.d_records.erase(rec);
continue;
}
if (rec->d_place == DNSResourceRecord::ADDITIONAL && allowedAdditionals.count(rec->d_name) == 0) {
- LOG(prefix << "Removing irrelevant additional record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the ADDITIONAL section received from " << auth << endl);
+ LOG(prefix << qname << ": Removing irrelevant additional record '" << rec->d_name << "|" << DNSRecordContent::NumberToType(rec->d_type) << "|" << rec->d_content->getZoneRepresentation() << "' in the ADDITIONAL section received from " << auth << endl);
rec = lwr.d_records.erase(rec);
continue;
}
for (const auto& ns : existing) {
auto content = getRR<NSRecordContent>(ns);
if (authSet.count(content->getNS()) == 0) {
- LOG(prefix << domain << ": at least one parent-side NS was not in the child-side NS set, remembering parent NS set and cached IPs" << endl);
+ LOG(prefix << domain << ": At least one parent-side NS was not in the child-side NS set, remembering parent NS set and cached IPs" << endl);
shouldSave = true;
break;
}
continue;
}
- LOG(prefix << qname << ": accept answer '" << rec.d_name << "|" << DNSRecordContent::NumberToType(rec.d_type) << "|" << rec.d_content->getZoneRepresentation() << "' from '" << auth << "' nameservers? ttl=" << rec.d_ttl << ", place=" << (int)rec.d_place << " ");
+ LOG(prefix << qname << ": Accept answer '" << rec.d_name << "|" << DNSRecordContent::NumberToType(rec.d_type) << "|" << rec.d_content->getZoneRepresentation() << "' from '" << auth << "' nameservers? ttl=" << rec.d_ttl << ", place=" << (int)rec.d_place << " ");
// We called sanitizeRecords before, so all ANY, non-IN and non-aa/non-forwardrecurse answer records are already removed
record.d_ttl = lowestTTD; // boom
}
}
-
- // cout<<"Have "<<i->second.records.size()<<" records and "<<i->second.signatures.size()<<" signatures for "<<i->first.name;
- // cout<<'|'<<DNSRecordContent::NumberToType(i->first.type)<<endl;
}
for (tcache_t::iterator i = tcache.begin(); i != tcache.end(); ++i) {
even after the delegation is gone from the parent.
So let's just do nothing with them, we can fetch them directly if we need them.
*/
- LOG(prefix << ": skipping authority NS from '" << auth << "' nameservers in CNAME/DNAME answer " << i->first.name << "|" << DNSRecordContent::NumberToType(i->first.type) << endl);
+ LOG(prefix << qname << ": Skipping authority NS from '" << auth << "' nameservers in CNAME/DNAME answer " << i->first.name << "|" << DNSRecordContent::NumberToType(i->first.type) << endl);
continue;
}
if (expectSignature && shouldValidate()) {
vState initialState = getValidationStatus(i->first.name, !i->second.signatures.empty(), i->first.type == QType::DS, depth, prefix);
- LOG(prefix << ": got initial zone status " << initialState << " for record " << i->first.name << "|" << DNSRecordContent::NumberToType(i->first.type) << endl);
+ LOG(prefix << qname << ": Got initial zone status " << initialState << " for record " << i->first.name << "|" << DNSRecordContent::NumberToType(i->first.type) << endl);
if (initialState == vState::Secure) {
if (i->first.type == QType::DNSKEY && i->first.place == DNSResourceRecord::ANSWER && i->first.name == getSigner(i->second.signatures)) {
- LOG(prefix << "Validating DNSKEY for " << i->first.name << endl);
+ LOG(prefix << qname << ": Validating DNSKEY for " << i->first.name << endl);
recordState = validateDNSKeys(i->first.name, i->second.records, i->second.signatures, depth, prefix);
}
else {
- LOG(prefix << "Validating non-additional " << QType(i->first.type).toString() << " record for " << i->first.name << endl);
+ LOG(prefix << qname << ": Validating non-additional " << QType(i->first.type).toString() << " record for " << i->first.name << endl);
recordState = validateRecordsWithSigs(depth, prefix, qname, qtype, i->first.name, QType(i->first.type), i->second.records, i->second.signatures);
}
}
else {
recordState = initialState;
- LOG(prefix << "Skipping validation because the current state is " << recordState << endl);
+ LOG(prefix << qname << ": Skipping validation because the current state is " << recordState << endl);
}
- LOG(prefix << "Validation result is " << recordState << ", current state is " << state << endl);
+ LOG(prefix << qname << ": Validation result is " << recordState << ", current state is " << state << endl);
if (state != recordState) {
- updateValidationState(state, recordState, prefix);
+ updateValidationState(qname, state, recordState, prefix);
}
}
return RCode::NoError;
}
-void SyncRes::updateDenialValidationState(vState& neValidationState, const DNSName& neName, vState& state, const dState denialState, const dState expectedState, bool isDS, unsigned int depth, const string& prefix)
+void SyncRes::updateDenialValidationState(const DNSName& qname, vState& neValidationState, const DNSName& neName, vState& state, const dState denialState, const dState expectedState, bool isDS, unsigned int depth, const string& prefix)
{
if (denialState == expectedState) {
neValidationState = vState::Secure;
}
else {
if (denialState == dState::OPTOUT) {
- LOG(prefix << "OPT-out denial found for " << neName << endl);
+ LOG(prefix << qname << ": OPT-out denial found for " << neName << endl);
/* rfc5155 states:
"The AD bit, as defined by [RFC4035], MUST NOT be set when returning a
response containing a closest (provable) encloser proof in which the
neValidationState = vState::Insecure;
}
else if (denialState == dState::INSECURE) {
- LOG(prefix << "Insecure denial found for " << neName << ", returning Insecure" << endl);
+ LOG(prefix << qname << ": Insecure denial found for " << neName << ", returning Insecure" << endl);
neValidationState = vState::Insecure;
}
else {
- LOG(prefix << "Invalid denial found for " << neName << ", res=" << denialState << ", expectedState=" << expectedState << ", checking whether we have missed a zone cut before returning a Bogus state" << endl);
+ LOG(prefix << qname << ": Invalid denial found for " << neName << ", res=" << denialState << ", expectedState=" << expectedState << ", checking whether we have missed a zone cut before returning a Bogus state" << endl);
/* try again to get the missed cuts, harder this time */
auto zState = getValidationStatus(neName, false, isDS, depth, prefix);
if (zState != vState::Secure) {
neValidationState = zState;
}
else {
- LOG(prefix << "Still in a secure zone with an invalid denial for " << neName << ", returning " << vStateToString(vState::BogusInvalidDenial) << endl);
+ LOG(prefix << qname << ": Still in a secure zone with an invalid denial for " << neName << ", returning " << vStateToString(vState::BogusInvalidDenial) << endl);
neValidationState = vState::BogusInvalidDenial;
}
}
}
- updateValidationState(state, neValidationState, prefix);
+ updateValidationState(qname, state, neValidationState, prefix);
}
dState SyncRes::getDenialValidationState(const NegCache::NegCacheEntry& ne, const dState expectedState, bool referralToUnsigned, const string& prefix)
}
if (negCacheIndication) {
- LOG(prefix << qname << ": got negative caching indication for name '" << qname << "' (accept=" << rec.d_name.isPartOf(auth) << "), newtarget='" << newtarget << "'" << endl);
+ LOG(prefix << qname << ": Got negative caching indication for name '" << qname << "' (accept=" << rec.d_name.isPartOf(auth) << "), newtarget='" << newtarget << "'" << endl);
rec.d_ttl = min(rec.d_ttl, s_maxnegttl);
// only add a SOA if we're not going anywhere after this
auto recordState = getValidationStatus(rec.d_name, !ne.authoritySOA.signatures.empty() || !ne.DNSSECRecords.signatures.empty(), false, depth, prefix);
if (recordState == vState::Secure) {
dState denialState = getDenialValidationState(ne, dState::NXDOMAIN, false, prefix);
- updateDenialValidationState(ne.d_validationState, ne.d_name, state, denialState, dState::NXDOMAIN, false, depth, prefix);
+ updateDenialValidationState(qname, ne.d_validationState, ne.d_name, state, denialState, dState::NXDOMAIN, false, depth, prefix);
}
else {
ne.d_validationState = recordState;
- updateValidationState(state, ne.d_validationState, prefix);
+ updateValidationState(qname, state, ne.d_validationState, prefix);
}
}
}
// for ANY answers we *must* have an authoritative answer, unless we are forwarding recursively
else if (rec.d_place == DNSResourceRecord::ANSWER && rec.d_name == qname && (rec.d_type == qtype.getCode() || ((lwr.d_aabit || sendRDQuery) && qtype == QType::ANY))) {
- LOG(prefix << qname << ": answer is in: resolved to '" << rec.d_content->getZoneRepresentation() << "|" << DNSRecordContent::NumberToType(rec.d_type) << "'" << endl);
+ LOG(prefix << qname << ": Answer is in: resolved to '" << rec.d_content->getZoneRepresentation() << "|" << DNSRecordContent::NumberToType(rec.d_type) << "'" << endl);
done = true;
rcode = RCode::NoError;
/* Some part could not be validated, for example a NSEC3 record with a too large number of iterations,
this is not enough to warrant a Bogus, but go Insecure. */
st = vState::Insecure;
- LOG(prefix << "Unable to validate denial in wildcard expanded positive response found for " << qname << ", returning Insecure, res=" << res << endl);
+ LOG(prefix << qname << ": Unable to validate denial in wildcard expanded positive response found for " << qname << ", returning Insecure, res=" << res << endl);
}
else {
- LOG(prefix << "Invalid denial in wildcard expanded positive response found for " << qname << ", returning Bogus, res=" << res << endl);
+ LOG(prefix << qname << ": Invalid denial in wildcard expanded positive response found for " << qname << ", returning Bogus, res=" << res << endl);
rec.d_ttl = std::min(rec.d_ttl, s_maxbogusttl);
}
- updateValidationState(state, st, prefix);
+ updateValidationState(qname, state, st, prefix);
/* we already stored the record with a different validation status, let's fix it */
updateValidationStatusInCache(qname, qtype, lwr.d_aabit, st);
}
else if (rec.d_place == DNSResourceRecord::AUTHORITY && rec.d_type == QType::NS && qname.isPartOf(rec.d_name)) {
if (moreSpecificThan(rec.d_name, auth)) {
newauth = rec.d_name;
- LOG(prefix << qname << ": got NS record '" << rec.d_name << "' -> '" << rec.d_content->getZoneRepresentation() << "'" << endl);
+ LOG(prefix << qname << ": Got NS record '" << rec.d_name << "' -> '" << rec.d_content->getZoneRepresentation() << "'" << endl);
/* check if we have a referral from the parent zone to a child zone for a DS query, which is not right */
if (qtype == QType::DS && (newauth.isPartOf(qname) || qname == newauth)) {
}
}
else {
- LOG(prefix << qname << ": got upwards/level NS record '" << rec.d_name << "' -> '" << rec.d_content->getZoneRepresentation() << "', had '" << auth << "'" << endl);
+ LOG(prefix << qname << ": Got upwards/level NS record '" << rec.d_name << "' -> '" << rec.d_content->getZoneRepresentation() << "', had '" << auth << "'" << endl);
if (auto content = getRR<NSRecordContent>(rec)) {
nsset.insert(content->getNS());
}
}
}
else if (rec.d_place == DNSResourceRecord::AUTHORITY && rec.d_type == QType::DS && qname.isPartOf(rec.d_name)) {
- LOG(prefix << qname << ": got DS record '" << rec.d_name << "' -> '" << rec.d_content->getZoneRepresentation() << "'" << endl);
+ LOG(prefix << qname << ": Got DS record '" << rec.d_name << "' -> '" << rec.d_content->getZoneRepresentation() << "'" << endl);
}
else if (realreferral && rec.d_place == DNSResourceRecord::AUTHORITY && (rec.d_type == QType::NSEC || rec.d_type == QType::NSEC3) && newauth.isPartOf(auth)) {
/* we might have received a denial of the DS, let's check */
if (denialState == dState::OPTOUT) {
ne.d_validationState = vState::Insecure;
}
- LOG(prefix << qname << ": got negative indication of DS record for '" << newauth << "'" << endl);
+ LOG(prefix << qname << ": Got negative indication of DS record for '" << newauth << "'" << endl);
g_negCache->add(ne);
}
}
else if (!done && rec.d_place == DNSResourceRecord::AUTHORITY && rec.d_type == QType::SOA && lwr.d_rcode == RCode::NoError && qname.isPartOf(rec.d_name)) {
- LOG(prefix << qname << ": got negative caching indication for '" << qname << "|" << qtype << "'" << endl);
+ LOG(prefix << qname << ": Got negative caching indication for '" << qname << "|" << qtype << "'" << endl);
if (!newtarget.empty()) {
LOG(prefix << qname << ": Hang on! Got a redirect to '" << newtarget << "' already" << endl);
auto recordState = getValidationStatus(qname, !ne.authoritySOA.signatures.empty() || !ne.DNSSECRecords.signatures.empty(), qtype == QType::DS, depth, prefix);
if (recordState == vState::Secure) {
dState denialState = getDenialValidationState(ne, dState::NXQTYPE, false, prefix);
- updateDenialValidationState(ne.d_validationState, ne.d_name, state, denialState, dState::NXQTYPE, qtype == QType::DS, depth, prefix);
+ updateDenialValidationState(qname, ne.d_validationState, ne.d_name, state, denialState, dState::NXQTYPE, qtype == QType::DS, depth, prefix);
}
else {
ne.d_validationState = recordState;
- updateValidationState(state, ne.d_validationState, prefix);
+ updateValidationState(qname, state, ne.d_validationState, prefix);
}
}
/* If we have seen a proper denial, let's forget that we also had a referral for a DS query.
Otherwise we need to deal with it. */
if (referralOnDS && !negindic) {
- LOG(prefix << qname << ": got a referral to the child zone for a DS query without a negative indication (missing SOA in authority), treating that as a NODATA" << endl);
+ LOG(prefix << qname << ": Got a referral to the child zone for a DS query without a negative indication (missing SOA in authority), treating that as a NODATA" << endl);
if (!vStateIsBogus(state)) {
auto recordState = getValidationStatus(qname, false, true, depth, prefix);
if (recordState == vState::Secure) {
/* we are in a secure zone, got a referral to the child zone on a DS query, no denial, that's wrong */
LOG(prefix << qname << ": NODATA without a negative indication (missing SOA in authority) in a DNSSEC secure zone, going Bogus" << endl);
- updateValidationState(state, vState::BogusMissingNegativeIndication, prefix);
+ updateValidationState(qname, state, vState::BogusMissingNegativeIndication, prefix);
}
}
negindic = true;
if (doTCP) {
if (doDoT) {
- LOG(prefix << qname << ": using DoT with " << remoteIP.toStringWithPort() << endl);
+ LOG(prefix << qname << ": Using DoT with " << remoteIP.toStringWithPort() << endl);
t_Counters.at(rec::Counter::dotoutqueries)++;
d_dotoutqueries++;
}
else {
- LOG(prefix << qname << ": using TCP with " << remoteIP.toStringWithPort() << endl);
+ LOG(prefix << qname << ": Using TCP with " << remoteIP.toStringWithPort() << endl);
t_Counters.at(rec::Counter::tcpoutqueries)++;
d_tcpoutqueries++;
}
int preOutQueryRet = RCode::NoError;
if (d_pdl && d_pdl->preoutquery(remoteIP, d_requestor, qname, qtype, doTCP, lwr.d_records, preOutQueryRet, d_eventTrace, timeval{0, 0})) {
- LOG(prefix << qname << ": query handled by Lua" << endl);
+ LOG(prefix << qname << ": Query handled by Lua" << endl);
}
else {
ednsmask = getEDNSSubnetMask(qname, remoteIP);
if (resolveret == LWResult::Result::Timeout) {
/* Time out */
- LOG(prefix << qname << ": timeout resolving after " << lwr.d_usec / 1000.0 << "msec " << (doTCP ? "over TCP" : "") << endl);
+ LOG(prefix << qname << ": Timeout resolving after " << lwr.d_usec / 1000.0 << "msec " << (doTCP ? "over TCP" : "") << endl);
d_timeouts++;
t_Counters.at(rec::Counter::outgoingtimeouts)++;
}
else if (resolveret == LWResult::Result::OSLimitError) {
/* OS resource limit reached */
- LOG(prefix << qname << ": hit a local resource limit resolving" << (doTCP ? " over TCP" : "") << ", probable error: " << stringerror() << endl);
+ LOG(prefix << qname << ": Hit a local resource limit resolving" << (doTCP ? " over TCP" : "") << ", probable error: " << stringerror() << endl);
t_Counters.at(rec::Counter::resourceLimits)++;
}
else if (resolveret == LWResult::Result::Spoofed) {
t_Counters.at(rec::Counter::unreachables)++;
d_unreachables++;
// XXX questionable use of errno
- LOG(prefix << qname << ": error resolving from " << remoteIP.toString() << (doTCP ? " over TCP" : "") << ", possible error: " << stringerror() << endl);
+ LOG(prefix << qname << ": Error resolving from " << remoteIP.toString() << (doTCP ? " over TCP" : "") << ", possible error: " << stringerror() << endl);
}
if (resolveret != LWResult::Result::OSLimitError && !chained && !dontThrottle) {
truncated = true;
if (doTCP) {
- LOG(prefix << qname << ": truncated bit set, over TCP?" << endl);
+ LOG(prefix << qname << ": Truncated bit set, over TCP?" << endl);
if (!dontThrottle) {
/* let's treat that as a ServFail answer from this server */
doThrottle(d_now.tv_sec, remoteIP, qname, qtype, 60, 3);
}
return false;
}
- LOG(prefix << qname << ": truncated bit set, over UDP" << endl);
+ LOG(prefix << qname << ": Truncated bit set, over UDP" << endl);
return true;
}
void SyncRes::handleNewTarget(const std::string& prefix, const DNSName& qname, const DNSName& newtarget, const QType qtype, std::vector<DNSRecord>& ret, int& rcode, int depth, const std::vector<DNSRecord>& recordsFromAnswer, vState& state)
{
if (newtarget == qname) {
- LOG(prefix << qname << ": status=got a CNAME referral to self, returning SERVFAIL" << endl);
+ LOG(prefix << qname << ": Status=got a CNAME referral to self, returning SERVFAIL" << endl);
ret.clear();
rcode = RCode::ServFail;
return;
}
if (newtarget.isPartOf(qname)) {
// a.b.c. CNAME x.a.b.c will go to great depths with QM on
- LOG(prefix << qname << ": status=got a CNAME referral to child, disabling QM" << endl);
+ LOG(prefix << qname << ": Status=got a CNAME referral to child, disabling QM" << endl);
setQNameMinimization(false);
}
if (depth > 10) {
- LOG(prefix << qname << ": status=got a CNAME referral, but recursing too deep, returning SERVFAIL" << endl);
+ LOG(prefix << qname << ": Status=got a CNAME referral, but recursing too deep, returning SERVFAIL" << endl);
rcode = RCode::ServFail;
return;
}
// Check to see if we already have seen the new target as a previous target
if (scanForCNAMELoop(newtarget, ret)) {
- LOG(prefix << qname << ": status=got a CNAME referral that causes a loop, returning SERVFAIL" << endl);
+ LOG(prefix << qname << ": Status=got a CNAME referral that causes a loop, returning SERVFAIL" << endl);
ret.clear();
rcode = RCode::ServFail;
return;
}
if (qtype == QType::DS || qtype == QType::DNSKEY) {
- LOG(prefix << qname << ": status=got a CNAME referral, but we are looking for a DS or DNSKEY" << endl);
+ LOG(prefix << qname << ": Status=got a CNAME referral, but we are looking for a DS or DNSKEY" << endl);
if (d_doDNSSEC) {
addNXNSECS(ret, recordsFromAnswer);
return;
}
- LOG(prefix << qname << ": status=got a CNAME referral, starting over with " << newtarget << endl);
+ LOG(prefix << qname << ": Status=got a CNAME referral, starting over with " << newtarget << endl);
set<GetBestNSAnswer> beenthere;
Context cnameContext;
rcode = doResolve(newtarget, qtype, ret, depth + 1, beenthere, cnameContext);
- LOG(prefix << qname << ": updating validation state for response to " << qname << " from " << state << " with the state from the CNAME quest: " << cnameContext.state << endl);
- updateValidationState(state, cnameContext.state, prefix);
+ LOG(prefix << qname << ": Updating validation state for response to " << qname << " from " << state << " with the state from the CNAME quest: " << cnameContext.state << endl);
+ updateValidationState(qname, state, cnameContext.state, prefix);
}
bool SyncRes::processAnswer(unsigned int depth, const string& prefix, LWResult& lwr, const DNSName& qname, const QType qtype, DNSName& auth, bool wasForwarded, const boost::optional<Netmask> ednsmask, bool sendRDQuery, NsSet& nameservers, std::vector<DNSRecord>& ret, const DNSFilterEngine& dfe, bool* gotNewServers, int* rcode, vState& state, const ComboAddress& remoteIP)
return true;
}
- LOG(prefix << qname << ": determining status after receiving this packet" << endl);
+ LOG(prefix << qname << ": Determining status after receiving this packet" << endl);
set<DNSName> nsset;
bool realreferral = false;
bool done = processRecords(prefix, qname, qtype, auth, lwr, sendRDQuery, ret, nsset, newtarget, newauth, realreferral, negindic, state, needWildcardProof, gatherWildcardProof, wildcardLabelsCount, *rcode, negIndicHasSignatures, depth);
if (done) {
- LOG(prefix << qname << ": status=got results, this level of recursion done" << endl);
- LOG(prefix << qname << ": validation status is " << state << endl);
+ LOG(prefix << qname << ": Status=got results, this level of recursion done" << endl);
+ LOG(prefix << qname << ": Validation status is " << state << endl);
return true;
}
}
if (lwr.d_rcode == RCode::NXDomain) {
- LOG(prefix << qname << ": status=NXDOMAIN, we are done " << (negindic ? "(have negative SOA)" : "") << endl);
+ LOG(prefix << qname << ": Status=NXDOMAIN, we are done " << (negindic ? "(have negative SOA)" : "") << endl);
auto tempState = getValidationStatus(qname, negIndicHasSignatures, qtype == QType::DS, depth, prefix);
if (tempState == vState::Secure && (lwr.d_aabit || sendRDQuery) && !negindic) {
LOG(prefix << qname << ": NXDOMAIN without a negative indication (missing SOA in authority) in a DNSSEC secure zone, going Bogus" << endl);
- updateValidationState(state, vState::BogusMissingNegativeIndication, prefix);
+ updateValidationState(qname, state, vState::BogusMissingNegativeIndication, prefix);
}
else if (state == vState::Indeterminate) {
/* we might not have validated any record, because we did get a NXDOMAIN without any SOA
from an insecure zone, for example */
- updateValidationState(state, tempState, prefix);
+ updateValidationState(qname, state, tempState, prefix);
}
if (d_doDNSSEC) {
}
if (nsset.empty() && !lwr.d_rcode && (negindic || lwr.d_aabit || sendRDQuery)) {
- LOG(prefix << qname << ": status=noerror, other types may exist, but we are done " << (negindic ? "(have negative SOA) " : "") << (lwr.d_aabit ? "(have aa bit) " : "") << endl);
+ LOG(prefix << qname << ": Status=noerror, other types may exist, but we are done " << (negindic ? "(have negative SOA) " : "") << (lwr.d_aabit ? "(have aa bit) " : "") << endl);
auto tempState = getValidationStatus(qname, negIndicHasSignatures, qtype == QType::DS, depth, prefix);
if (tempState == vState::Secure && (lwr.d_aabit || sendRDQuery) && !negindic) {
LOG(prefix << qname << ": NODATA without a negative indication (missing SOA in authority) in a DNSSEC secure zone, going Bogus" << endl);
- updateValidationState(state, vState::BogusMissingNegativeIndication, prefix);
+ updateValidationState(qname, state, vState::BogusMissingNegativeIndication, prefix);
}
else if (state == vState::Indeterminate) {
/* we might not have validated any record, because we did get a NODATA without any SOA
from an insecure zone, for example */
- updateValidationState(state, tempState, prefix);
+ updateValidationState(qname, state, tempState, prefix);
}
if (d_doDNSSEC) {
}
if (realreferral) {
- LOG(prefix << qname << ": status=did not resolve, got " << (unsigned int)nsset.size() << " NS, ");
+ LOG(prefix << qname << ": Status=did not resolve, got " << (unsigned int)nsset.size() << " NS, ");
nameservers.clear();
for (auto const& nameserver : nsset) {
unsigned int addressQueriesForNS = 0;
for (;;) { // we may get more specific nameservers
- auto rnameservers = shuffleInSpeedOrder(nameservers, doLog() ? (prefix + qname.toString() + ": ") : string());
+ auto rnameservers = shuffleInSpeedOrder(qname, nameservers, prefix);
// We allow s_maxnsaddressqperq (default 10) queries with empty responses when resolving NS names.
// If a zone publishes many (more than s_maxnsaddressqperq) NS records, we allow less.
static bool provesNoDataWildCard(const DNSName& qname, const uint16_t qtype, const DNSName& closestEncloser, const cspmap_t& validrrsets, const OptLog& log)
{
const DNSName wildcard = g_wildcarddnsname + closestEncloser;
- VLOG(log, "Trying to prove that there is no data in wildcard for "<<qname<<"/"<<QType(qtype)<<endl);
+ VLOG(log, qname << ": Trying to prove that there is no data in wildcard for "<<qname<<"/"<<QType(qtype)<<endl);
for (const auto& v : validrrsets) {
- VLOG(log, "Do have: "<<v.first.first<<"/"<<DNSRecordContent::NumberToType(v.first.second)<<endl);
+ VLOG(log, qname << ": Do have: "<<v.first.first<<"/"<<DNSRecordContent::NumberToType(v.first.second)<<endl);
if (v.first.second == QType::NSEC) {
for (const auto& r : v.second.records) {
- VLOG(log, "\t"<<r->getZoneRepresentation()<<endl);
+ VLOG(log, ":\t"<<r->getZoneRepresentation()<<endl);
auto nsec = std::dynamic_pointer_cast<NSECRecordContent>(r);
if (!nsec) {
continue;
continue;
}
- VLOG(log, "\tWildcard matches");
+ VLOG(log, qname << ":\tWildcard matches");
if (qtype == 0 || isTypeDenied(nsec, QType(qtype))) {
- VLOG(log, " and proves that the type did not exist"<<endl);
+ VLOG_NO_PREFIX(log, " and proves that the type did not exist"<<endl);
return true;
}
- VLOG(log, " BUT the type did exist!"<<endl);
+ VLOG_NO_PREFIX(log, " BUT the type did exist!"<<endl);
return false;
}
}
*/
static bool provesNoWildCard(const DNSName& qname, const uint16_t qtype, const DNSName& closestEncloser, const cspmap_t & validrrsets, const OptLog& log)
{
- VLOG(log, "Trying to prove that there is no wildcard for "<<qname<<"/"<<QType(qtype)<<endl);
+ VLOG(log, qname << ": Trying to prove that there is no wildcard for "<<qname<<"/"<<QType(qtype)<<endl);
const DNSName wildcard = g_wildcarddnsname + closestEncloser;
for (const auto& v : validrrsets) {
- VLOG(log, "Do have: "<<v.first.first<<"/"<<DNSRecordContent::NumberToType(v.first.second)<<endl);
+ VLOG(log, qname << ": Do have: "<<v.first.first<<"/"<<DNSRecordContent::NumberToType(v.first.second)<<endl);
if (v.first.second == QType::NSEC) {
for (const auto& r : v.second.records) {
- VLOG(log, "\t"<<r->getZoneRepresentation()<<endl);
+ VLOG(log, qname << ":\t"<<r->getZoneRepresentation()<<endl);
auto nsec = std::dynamic_pointer_cast<NSECRecordContent>(r);
if (!nsec) {
continue;
}
const DNSName owner = getNSECOwnerName(v.first.first, v.second.signatures);
- VLOG(log, "Comparing owner: "<<owner<<" with target: "<<wildcard<<endl);
+ VLOG(log, qname << ": Comparing owner: "<<owner<<" with target: "<<wildcard<<endl);
if (qname != owner && qname.isPartOf(owner) && nsec->isSet(QType::DNAME)) {
/* rfc6672 section 5.3.2: DNAME Bit in NSEC Type Map
asserted, then DNAME substitution should have been done, but the
substitution has not been done as specified.
*/
- VLOG(log, "\tThe qname is a subdomain of the NSEC and the DNAME bit is set"<<endl);
+ VLOG(log, qname << ":\tThe qname is a subdomain of the NSEC and the DNAME bit is set"<<endl);
return false;
}
if (wildcard != owner && isCoveredByNSEC(wildcard, owner, nsec->d_next)) {
- VLOG(log, "\tWildcard is covered"<<endl);
+ VLOG(log, qname << ":\tWildcard is covered"<<endl);
return true;
}
}
static bool provesNSEC3NoWildCard(const DNSName& closestEncloser, uint16_t const qtype, const cspmap_t& validrrsets, bool* wildcardExists, nsec3HashesCache& cache, const OptLog& log)
{
auto wildcard = g_wildcarddnsname + closestEncloser;
- VLOG(log, "Trying to prove that there is no wildcard for "<<wildcard<<"/"<<QType(qtype)<<endl);
+ VLOG(log, closestEncloser << ": Trying to prove that there is no wildcard for "<<wildcard<<"/"<<QType(qtype)<<endl);
for (const auto& v : validrrsets) {
- VLOG(log, "Do have: "<<v.first.first<<"/"<<DNSRecordContent::NumberToType(v.first.second)<<endl);
+ VLOG(log, closestEncloser << ": Do have: "<<v.first.first<<"/"<<DNSRecordContent::NumberToType(v.first.second)<<endl);
if (v.first.second == QType::NSEC3) {
for (const auto& r : v.second.records) {
- VLOG(log, "\t"<<r->getZoneRepresentation()<<endl);
+ VLOG(log, closestEncloser << ":\t"<<r->getZoneRepresentation()<<endl);
auto nsec3 = std::dynamic_pointer_cast<NSEC3RecordContent>(r);
if (!nsec3) {
continue;
if (h.empty()) {
return false;
}
- VLOG(log, "\tWildcard hash: "<<toBase32Hex(h)<<endl);
+ VLOG(log, closestEncloser << ":\tWildcard hash: "<<toBase32Hex(h)<<endl);
string beginHash=fromBase32Hex(v.first.first.getRawLabels()[0]);
- VLOG(log, "\tNSEC3 hash: "<<toBase32Hex(beginHash)<<" -> "<<toBase32Hex(nsec3->d_nexthash)<<endl);
+ VLOG(log, closestEncloser << ":\tNSEC3 hash: "<<toBase32Hex(beginHash)<<" -> "<<toBase32Hex(nsec3->d_nexthash)<<endl);
if (beginHash == h) {
- VLOG(log, "\tWildcard hash matches");
+ VLOG(log, closestEncloser << ":\tWildcard hash matches");
if (wildcardExists) {
*wildcardExists = true;
}
*/
if (qtype != QType::DS && isNSEC3AncestorDelegation(signer, v.first.first, nsec3)) {
/* this is an "ancestor delegation" NSEC3 RR */
- VLOG(log, " BUT an ancestor delegation NSEC3 RR can only deny the existence of a DS"<<endl);
+ VLOG_NO_PREFIX(log, " BUT an ancestor delegation NSEC3 RR can only deny the existence of a DS"<<endl);
return false;
}
if (qtype == 0 || isTypeDenied(nsec3, QType(qtype))) {
- VLOG(log, " and proves that the type did not exist"<<endl);
+ VLOG_NO_PREFIX(log, " and proves that the type did not exist"<<endl);
return true;
}
- VLOG(log, " BUT the type did exist!"<<endl);
+ VLOG_NO_PREFIX(log, " BUT the type did exist!"<<endl);
return false;
}
if (isCoveredByNSEC3Hash(h, beginHash, nsec3->d_nexthash)) {
- VLOG(log, "\tWildcard hash is covered"<<endl);
+ VLOG(log, closestEncloser << ":\tWildcard hash is covered"<<endl);
return true;
}
}
if (name.isPartOf(owner) && isNSECAncestorDelegation(signer, owner, nsec)) {
/* this is an "ancestor delegation" NSEC RR */
if (!(qtype == QType::DS && name == owner)) {
- VLOG(log, "An ancestor delegation NSEC RR can only deny the existence of a DS"<<endl);
+ VLOG_NO_PREFIX(log, "An ancestor delegation NSEC RR can only deny the existence of a DS"<<endl);
return dState::NODENIAL;
}
}
/* check if the type is denied */
if (name == owner) {
if (!isTypeDenied(nsec, QType(qtype))) {
- VLOG(log, "Does _not_ deny existence of type "<<QType(qtype)<<endl);
+ VLOG_NO_PREFIX(log, "Does _not_ deny existence of type "<<QType(qtype)<<endl);
return dState::NODENIAL;
}
if (qtype == QType::DS && signer == name) {
- VLOG(log, "The NSEC comes from the child zone and cannot be used to deny a DS");
+ VLOG_NO_PREFIX(log, "The NSEC comes from the child zone and cannot be used to deny a DS"<<endl);
return dState::NODENIAL;
}
- VLOG(log, "Denies existence of type "<<QType(qtype)<<endl);
+ VLOG_NO_PREFIX(log, "Denies existence of type "<<QType(qtype)<<endl);
return dState::NXQTYPE;
}
}
if (isCoveredByNSEC(name, owner, nsec->d_next)) {
- VLOG(log, name<<" is covered by ("<<owner<<" to "<<nsec->d_next<<") ");
+ VLOG_NO_PREFIX(log, name << ": is covered by ("<<owner<<" to "<<nsec->d_next<<")");
if (nsecProvesENT(name, owner, nsec->d_next)) {
- VLOG(log, "Denies existence of type "<<name<<"/"<<QType(qtype)<<" by proving that "<<name<<" is an ENT"<<endl);
+ VLOG_NO_PREFIX(log, " Denies existence of type "<<name<<"/"<<QType(qtype)<<" by proving that "<<name<<" is an ENT"<<endl);
return dState::NXQTYPE;
}
}
for (const auto& v : validrrsets) {
- VLOG(log, "Do have: "<<v.first.first<<"/"<<DNSRecordContent::NumberToType(v.first.second)<<endl);
+ VLOG(log, qname << ": Do have: "<<v.first.first<<"/"<<DNSRecordContent::NumberToType(v.first.second)<<endl);
if (v.first.second==QType::NSEC) {
for (const auto& r : v.second.records) {
- VLOG(log, "\t"<<r->getZoneRepresentation()<<endl);
+ VLOG(log, qname << ":\t"<<r->getZoneRepresentation()<<endl);
if (v.second.signatures.empty()) {
continue;
*/
const bool notApex = signer.countLabels() < owner.countLabels();
if (notApex && nsec->isSet(QType::NS) && nsec->isSet(QType::SOA)) {
- VLOG(log, "However, that NSEC is not at the apex and has both the NS and the SOA bits set!"<<endl);
+ VLOG(log, qname << ": However, that NSEC is not at the apex and has both the NS and the SOA bits set!"<<endl);
continue;
}
if (qname.isPartOf(owner) && isNSECAncestorDelegation(signer, owner, nsec)) {
/* this is an "ancestor delegation" NSEC RR */
if (!(qtype == QType::DS && qname == owner)) {
- VLOG(log, "An ancestor delegation NSEC RR can only deny the existence of a DS"<<endl);
+ VLOG(log, qname << ": An ancestor delegation NSEC RR can only deny the existence of a DS"<<endl);
return dState::NODENIAL;
}
}
if (qtype == QType::DS && !qname.isRoot() && signer == qname) {
- VLOG(log, "A NSEC RR from the child zone cannot deny the existence of a DS"<<endl);
+ VLOG(log, qname << ": A NSEC RR from the child zone cannot deny the existence of a DS"<<endl);
continue;
}
/* check if the type is denied */
if (qname == owner) {
if (!isTypeDenied(nsec, QType(qtype))) {
- VLOG(log, "Does _not_ deny existence of type "<<QType(qtype)<<endl);
+ VLOG(log, qname << ": Does _not_ deny existence of type "<<QType(qtype)<<endl);
return dState::NODENIAL;
}
- VLOG(log, "Denies existence of type "<<QType(qtype)<<endl);
+ VLOG(log, qname << ": Denies existence of type "<<QType(qtype)<<endl);
/*
* RFC 4035 Section 2.3:
*/
if (referralToUnsigned && qtype == QType::DS) {
if (!nsec->isSet(QType::NS)) {
- VLOG(log, "However, no NS record exists at this level!"<<endl);
+ VLOG(log, qname << ": However, no NS record exists at this level!"<<endl);
return dState::NODENIAL;
}
}
return dState::NXQTYPE;
}
- VLOG(log, "But the existence of a wildcard is not denied for "<<qname<<"/"<<endl);
+ VLOG(log, qname << ": But the existence of a wildcard is not denied for "<<qname<<"/"<<endl);
return dState::NODENIAL;
}
asserted, then DNAME substitution should have been done, but the
substitution has not been done as specified.
*/
- VLOG(log, "The DNAME bit is set and the query name is a subdomain of that NSEC");
+ VLOG(log, qname << ": The DNAME bit is set and the query name is a subdomain of that NSEC"<< endl);
return dState::NODENIAL;
}
/* check if the whole NAME is denied existing */
if (isCoveredByNSEC(qname, owner, nsec->d_next)) {
- VLOG(log, qname<<" is covered by ("<<owner<<" to "<<nsec->d_next<<") ");
+ VLOG(log, qname<< ": Is covered by ("<<owner<<" to "<<nsec->d_next<<") ");
if (nsecProvesENT(qname, owner, nsec->d_next)) {
if (wantsNoDataProof) {
/* if the name is an ENT and we received a NODATA answer,
we are fine with a NSEC proving that the name does not exist. */
- VLOG(log, "Denies existence of type "<<qname<<"/"<<QType(qtype)<<" by proving that "<<qname<<" is an ENT"<<endl);
+ VLOG_NO_PREFIX(log, "Denies existence of type "<<qname<<"/"<<QType(qtype)<<" by proving that "<<qname<<" is an ENT"<<endl);
return dState::NXQTYPE;
}
else {
/* but for a NXDOMAIN proof, this doesn't make sense! */
- VLOG(log, "but it tries to deny the existence of "<<qname<<" by proving that "<<qname<<" is an ENT, this does not make sense!"<<endl);
+ VLOG_NO_PREFIX(log, "but it tries to deny the existence of "<<qname<<" by proving that "<<qname<<" is an ENT, this does not make sense!"<<endl);
return dState::NODENIAL;
}
}
if (!needWildcardProof) {
- VLOG(log, "and we did not need a wildcard proof"<<endl);
+ VLOG_NO_PREFIX(log, "and we did not need a wildcard proof"<<endl);
return dState::NXDOMAIN;
}
- VLOG(log, "but we do need a wildcard proof so ");
+ VLOG_NO_PREFIX(log, "but we do need a wildcard proof so ");
DNSName closestEncloser = getClosestEncloserFromNSEC(qname, owner, nsec->d_next);
if (wantsNoDataProof) {
- VLOG(log, "looking for NODATA proof"<<endl);
+ VLOG_NO_PREFIX(log, "looking for NODATA proof"<<endl);
if (provesNoDataWildCard(qname, qtype, closestEncloser, validrrsets, log)) {
return dState::NXQTYPE;
}
}
else {
- VLOG(log, "looking for NO wildcard proof"<<endl);
+ VLOG_NO_PREFIX(log, "looking for NO wildcard proof"<<endl);
if (provesNoWildCard(qname, qtype, closestEncloser, validrrsets, log)) {
return dState::NXDOMAIN;
}
}
- VLOG(log, "But the existence of a wildcard is not denied for "<<qname<<"/"<<endl);
+ VLOG(log, qname << ": But the existence of a wildcard is not denied for "<<qname<<"/"<<endl);
return dState::NODENIAL;
}
- VLOG(log, "Did not deny existence of "<<QType(qtype)<<", "<<v.first.first<<"?="<<qname<<", "<<nsec->isSet(qtype)<<", next: "<<nsec->d_next<<endl);
+ VLOG(log, qname << ": Did not deny existence of "<<QType(qtype)<<", "<<v.first.first<<"?="<<qname<<", "<<nsec->isSet(qtype)<<", next: "<<nsec->d_next<<endl);
}
} else if(v.first.second==QType::NSEC3) {
for (const auto& r : v.second.records) {
- VLOG(log, "\t"<<r->getZoneRepresentation()<<endl);
+ VLOG(log, qname << ":\t"<<r->getZoneRepresentation()<<endl);
auto nsec3 = std::dynamic_pointer_cast<NSEC3RecordContent>(r);
if (!nsec3) {
continue;
const DNSName& hashedOwner = v.first.first;
const DNSName signer = getSigner(v.second.signatures);
if (!hashedOwner.isPartOf(signer)) {
- VLOG(log, "Owner "<<hashedOwner<<" is not part of the signer "<<signer<<", ignoring"<<endl);
+ VLOG(log, qname << ": Owner "<<hashedOwner<<" is not part of the signer "<<signer<<", ignoring"<<endl);
continue;
}
if (qtype == QType::DS && !qname.isRoot() && signer == qname) {
- VLOG(log, "A NSEC3 RR from the child zone cannot deny the existence of a DS"<<endl);
+ VLOG(log, qname << ": A NSEC3 RR from the child zone cannot deny the existence of a DS"<<endl);
continue;
}
string h = getHashFromNSEC3(qname, nsec3, cache);
if (h.empty()) {
- VLOG(log, "Unsupported hash, ignoring"<<endl);
+ VLOG(log, qname << ": Unsupported hash, ignoring"<<endl);
return dState::INSECURE;
}
nsec3Seen = true;
- VLOG(log, "\tquery hash: "<<toBase32Hex(h)<<endl);
+ VLOG(log, qname << ":\tquery hash: "<<toBase32Hex(h)<<endl);
string beginHash = fromBase32Hex(hashedOwner.getRawLabels()[0]);
// If the name exists, check if the qtype is denied
*/
const bool notApex = signer.countLabels() < qname.countLabels();
if (notApex && nsec3->isSet(QType::NS) && nsec3->isSet(QType::SOA)) {
- VLOG(log, "However, that NSEC3 is not at the apex and has both the NS and the SOA bits set!"<<endl);
+ VLOG(log, qname << ": However, that NSEC3 is not at the apex and has both the NS and the SOA bits set!"<<endl);
continue;
}
*/
if (qtype != QType::DS && isNSEC3AncestorDelegation(signer, qname, nsec3)) {
/* this is an "ancestor delegation" NSEC3 RR */
- VLOG(log, "An ancestor delegation NSEC3 RR can only deny the existence of a DS"<<endl);
+ VLOG(log, qname << ": An ancestor delegation NSEC3 RR can only deny the existence of a DS"<<endl);
return dState::NODENIAL;
}
if (!isTypeDenied(nsec3, QType(qtype))) {
- VLOG(log, "Does _not_ deny existence of type "<<QType(qtype)<<" for name "<<qname<<" (not opt-out)."<<endl);
+ VLOG(log, qname << ": Does _not_ deny existence of type "<<QType(qtype)<<" for name "<<qname<<" (not opt-out)."<<endl);
return dState::NODENIAL;
}
- VLOG(log, "Denies existence of type "<<QType(qtype)<<" for name "<<qname<<" (not opt-out)."<<endl);
+ VLOG(log, qname << ": Denies existence of type "<<QType(qtype)<<" for name "<<qname<<" (not opt-out)."<<endl);
/*
* RFC 5155 section 8.9:
*/
if (referralToUnsigned && qtype == QType::DS) {
if (!nsec3->isSet(QType::NS)) {
- VLOG(log, "However, no NS record exists at this level!"<<endl);
+ VLOG(log, qname << ": However, no NS record exists at this level!"<<endl);
return dState::NODENIAL;
}
}
RFC 5155 section-7.2.1
RFC 7129 section-5.5
*/
- VLOG(log, "Now looking for the closest encloser for "<<qname<<endl);
+ VLOG(log, qname << ": Now looking for the closest encloser for "<<qname<<endl);
while (found == false && closestEncloser.chopOff()) {
for(const auto& v : validrrsets) {
if(v.first.second==QType::NSEC3) {
for(const auto& r : v.second.records) {
- VLOG(log, "\t"<<r->getZoneRepresentation()<<endl);
+ VLOG(log, qname << ":\t"<<r->getZoneRepresentation()<<endl);
auto nsec3 = std::dynamic_pointer_cast<NSEC3RecordContent>(r);
if (!nsec3) {
continue;
const DNSName signer = getSigner(v.second.signatures);
if (!v.first.first.isPartOf(signer)) {
- VLOG(log, "Owner "<<v.first.first<<" is not part of the signer "<<signer<<", ignoring"<<endl);
+ VLOG(log, qname << ": Owner "<<v.first.first<<" is not part of the signer "<<signer<<", ignoring"<<endl);
continue;
}
string beginHash=fromBase32Hex(v.first.first.getRawLabels()[0]);
- VLOG(log, "Comparing "<<toBase32Hex(h)<<" ("<<closestEncloser<<") against "<<toBase32Hex(beginHash)<<endl);
+ VLOG(log, qname << ": Comparing "<<toBase32Hex(h)<<" ("<<closestEncloser<<") against "<<toBase32Hex(beginHash)<<endl);
if (beginHash == h) {
/* If the closest encloser is a delegation NS we know nothing about the names in the child zone. */
if (isNSEC3AncestorDelegation(signer, v.first.first, nsec3)) {
- VLOG(log, "An ancestor delegation NSEC3 RR can only deny the existence of a DS"<<endl);
+ VLOG(log, qname << ": An ancestor delegation NSEC3 RR can only deny the existence of a DS"<<endl);
continue;
}
- VLOG(log, "Closest encloser for "<<qname<<" is "<<closestEncloser<<endl);
+ VLOG(log, qname << ": Closest encloser for "<<qname<<" is "<<closestEncloser<<endl);
found = true;
if (nsec3->isSet(QType::DNAME)) {
asserted, then DNAME substitution should have been done, but the
substitution has not been done as specified.
*/
- VLOG(log, "\tThe closest encloser NSEC3 has the DNAME bit is set"<<endl);
+ VLOG(log, qname << ":\tThe closest encloser NSEC3 has the DNAME bit is set"<<endl);
return dState::NODENIAL;
}
if (labelIdx >= 1) {
DNSName nextCloser(closestEncloser);
nextCloser.prependRawLabel(qname.getRawLabel(labelIdx - 1));
- VLOG(log, "Looking for a NSEC3 covering the next closer name "<<nextCloser<<endl);
+ VLOG(log, qname << ":Looking for a NSEC3 covering the next closer name "<<nextCloser<<endl);
for(const auto& v : validrrsets) {
if(v.first.second==QType::NSEC3) {
for(const auto& r : v.second.records) {
- VLOG(log, "\t"<<r->getZoneRepresentation()<<endl);
+ VLOG(log, qname << ":\t"<<r->getZoneRepresentation()<<endl);
auto nsec3 = std::dynamic_pointer_cast<NSEC3RecordContent>(r);
if(!nsec3)
continue;
const DNSName signer = getSigner(v.second.signatures);
if (!v.first.first.isPartOf(signer)) {
- VLOG(log, "Owner "<<v.first.first<<" is not part of the signer "<<signer<<", ignoring"<<endl);
+ VLOG(log, qname << ": Owner "<<v.first.first<<" is not part of the signer "<<signer<<", ignoring"<<endl);
continue;
}
string beginHash=fromBase32Hex(v.first.first.getRawLabels()[0]);
- VLOG(log, "Comparing "<<toBase32Hex(h)<<" against "<<toBase32Hex(beginHash)<<" -> "<<toBase32Hex(nsec3->d_nexthash)<<endl);
+ VLOG(log, qname << ": Comparing "<<toBase32Hex(h)<<" against "<<toBase32Hex(beginHash)<<" -> "<<toBase32Hex(nsec3->d_nexthash)<<endl);
if (isCoveredByNSEC3Hash(h, beginHash, nsec3->d_nexthash)) {
- VLOG(log, "Denies existence of name "<<qname<<"/"<<QType(qtype));
+ VLOG(log, qname << ": Denies existence of name "<<qname<<"/"<<QType(qtype));
nextCloserFound = true;
if (nsec3->isOptOut()) {
- VLOG(log, " but is opt-out!");
+ VLOG_NO_PREFIX(log, " but is opt-out!");
isOptOut = true;
}
- VLOG(log, endl);
+ VLOG_NO_PREFIX(log, endl);
break;
}
- VLOG(log, "Did not cover us ("<<qname<<"), start="<<v.first.first<<", us="<<toBase32Hex(h)<<", end="<<toBase32Hex(nsec3->d_nexthash)<<endl);
+ VLOG(log, qname << ": Did not cover us ("<<qname<<"), start="<<v.first.first<<", us="<<toBase32Hex(h)<<", end="<<toBase32Hex(nsec3->d_nexthash)<<endl);
}
}
if (nextCloserFound) {
/* RFC 7129 section-5.6 */
if (needWildcardProof && !provesNSEC3NoWildCard(closestEncloser, qtype, validrrsets, &wildcardExists, cache, log)) {
if (!isOptOut) {
- VLOG(log, "But the existence of a wildcard is not denied for "<<qname<<"/"<<QType(qtype)<<endl);
+ VLOG(log, qname << ": But the existence of a wildcard is not denied for "<<qname<<"/"<<QType(qtype)<<endl);
return dState::NODENIAL;
}
}
return sig->d_siginception - g_signatureInceptionSkew <= now;
}
-static bool checkSignatureWithKey(time_t now, const shared_ptr<RRSIGRecordContent> sig, const shared_ptr<DNSKEYRecordContent> key, const std::string& msg, vState& ede, const OptLog& log)
+static bool checkSignatureWithKey(const DNSName& qname, time_t now, const shared_ptr<RRSIGRecordContent> sig, const shared_ptr<DNSKEYRecordContent> key, const std::string& msg, vState& ede, const OptLog& log)
{
bool result = false;
try {
if (isRRSIGIncepted(now, sig) && isRRSIGNotExpired(now, sig)) {
auto dke = DNSCryptoKeyEngine::makeFromPublicKeyString(key->d_algorithm, key->d_key);
result = dke->verify(msg, sig->d_signature);
- VLOG(log, "signature by key with tag "<<sig->d_tag<<" and algorithm "<<DNSSECKeeper::algorithm2name(sig->d_algorithm)<<" was " << (result ? "" : "NOT ")<<"valid"<<endl);
+ VLOG(log, qname << ": Signature by key with tag "<<sig->d_tag<<" and algorithm "<<DNSSECKeeper::algorithm2name(sig->d_algorithm)<<" was " << (result ? "" : "NOT ")<<"valid"<<endl);
if (!result) {
ede = vState::BogusNoValidRRSIG;
}
}
else {
ede = ((sig->d_siginception - g_signatureInceptionSkew) > now) ? vState::BogusSignatureNotYetValid : vState::BogusSignatureExpired;
- VLOG(log, "Signature is "<<(ede == vState::BogusSignatureNotYetValid ? "not yet valid" : "expired")<<" (inception: "<<sig->d_siginception<<", inception skew: "<<g_signatureInceptionSkew<<", expiration: "<<sig->d_sigexpire<<", now: "<<now<<")"<<endl);
+ VLOG(log, qname << ": Signature is "<<(ede == vState::BogusSignatureNotYetValid ? "not yet valid" : "expired")<<" (inception: "<<sig->d_siginception<<", inception skew: "<<g_signatureInceptionSkew<<", expiration: "<<sig->d_sigexpire<<", now: "<<now<<")"<<endl);
}
}
catch (const std::exception& e) {
- VLOG(log, "Could not make a validator for signature: "<<e.what()<<endl);
+ VLOG(log, qname << ": Could not make a validator for signature: "<<e.what()<<endl);
ede = vState::BogusUnsupportedDNSKEYAlgo;
}
return result;
auto keysMatchingTag = getByTag(keys, signature->d_tag, signature->d_algorithm, log);
if (keysMatchingTag.empty()) {
- VLOG(log, "No key provided for "<<signature->d_tag<<" and algorithm "<<std::to_string(signature->d_algorithm)<<endl;);
+ VLOG(log, name<<"No key provided for "<<signature->d_tag<<" and algorithm "<<std::to_string(signature->d_algorithm)<<endl;);
continue;
}
string msg = getMessageForRRSET(name, *signature, toSign, true);
for (const auto& key : keysMatchingTag) {
vState ede;
- bool signIsValid = checkSignatureWithKey(now, signature, key, msg, ede, log);
+ bool signIsValid = checkSignatureWithKey(name, now, signature, key, msg, ede, log);
foundKey = true;
if (signIsValid) {
isValid = true;
- VLOG(log, "Validated "<<name<<"/"<<DNSRecordContent::NumberToType(signature->d_type)<<endl);
+ VLOG(log, name<< ": Validated "<<name<<"/"<<DNSRecordContent::NumberToType(signature->d_type)<<endl);
// cerr<<"valid"<<endl;
// cerr<<"! validated "<<i->first.first<<"/"<<)<<endl;
}
else {
- VLOG(log, "signature invalid"<<endl);
+ VLOG(log, name << ": signature invalid"<<endl);
if (isRRSIGIncepted(now, signature)) {
noneIncepted = false;
}
isValid = dsrc == dsrc2;
}
catch (const std::exception &e) {
- VLOG(log, "Unable to make DS from DNSKey: "<<e.what()<<endl);
+ VLOG(log, zone << ": Unable to make DS from DNSKey: "<<e.what()<<endl);
}
if (isValid) {
- VLOG(log, "got valid DNSKEY (it matches the DS) with tag "<<dsrc.d_tag<<" and algorithm "<<std::to_string(dsrc.d_algorithm)<<" for "<<zone<<endl);
+ VLOG(log, zone << ": got valid DNSKEY (it matches the DS) with tag "<<dsrc.d_tag<<" and algorithm "<<std::to_string(dsrc.d_algorithm)<<" for "<<zone<<endl);
validkeys.insert(drc);
}
else {
if (dsCreated) {
- VLOG(log, "DNSKEY did not match the DS, parent DS: "<<dsrc.getZoneRepresentation() << " ! = "<<dsrc2.getZoneRepresentation()<<endl);
+ VLOG(log, zone << ": DNSKEY did not match the DS, parent DS: "<<dsrc.getZoneRepresentation() << " ! = "<<dsrc2.getZoneRepresentation()<<endl);
}
}
}
string msg = getMessageForRRSET(zone, *sig, toSign);
for (const auto& key : bytag) {
// cerr<<"validating : ";
- bool signIsValid = checkSignatureWithKey(now, sig, key, msg, ede, log);
+ bool signIsValid = checkSignatureWithKey(zone, now, sig, key, msg, ede, log);
if (signIsValid)
{
- VLOG(log, "validation succeeded - whole DNSKEY set is valid"<<endl);
+ VLOG(log, zone << ": Validation succeeded - whole DNSKEY set is valid"<<endl);
validkeys = tkeys;
break;
}
else {
- VLOG(log, "Validation did not succeed!"<<endl);
+ VLOG(log, zone << ": Validation did not succeed!"<<endl);
}
}
// if(validkeys.empty()) cerr<<"did not manage to validate DNSKEY set based on DS-validated KSK, only passing KSK on"<<endl;
projects / thirdparty / pdns.git / commitdiff
