From: Otto Moerbeek Date: Wed, 25 Jan 2023 13:26:35 +0000 (+0100) Subject: Make sure validation and aggressive cache logging also uses the right prefix X-Git-Tag: dnsdist-1.8.0-rc1~38^2~8 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=baaa61a147678a26fcd3639fe656628acc9ecb7e;p=thirdparty%2Fpdns.git Make sure validation and aggressive cache logging also uses the right prefix More complex than you'd think, as this code "builds up" logg lines --- diff --git a/pdns/logger.hh b/pdns/logger.hh index 61ef70a00c..718a7f47c4 100644 --- a/pdns/logger.hh +++ b/pdns/logger.hh @@ -193,7 +193,7 @@ void addTraceTS(const timeval& start, ostringstream& str); #define VLOG(log, x) \ if (log) { \ - if (std::holds_alternative((log)->v)) { \ + if (std::holds_alternative((log)->v)) { \ *std::get(log->v) << Logger::Warning << (log)->prefix << x; \ } \ else if (std::holds_alternative((log)->v)) { \ @@ -201,4 +201,16 @@ void addTraceTS(const timeval& start, ostringstream& str); *std::get((log)->v) << (log)->prefix << x; \ } \ } + +#define VLOG_NO_PREFIX(log, x) \ + if (log) { \ + if (std::holds_alternative((log)->v)) { \ + *std::get(log->v) << Logger::Warning << x; \ + } \ + else if (std::holds_alternative((log)->v)) { \ + addTraceTS((log)->start, *std::get((log)->v)); \ + *std::get((log)->v) << x; \ + } \ + } + #endif diff --git a/pdns/recursordist/aggressive_nsec.cc b/pdns/recursordist/aggressive_nsec.cc index 0cb551b66a..7f9ea40842 100644 --- a/pdns/recursordist/aggressive_nsec.cc +++ b/pdns/recursordist/aggressive_nsec.cc @@ -468,7 +468,7 @@ bool AggressiveNSECCache::synthesizeFromNSEC3Wildcard(time_t now, const DNSName& std::vector> 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; } @@ -477,7 +477,7 @@ bool AggressiveNSECCache::synthesizeFromNSEC3Wildcard(time_t now, const DNSName& 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; } @@ -490,14 +490,14 @@ bool AggressiveNSECCache::synthesizeFromNSECWildcard(time_t now, const DNSName& std::vector> 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; } @@ -522,15 +522,15 @@ bool AggressiveNSECCache::getNSEC3Denial(time_t now, std::shared_ptr(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; } @@ -544,12 +544,12 @@ bool AggressiveNSECCache::getNSEC3Denial(time_t now, std::shared_ptr(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; } @@ -587,12 +587,12 @@ bool AggressiveNSECCache::getNSEC3Denial(time_t now, std::shared_ptr(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; } @@ -644,20 +644,20 @@ bool AggressiveNSECCache::getNSEC3Denial(time_t now, std::shared_ptr(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; } @@ -671,17 +671,17 @@ bool AggressiveNSECCache::getNSEC3Denial(time_t now, std::shared_ptr(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; } @@ -722,7 +722,7 @@ bool AggressiveNSECCache::getNSEC3Denial(time_t now, std::shared_ptr> 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; } @@ -775,9 +775,9 @@ bool AggressiveNSECCache::getDenial(time_t now, const DNSName& name, const QType 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; } @@ -786,30 +786,30 @@ bool AggressiveNSECCache::getDenial(time_t now, const DNSName& name, const QType 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(wcEntry.d_record); @@ -817,21 +817,21 @@ bool AggressiveNSECCache::getDenial(time_t now, const DNSName& name, const QType 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; } @@ -854,7 +854,7 @@ bool AggressiveNSECCache::getDenial(time_t now, const DNSName& name, const QType 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; } diff --git a/pdns/recursordist/secpoll-recursor.cc b/pdns/recursordist/secpoll-recursor.cc index 0c8d7b869e..9b8761d4ab 100644 --- a/pdns/recursordist/secpoll-recursor.cc +++ b/pdns/recursordist/secpoll-recursor.cc @@ -35,6 +35,7 @@ void doSecPoll(time_t* last_secpoll, Logr::log_t log) sr.setDoDNSSEC(true); sr.setDNSSECValidationRequested(true); } + sr.setId("SecPoll"); vector ret; diff --git a/pdns/recursordist/syncres.cc b/pdns/recursordist/syncres.cc index 1fa55f37c0..a9c1d4aef5 100644 --- a/pdns/recursordist/syncres.cc +++ b/pdns/recursordist/syncres.cc @@ -882,9 +882,6 @@ void SyncRes::AuthDomain::addSOA(std::vector& records) const dr.d_place = DNSResourceRecord::AUTHORITY; records.push_back(dr); } - else { - // cerr<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); } @@ -1814,7 +1805,7 @@ int SyncRes::doResolveNoQNameMinimization(const DNSName& qname, const QType qtyp { 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(); @@ -1842,7 +1833,7 @@ int SyncRes::doResolveNoQNameMinimization(const DNSName& qname, const QType qtyp 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) { @@ -2011,7 +2002,7 @@ int SyncRes::doResolveNoQNameMinimization(const DNSName& qname, const QType qtyp return 0; } - LOG(prefix << qname << ": failed (res=" << res << ")" << endl); + LOG(prefix << qname << ": Failed (res=" << res << ")" << endl); if (res >= 0) { break; } @@ -2180,7 +2171,7 @@ vector SyncRes::getAddrs(const DNSName& qname, unsigned int depth, } if (doLog()) { - LOG(prefix << "Nameserver " << qname << " IPs: "); + LOG(prefix << qname << ": Nameserver " << qname << " IPs: "); bool first = true; for (const auto& addr : ret) { if (first) { @@ -2239,10 +2230,10 @@ void SyncRes::getBestNSFromCache(const DNSName& qname, const QType qtype, vector auto nrr = getRR(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); @@ -2273,7 +2264,7 @@ void SyncRes::getBestNSFromCache(const DNSName& qname, const QType qtype, vector if (doLog()) for (set::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(); } @@ -2283,12 +2274,12 @@ void SyncRes::getBestNSFromCache(const DNSName& qname, const QType qtype, vector } } } - 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"); @@ -2362,14 +2353,14 @@ DNSName SyncRes::getBestNSNamesFromCache(const DNSName& qname, const QType qtype // 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); } } } @@ -2413,7 +2404,7 @@ static bool scanForCNAMELoop(const DNSName& name, const vector& recor bool SyncRes::doCNAMECacheCheck(const DNSName& qname, const QType qtype, vector& 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; } @@ -2485,10 +2476,10 @@ bool SyncRes::doCNAMECacheCheck(const DNSName& qname, const QType qtype, vector< 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; } @@ -2573,14 +2564,14 @@ bool SyncRes::doCNAMECacheCheck(const DNSName& qname, const QType qtype, vector< } 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); } @@ -2593,7 +2584,7 @@ bool SyncRes::doCNAMECacheCheck(const DNSName& qname, const QType qtype, vector< // 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); } @@ -2602,8 +2593,8 @@ bool SyncRes::doCNAMECacheCheck(const DNSName& qname, const QType qtype, vector< // 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; } @@ -2707,7 +2698,7 @@ void SyncRes::computeNegCacheValidationStatus(const NegCache::NegCacheEntry& ne, } if (recordState != vState::Indeterminate && recordState != state) { - updateValidationState(state, recordState, prefix); + updateValidationState(qname, state, recordState, prefix); if (state != vState::Secure) { break; } @@ -2718,7 +2709,7 @@ void SyncRes::computeNegCacheValidationStatus(const NegCache::NegCacheEntry& ne, 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 */ @@ -2768,7 +2759,7 @@ bool SyncRes::doCacheCheck(const DNSName& qname, const DNSName& authname, bool w 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"}; @@ -2818,7 +2809,7 @@ bool SyncRes::doCacheCheck(const DNSName& qname, const DNSName& authname, bool w 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)) { @@ -2834,7 +2825,7 @@ bool SyncRes::doCacheCheck(const DNSName& qname, const DNSName& authname, bool w 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; } @@ -2865,7 +2856,7 @@ bool SyncRes::doCacheCheck(const DNSName& qname, const DNSName& authname, bool w 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); } @@ -2896,7 +2887,7 @@ bool SyncRes::doCacheCheck(const DNSName& qname, const DNSName& authname, bool w } 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; } @@ -2952,12 +2943,12 @@ bool SyncRes::doCacheCheck(const DNSName& qname, const DNSName& authname, bool w 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 */ @@ -2987,7 +2978,7 @@ struct speedOrder } }; -inline std::vector> SyncRes::shuffleInSpeedOrder(NsSet& tnameservers, const string& prefix) +std::vector> SyncRes::shuffleInSpeedOrder(const DNSName& qname, NsSet& tnameservers, const string& prefix) { std::vector> rnameservers; rnameservers.reserve(tnameservers.size()); @@ -3003,7 +2994,7 @@ inline std::vector> SyncRes::shuffleInSpeedOrder(NsSet 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(", "); @@ -3019,7 +3010,7 @@ inline std::vector> SyncRes::shuffleInSpeedOrder(NsSet return rnameservers; } -inline vector SyncRes::shuffleForwardSpeed(const vector& rnameservers, const string& prefix, const bool wasRd) +vector SyncRes::shuffleForwardSpeed(const DNSName &qname, const vector& rnameservers, const string& prefix, const bool wasRd) { vector nameservers = rnameservers; map speeds; @@ -3034,7 +3025,7 @@ inline vector SyncRes::shuffleForwardSpeed(const vector::const_iterator i = nameservers.cbegin(); i != nameservers.cend(); ++i) { if (i != nameservers.cbegin()) { LOG(", "); @@ -3206,7 +3197,7 @@ void SyncRes::handlePolicyHit(const std::string& prefix, const DNSName& qname, c } 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) { @@ -3372,7 +3363,7 @@ vector SyncRes::retrieveAddressesForNS(const std::string& prefix, 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; @@ -3388,13 +3379,13 @@ void SyncRes::checkMaxQperQ(const DNSName& qname) const 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; @@ -3405,7 +3396,7 @@ bool SyncRes::throttledOrBlocked(const std::string& prefix, const ComboAddress& 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; } @@ -3413,12 +3404,12 @@ bool SyncRes::throttledOrBlocked(const std::string& prefix, const ComboAddress& // 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); } } } @@ -3470,9 +3461,9 @@ uint32_t SyncRes::computeLowestTTD(const std::vector& records, const 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); } @@ -3482,24 +3473,23 @@ vState SyncRes::getTA(const DNSName& zone, dsmap_t& ds, const string& prefix) 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 */ @@ -3662,7 +3652,7 @@ vState SyncRes::getDSRecords(const DNSName& zone, dsmap_t& ds, bool taOnly, unsi 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; } @@ -3682,7 +3672,7 @@ vState SyncRes::getValidationStatus(const DNSName& name, bool wouldBeValid, bool { 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; } } @@ -3694,7 +3684,7 @@ vState SyncRes::getValidationStatus(const DNSName& name, bool wouldBeValid, bool 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; @@ -3707,7 +3697,7 @@ vState SyncRes::getValidationStatus(const DNSName& name, bool wouldBeValid, bool 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 labelsToAdd = subdomain.makeRelative(ds).getRawLabels(); @@ -3715,15 +3705,15 @@ vState SyncRes::getValidationStatus(const DNSName& name, bool wouldBeValid, bool 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) { @@ -3760,7 +3750,7 @@ vState SyncRes::validateDNSKeys(const DNSName& zone, const std::vector records; std::set beenthere; - LOG(prefix << "Retrieving DNSKeys for " << signer << endl); + LOG(prefix << signer << ": Retrieving DNSKeys" << endl); Context context; @@ -3855,7 +3845,7 @@ vState SyncRes::getDNSKeys(const DNSName& signer, skeyset_t& keys, bool& servFai } } } - 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; } @@ -3863,7 +3853,7 @@ vState SyncRes::getDNSKeys(const DNSName& signer, skeyset_t& keys, bool& servFai 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; } @@ -3871,7 +3861,7 @@ vState SyncRes::validateRecordsWithSigs(unsigned int depth, const string& prefix { skeyset_t keys; if (signatures.empty()) { - LOG(prefix << "Bogus!" << endl); + LOG(prefix << qname << ": Bogus!" << endl); return vState::BogusNoRRSIG; } @@ -3886,7 +3876,7 @@ vState SyncRes::validateRecordsWithSigs(unsigned int depth, const string& prefix /* 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; } @@ -3921,7 +3911,7 @@ vState SyncRes::validateRecordsWithSigs(unsigned int depth, const string& prefix } } 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; } @@ -3930,14 +3920,14 @@ vState SyncRes::validateRecordsWithSigs(unsigned int depth, const string& prefix /* 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); } @@ -3946,14 +3936,14 @@ vState SyncRes::validateRecordsWithSigs(unsigned int depth, const string& 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 { @@ -3967,20 +3957,20 @@ vState SyncRes::validateRecordsWithSigs(unsigned int depth, const string& prefix 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 { @@ -4016,7 +4006,7 @@ void SyncRes::fixupAnswer(const std::string& prefix, LWResult& lwr, const DNSNam 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; } @@ -4093,19 +4083,19 @@ void SyncRes::sanitizeRecords(const std::string& prefix, LWResult& lwr, const DN } 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; } @@ -4115,20 +4105,20 @@ void SyncRes::sanitizeRecords(const std::string& prefix, LWResult& lwr, const DN /* 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; } @@ -4143,20 +4133,20 @@ void SyncRes::sanitizeRecords(const std::string& prefix, LWResult& lwr, const DN /* 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; } @@ -4177,7 +4167,7 @@ void SyncRes::sanitizeRecords(const std::string& prefix, LWResult& lwr, const DN * 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; } @@ -4187,7 +4177,7 @@ void SyncRes::sanitizeRecords(const std::string& prefix, LWResult& lwr, const DN * 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; } @@ -4198,13 +4188,13 @@ void SyncRes::sanitizeRecords(const std::string& prefix, LWResult& lwr, const DN /* 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; } @@ -4241,7 +4231,7 @@ void SyncRes::rememberParentSetIfNeeded(const DNSName& domain, const vector(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; } @@ -4353,7 +4343,7 @@ RCode::rcodes_ SyncRes::updateCacheFromRecords(unsigned int depth, const string& 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 @@ -4421,9 +4411,6 @@ RCode::rcodes_ SyncRes::updateCacheFromRecords(unsigned int depth, const string& record.d_ttl = lowestTTD; // boom } } - - // cout<<"Have "<second.records.size()<<" records and "<second.signatures.size()<<" signatures for "<first.name; - // cout<<'|'<first.type)<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; } @@ -4505,26 +4492,26 @@ RCode::rcodes_ SyncRes::updateCacheFromRecords(unsigned int depth, const string& 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); } } @@ -4625,14 +4612,14 @@ RCode::rcodes_ SyncRes::updateCacheFromRecords(unsigned int depth, const string& 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 @@ -4650,23 +4637,23 @@ void SyncRes::updateDenialValidationState(vState& neValidationState, const DNSNa 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) @@ -4703,7 +4690,7 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co } 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 @@ -4730,11 +4717,11 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co 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); } } @@ -4811,7 +4798,7 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co } // 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; @@ -4843,14 +4830,14 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co /* 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); } @@ -4874,7 +4861,7 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co 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)) { @@ -4889,14 +4876,14 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co } } 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(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 */ @@ -4922,7 +4909,7 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co 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); @@ -4940,7 +4927,7 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co } } 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); @@ -4962,11 +4949,11 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co 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); } } @@ -5000,13 +4987,13 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co /* 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; @@ -5137,12 +5124,12 @@ bool SyncRes::doResolveAtThisIP(const std::string& prefix, const DNSName& qname, 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++; } @@ -5150,7 +5137,7 @@ bool SyncRes::doResolveAtThisIP(const std::string& prefix, const DNSName& qname, 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); @@ -5194,7 +5181,7 @@ bool SyncRes::doResolveAtThisIP(const std::string& prefix, const DNSName& qname, 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)++; @@ -5208,7 +5195,7 @@ bool SyncRes::doResolveAtThisIP(const std::string& prefix, const DNSName& qname, } 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) { @@ -5219,7 +5206,7 @@ bool SyncRes::doResolveAtThisIP(const std::string& prefix, const DNSName& qname, 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) { @@ -5291,14 +5278,14 @@ bool SyncRes::doResolveAtThisIP(const std::string& prefix, const DNSName& qname, 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; } @@ -5309,19 +5296,19 @@ bool SyncRes::doResolveAtThisIP(const std::string& prefix, const DNSName& qname, void SyncRes::handleNewTarget(const std::string& prefix, const DNSName& qname, const DNSName& newtarget, const QType qtype, std::vector& ret, int& rcode, int depth, const std::vector& 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; } @@ -5333,14 +5320,14 @@ void SyncRes::handleNewTarget(const std::string& prefix, const DNSName& qname, c // 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); @@ -5350,13 +5337,13 @@ void SyncRes::handleNewTarget(const std::string& prefix, const DNSName& qname, c 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 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 ednsmask, bool sendRDQuery, NsSet& nameservers, std::vector& ret, const DNSFilterEngine& dfe, bool* gotNewServers, int* rcode, vState& state, const ComboAddress& remoteIP) @@ -5385,7 +5372,7 @@ bool SyncRes::processAnswer(unsigned int depth, const string& prefix, LWResult& return true; } - LOG(prefix << qname << ": determining status after receiving this packet" << endl); + LOG(prefix << qname << ": Determining status after receiving this packet" << endl); set nsset; bool realreferral = false; @@ -5397,8 +5384,8 @@ bool SyncRes::processAnswer(unsigned int depth, const string& prefix, LWResult& 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; } @@ -5408,17 +5395,17 @@ bool SyncRes::processAnswer(unsigned int depth, const string& prefix, LWResult& } 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) { @@ -5430,17 +5417,17 @@ bool SyncRes::processAnswer(unsigned int depth, const string& prefix, LWResult& } 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) { @@ -5452,7 +5439,7 @@ bool SyncRes::processAnswer(unsigned int depth, const string& prefix, LWResult& } 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) { @@ -5517,7 +5504,7 @@ int SyncRes::doResolveAt(NsSet& nameservers, DNSName auth, bool flawedNSSet, con 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. diff --git a/pdns/recursordist/syncres.hh b/pdns/recursordist/syncres.hh index ef6e27db56..8554398386 100644 --- a/pdns/recursordist/syncres.hh +++ b/pdns/recursordist/syncres.hh @@ -624,8 +624,8 @@ private: void getBestNSFromCache(const DNSName& qname, QType qtype, vector& bestns, bool* flawedNSSet, unsigned int depth, const string& prefix, set& beenthere, const boost::optional& cutOffDomain = boost::none); DNSName getBestNSNamesFromCache(const DNSName& qname, QType qtype, NsSet& nsset, bool* flawedNSSet, unsigned int depth, const string& prefix, set& beenthere); - inline vector> shuffleInSpeedOrder(NsSet& nameservers, const string& prefix); - inline vector shuffleForwardSpeed(const vector& rnameservers, const string& prefix, const bool wasRd); + vector> shuffleInSpeedOrder(const DNSName& qname, NsSet& nameservers, const string& prefix); + vector shuffleForwardSpeed(const DNSName& qname, const vector& rnameservers, const string& prefix, const bool wasRd); bool moreSpecificThan(const DNSName& a, const DNSName& b) const; vector getAddrs(const DNSName& qname, unsigned int depth, const string& prefix, set& beenthere, bool cacheOnly, unsigned int& addressQueriesForNS); @@ -652,12 +652,12 @@ private: bool validationEnabled() const; uint32_t computeLowestTTD(const std::vector& records, const std::vector>& signatures, uint32_t signaturesTTL, const std::vector>& authorityRecs) const; - void updateValidationState(vState& state, const vState stateUpdate, const string& prefix); + void updateValidationState(const DNSName& qname, vState& state, const vState stateUpdate, const string& prefix); vState validateRecordsWithSigs(unsigned int depth, const string& prefix, const DNSName& qname, const QType qtype, const DNSName& name, const QType type, const std::vector& records, const std::vector>& signatures); vState validateDNSKeys(const DNSName& zone, const std::vector& dnskeys, const std::vector>& signatures, unsigned int depth, const string& prefix); vState getDNSKeys(const DNSName& signer, skeyset_t& keys, bool& servFailOccurred, unsigned int depth, const string& prefix); dState getDenialValidationState(const NegCache::NegCacheEntry& ne, const dState expectedState, bool referralToUnsigned, const string& prefix); - void updateDenialValidationState(vState& neValidationState, const DNSName& neName, vState& state, const dState denialState, const dState expectedState, bool isDS, unsigned int depth, const string& prefix); + void 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); void computeNegCacheValidationStatus(const NegCache::NegCacheEntry& ne, const DNSName& qname, QType qtype, const int res, vState& state, unsigned int depth, const string& prefix); vState getTA(const DNSName& zone, dsmap_t& ds, const string& prefix); vState getValidationStatus(const DNSName& subdomain, bool wouldBeValid, bool typeIsDS, unsigned int depth, const string& prefix); diff --git a/pdns/validate.cc b/pdns/validate.cc index 5a085feca1..02efdcc3b9 100644 --- a/pdns/validate.cc +++ b/pdns/validate.cc @@ -245,12 +245,12 @@ bool isNSEC3AncestorDelegation(const DNSName& signer, const DNSName& owner, cons 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 "<getZoneRepresentation()<getZoneRepresentation()<(r); if (!nsec) { continue; @@ -261,12 +261,12 @@ static bool provesNoDataWildCard(const DNSName& qname, const uint16_t qtype, con 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"<getZoneRepresentation()<getZoneRepresentation()<(r); if (!nsec) { continue; } const DNSName owner = getNSECOwnerName(v.first.first, v.second.signatures); - VLOG(log, "Comparing owner: "<isSet(QType::DNAME)) { /* rfc6672 section 5.3.2: DNAME Bit in NSEC Type Map @@ -316,12 +316,12 @@ static bool provesNoWildCard(const DNSName& qname, const uint16_t qtype, const D 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"<d_next)) { - VLOG(log, "\tWildcard is covered"<getZoneRepresentation()<getZoneRepresentation()<(r); if (!nsec3) { continue; @@ -361,12 +361,12 @@ static bool provesNSEC3NoWildCard(const DNSName& closestEncloser, uint16_t const if (h.empty()) { return false; } - VLOG(log, "\tWildcard hash: "< "<d_nexthash)< "<d_nexthash)<d_nexthash)) { - VLOG(log, "\tWildcard hash is covered"<d_next)) { - VLOG(log, name<<" is covered by ("<d_next<<") "); + VLOG_NO_PREFIX(log, name << ": is covered by ("<d_next<<")"); if (nsecProvesENT(name, owner, nsec->d_next)) { - VLOG(log, "Denies existence of type "<getZoneRepresentation()<getZoneRepresentation()<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!"<isSet(QType::NS)) { - VLOG(log, "However, no NS record exists at this level!"<d_next)) { - VLOG(log, qname<<" is covered by ("<d_next<<") "); + VLOG(log, qname<< ": Is covered by ("<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 "<d_next); if (wantsNoDataProof) { - VLOG(log, "looking for NODATA proof"<isSet(qtype)<<", next: "<d_next<isSet(qtype)<<", next: "<d_next<getZoneRepresentation()<getZoneRepresentation()<(r); if (!nsec3) { continue; @@ -654,24 +654,24 @@ dState getDenial(const cspmap_t &validrrsets, const DNSName& qname, const uint16 const DNSName& hashedOwner = v.first.first; const DNSName signer = getSigner(v.second.signatures); if (!hashedOwner.isPartOf(signer)) { - VLOG(log, "Owner "<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!"<isSet(QType::NS)) { - VLOG(log, "However, no NS record exists at this level!"<getZoneRepresentation()<getZoneRepresentation()<(r); if (!nsec3) { continue; @@ -754,7 +754,7 @@ dState getDenial(const cspmap_t &validrrsets, const DNSName& qname, const uint16 const DNSName signer = getSigner(v.second.signatures); if (!v.first.first.isPartOf(signer)) { - VLOG(log, "Owner "<isSet(QType::DNAME)) { @@ -786,7 +786,7 @@ dState getDenial(const cspmap_t &validrrsets, const DNSName& qname, const uint16 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"<= 1) { DNSName nextCloser(closestEncloser); nextCloser.prependRawLabel(qname.getRawLabel(labelIdx - 1)); - VLOG(log, "Looking for a NSEC3 covering the next closer name "<getZoneRepresentation()<getZoneRepresentation()<(r); if(!nsec3) continue; @@ -842,26 +842,26 @@ dState getDenial(const cspmap_t &validrrsets, const DNSName& qname, const uint16 const DNSName signer = getSigner(v.second.signatures); if (!v.first.first.isPartOf(signer)) { - VLOG(log, "Owner "< "<d_nexthash)< "<d_nexthash)<d_nexthash)) { - VLOG(log, "Denies existence of name "<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 ("<& sig return sig->d_siginception - g_signatureInceptionSkew <= now; } -static bool checkSignatureWithKey(time_t now, const shared_ptr sig, const shared_ptr key, const std::string& msg, vState& ede, const OptLog& log) +static bool checkSignatureWithKey(const DNSName& qname, time_t now, const shared_ptr sig, const shared_ptr key, const std::string& msg, vState& ede, const OptLog& log) { bool result = false; try { @@ -919,18 +919,18 @@ static bool checkSignatureWithKey(time_t now, const shared_ptrd_algorithm, key->d_key); result = dke->verify(msg, sig->d_signature); - VLOG(log, "signature by key with tag "<d_tag<<" and algorithm "<d_algorithm)<<" was " << (result ? "" : "NOT ")<<"valid"<d_tag<<" and algorithm "<d_algorithm)<<" was " << (result ? "" : "NOT ")<<"valid"<d_siginception - g_signatureInceptionSkew) > now) ? vState::BogusSignatureNotYetValid : vState::BogusSignatureExpired; - VLOG(log, "Signature is "<<(ede == vState::BogusSignatureNotYetValid ? "not yet valid" : "expired")<<" (inception: "<d_siginception<<", inception skew: "<d_sigexpire<<", now: "<d_siginception<<", inception skew: "<d_sigexpire<<", now: "<d_tag, signature->d_algorithm, log); if (keysMatchingTag.empty()) { - VLOG(log, "No key provided for "<d_tag<<" and algorithm "<d_algorithm)<d_tag<<" and algorithm "<d_algorithm)<d_type)<d_type)<first.first<<"/"<<)<