From cb273be5968d356c5737e807d60afebe5cd83c55 Mon Sep 17 00:00:00 2001 From: Otto Moerbeek Date: Mon, 16 Jan 2023 11:31:51 +0100 Subject: [PATCH] Consistently use prefix and mark trace regex lines --- pdns/recursordist/aggressive_nsec.cc | 2 +- pdns/recursordist/pdns_recursor.cc | 1 + pdns/recursordist/syncres.cc | 198 +++++++++++++-------------- pdns/recursordist/syncres.hh | 30 ++-- pdns/validate.cc | 2 +- 5 files changed, 121 insertions(+), 112 deletions(-) diff --git a/pdns/recursordist/aggressive_nsec.cc b/pdns/recursordist/aggressive_nsec.cc index 1b18dc4b67..d4b5c5c212 100644 --- a/pdns/recursordist/aggressive_nsec.cc +++ b/pdns/recursordist/aggressive_nsec.cc @@ -473,7 +473,7 @@ static void addRecordToRRSet(time_t now, const DNSName& owner, const QType& type *std::get(log->v) << Logger::Warning << log->prefix << x; \ } \ else if (std::holds_alternative(log->v)) { \ - *std::get(log->v) << x; \ + *std::get(log->v) << x << log->prefix; \ } \ } diff --git a/pdns/recursordist/pdns_recursor.cc b/pdns/recursordist/pdns_recursor.cc index d5f906a1b3..b9420e7455 100644 --- a/pdns/recursordist/pdns_recursor.cc +++ b/pdns/recursordist/pdns_recursor.cc @@ -1060,6 +1060,7 @@ void startDoResolve(void* p) if (t_traceRegex && t_traceRegex->match(dc->d_mdp.d_qname.toString())) { sr.setLogMode(SyncRes::Store); tracedQuery = true; + sr.setId("T"); } if (!g_quiet || tracedQuery) { diff --git a/pdns/recursordist/syncres.cc b/pdns/recursordist/syncres.cc index 8c8e733dee..4e7ad60767 100644 --- a/pdns/recursordist/syncres.cc +++ b/pdns/recursordist/syncres.cc @@ -2488,10 +2488,10 @@ bool SyncRes::doCNAMECacheCheck(const DNSName& qname, const QType qtype, vector< if (!wasAuthZone && shouldValidate() && (wasAuth || wasForwardRecurse) && context.state == vState::Indeterminate && d_requireAuthData) { /* This means we couldn't figure out the state when this entry was cached */ - vState recordState = getValidationStatus(foundName, !signatures.empty(), qtype == QType::DS, depth); + 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); - context.state = SyncRes::validateRecordsWithSigs(depth, qname, qtype, foundName, foundQT, cset, signatures); + 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); if (vStateIsBogus(context.state)) { @@ -2608,7 +2608,7 @@ bool SyncRes::doCNAMECacheCheck(const DNSName& qname, const QType qtype, vector< // 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); + updateValidationState(context.state, cnameContext.state, prefix); return true; } @@ -2702,17 +2702,17 @@ void SyncRes::computeNegCacheValidationStatus(const NegCache::NegCacheEntry& ne, const DNSName& owner = entry.first.name; - vState recordState = getValidationStatus(owner, !entry.second.signatures.empty(), qtype == QType::DS, depth); + vState recordState = getValidationStatus(owner, !entry.second.signatures.empty(), qtype == QType::DS, depth, prefix); if (state == vState::Indeterminate) { state = recordState; } if (recordState == vState::Secure) { - recordState = SyncRes::validateRecordsWithSigs(depth, qname, qtype, owner, QType(entry.first.type), entry.second.records, entry.second.signatures); + recordState = SyncRes::validateRecordsWithSigs(depth, prefix, qname, qtype, owner, QType(entry.first.type), entry.second.records, entry.second.signatures); } if (recordState != vState::Indeterminate && recordState != state) { - updateValidationState(state, recordState); + updateValidationState(state, recordState, prefix); if (state != vState::Secure) { break; } @@ -2723,7 +2723,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); + updateDenialValidationState(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 */ @@ -2869,12 +2869,12 @@ bool SyncRes::doCacheCheck(const DNSName& qname, const DNSName& authname, bool w if (!wasAuthZone && shouldValidate() && (wasCachedAuth || wasForwardRecurse) && cachedState == vState::Indeterminate && d_requireAuthData) { /* This means we couldn't figure out the state when this entry was cached */ - vState recordState = getValidationStatus(qname, !signatures.empty(), qtype == QType::DS, depth); + 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); if (sqt == QType::DNSKEY && sqname == getSigner(signatures)) { - cachedState = validateDNSKeys(sqname, cset, signatures, depth); + cachedState = validateDNSKeys(sqname, cset, signatures, depth, prefix); } else { if (sqt == QType::ANY) { @@ -2885,16 +2885,16 @@ bool SyncRes::doCacheCheck(const DNSName& qname, const DNSName& authname, bool w for (const auto& type : types) { vState cachedRecordState; if (type.first == QType::DNSKEY && sqname == getSigner(type.second.signatures)) { - cachedRecordState = validateDNSKeys(sqname, type.second.records, type.second.signatures, depth); + cachedRecordState = validateDNSKeys(sqname, type.second.records, type.second.signatures, depth, prefix); } else { - cachedRecordState = SyncRes::validateRecordsWithSigs(depth, qname, qtype, sqname, type.first, type.second.records, type.second.signatures); + cachedRecordState = SyncRes::validateRecordsWithSigs(depth, prefix, qname, qtype, sqname, type.first, type.second.records, type.second.signatures); } updateDNSSECValidationState(cachedState, cachedRecordState); } } else { - cachedState = SyncRes::validateRecordsWithSigs(depth, qname, qtype, sqname, sqt, cset, signatures); + cachedState = SyncRes::validateRecordsWithSigs(depth, prefix, qname, qtype, sqname, sqt, cset, signatures); } } } @@ -3477,35 +3477,35 @@ uint32_t SyncRes::computeLowestTTD(const std::vector& records, const return lowestTTD; } -void SyncRes::updateValidationState(vState& state, const vState stateUpdate) +void SyncRes::updateValidationState(vState& state, const vState stateUpdate, const string& prefix) { - LOG(d_prefix << "validation state was " << state << ", state update is " << stateUpdate); + LOG(prefix << "validation state was " << state << ", state update is " << stateUpdate); updateDNSSECValidationState(state, stateUpdate); LOG(", validation state is now " << state << endl); } -vState SyncRes::getTA(const DNSName& zone, dsmap_t& ds) +vState SyncRes::getTA(const DNSName& zone, dsmap_t& ds, const string& prefix) { auto luaLocal = g_luaconfs.getLocal(); if (luaLocal->dsAnchors.empty()) { - LOG(d_prefix << ": No trust anchors configured, everything is Insecure" << endl); + LOG(prefix << ": 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(d_prefix << ": got NTA for '" << zone << "'" << endl); + LOG(prefix << ": got NTA for '" << zone << "'" << endl); return vState::NTA; } if (getTrustAnchor(luaLocal->dsAnchors, zone, ds)) { - LOG(d_prefix << ": got TA for '" << zone << "'" << endl); + LOG(prefix << ": got TA for '" << zone << "'" << endl); return vState::TA; } else { - LOG(d_prefix << ": no TA found for '" << zone << "' among " << luaLocal->dsAnchors.size() << endl); + LOG(prefix << ": no TA found for '" << zone << "' among " << luaLocal->dsAnchors.size() << endl); } if (zone.isRoot()) { @@ -3534,7 +3534,7 @@ void SyncRes::initZoneCutsFromTA(const DNSName& from, const string& prefix) DNSName zone(from); do { dsmap_t ds; - vState result = getTA(zone, ds); + vState result = getTA(zone, ds, prefix); if (result != vState::Indeterminate) { if (result == vState::TA) { if (countSupportedDS(ds, prefix) == 0) { @@ -3556,7 +3556,7 @@ void SyncRes::initZoneCutsFromTA(const DNSName& from, const string& prefix) vState SyncRes::getDSRecords(const DNSName& zone, dsmap_t& ds, bool taOnly, unsigned int depth, const string& prefix, bool bogusOnNXD, bool* foundCut) { - vState result = getTA(zone, ds); + vState result = getTA(zone, ds, prefix); if (result != vState::Indeterminate || taOnly) { if (foundCut) { @@ -3669,11 +3669,11 @@ vState SyncRes::getDSRecords(const DNSName& zone, dsmap_t& ds, bool taOnly, unsi return context.state; } - LOG(d_prefix << ": returning Bogus state from " << __func__ << "(" << zone << ")" << endl); + LOG(prefix << ": returning Bogus state from " << __func__ << "(" << zone << ")" << endl); return vState::BogusUnableToGetDSs; } -vState SyncRes::getValidationStatus(const DNSName& name, bool wouldBeValid, bool typeIsDS, unsigned int depth) +vState SyncRes::getValidationStatus(const DNSName& name, bool wouldBeValid, bool typeIsDS, unsigned int depth, const string& prefix) { vState result = vState::Indeterminate; @@ -3689,7 +3689,7 @@ vState SyncRes::getValidationStatus(const DNSName& name, bool wouldBeValid, bool { const auto& it = d_cutStates.find(subdomain); if (it != d_cutStates.cend()) { - LOG(d_prefix << ": got status " << it->second << " for name " << subdomain << endl); + LOG(prefix << ": got status " << it->second << " for name " << subdomain << endl); return it->second; } } @@ -3701,7 +3701,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(d_prefix << ": got status " << result << " for name " << best << endl); + LOG(prefix << ": got status " << result << " for name " << best << endl); return result; } break; @@ -3714,7 +3714,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(d_prefix << ": no or invalid signature/proof for " << name << ", we likely missed a cut between " << best << " and " << subdomain << ", looking for it" << endl); + LOG(prefix << ": 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(); @@ -3722,15 +3722,15 @@ vState SyncRes::getValidationStatus(const DNSName& name, bool wouldBeValid, bool ds.prependRawLabel(labelsToAdd.back()); labelsToAdd.pop_back(); - LOG(d_prefix << ": - Looking for a DS at " << ds << endl); + LOG(prefix << ": - Looking for a DS at " << ds << endl); bool foundCut = false; dsmap_t results; vState dsState = getDSRecords(ds, results, false, depth, d_prefix, false, &foundCut); if (foundCut) { - LOG(d_prefix << ": - Found cut at " << ds << endl); - LOG(d_prefix << ": New state for " << ds << " is " << dsState << endl); + LOG(prefix << ": - Found cut at " << ds << endl); + LOG(prefix << ": New state for " << ds << " is " << dsState << endl); d_cutStates[ds] = dsState; if (dsState != vState::Secure) { @@ -3763,11 +3763,11 @@ vState SyncRes::getValidationStatus(const DNSName& name, bool wouldBeValid, bool return result; } -vState SyncRes::validateDNSKeys(const DNSName& zone, const std::vector& dnskeys, const std::vector>& signatures, unsigned int depth) +vState SyncRes::validateDNSKeys(const DNSName& zone, const std::vector& dnskeys, const std::vector>& signatures, unsigned int depth, const string& prefix) { dsmap_t ds; if (signatures.empty()) { - LOG(d_prefix << ": we have " << std::to_string(dnskeys.size()) << " DNSKEYs but no signature, going Bogus!" << endl); + LOG(prefix << ": we have " << std::to_string(dnskeys.size()) << " DNSKEYs but no signature, going Bogus!" << endl); return vState::BogusNoRRSIG; } @@ -3781,12 +3781,12 @@ vState SyncRes::validateDNSKeys(const DNSName& zone, const std::vector records; std::set beenthere; - LOG(d_prefix << "Retrieving DNSKeys for " << signer << endl); + LOG(prefix << "Retrieving DNSKeys for " << signer << endl); Context context; @@ -3862,7 +3862,7 @@ vState SyncRes::getDNSKeys(const DNSName& signer, skeyset_t& keys, bool& servFai } } } - LOG(d_prefix << "Retrieved " << keys.size() << " DNSKeys for " << signer << ", state is " << context.state << endl); + LOG(prefix << "Retrieved " << keys.size() << " DNSKeys for " << signer << ", state is " << context.state << endl); return context.state; } @@ -3870,15 +3870,15 @@ vState SyncRes::getDNSKeys(const DNSName& signer, skeyset_t& keys, bool& servFai return context.state; } - LOG(d_prefix << "Returning Bogus state from " << __func__ << "(" << signer << ")" << endl); + LOG(prefix << "Returning Bogus state from " << __func__ << "(" << signer << ")" << endl); return vState::BogusUnableToGetDNSKEYs; } -vState SyncRes::validateRecordsWithSigs(unsigned int depth, const DNSName& qname, const QType qtype, const DNSName& name, const QType type, const std::vector& records, const std::vector>& signatures) +vState SyncRes::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) { skeyset_t keys; if (signatures.empty()) { - LOG(d_prefix << "Bogus!" << endl); + LOG(prefix << "Bogus!" << endl); return vState::BogusNoRRSIG; } @@ -3893,7 +3893,7 @@ vState SyncRes::validateRecordsWithSigs(unsigned int depth, const DNSName& qname /* 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(d_prefix << "The DS for " << qname << " is signed by itself" << endl); + LOG(prefix << "The DS for " << qname << " is signed by itself" << endl); state = vState::BogusSelfSignedDS; dsFailed = true; } @@ -3928,7 +3928,7 @@ vState SyncRes::validateRecordsWithSigs(unsigned int depth, const DNSName& qname } } else { - LOG(d_prefix << "Unable to get the DS for " << signer << endl); + LOG(prefix << "Unable to get the DS for " << signer << endl); state = vState::BogusUnableToGetDNSKEYs; dsFailed = true; } @@ -3937,15 +3937,15 @@ vState SyncRes::validateRecordsWithSigs(unsigned int depth, const DNSName& qname /* 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(d_prefix << "we are looking at a signature done with the key we are trying to obtain " << signer << endl); + LOG(prefix << "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(d_prefix << "retrieving the DNSKEYs for " << signer << endl); - state = getDNSKeys(signer, keys, servFailOccurred, depth); + LOG(prefix << "retrieving the DNSKEYs for " << signer << endl); + state = getDNSKeys(signer, keys, servFailOccurred, depth, prefix); } if (state != vState::Secure) { @@ -3953,14 +3953,14 @@ vState SyncRes::validateRecordsWithSigs(unsigned int depth, const DNSName& qname return state; } /* try again to get the missed cuts, harder this time */ - LOG(d_prefix << "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); + LOG(prefix << "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(d_prefix << "we are still in a Secure zone, returning " << vStateToString(state) << endl); + LOG(prefix << "we are still in a Secure zone, returning " << vStateToString(state) << endl); return state; } else { @@ -3974,20 +3974,20 @@ vState SyncRes::validateRecordsWithSigs(unsigned int depth, const DNSName& qname recordcontents.insert(record.d_content); } - LOG(d_prefix << "Going to validate " << recordcontents.size() << " record contents with " << signatures.size() << " sigs and " << keys.size() << " keys for " << name << "|" << type.toString() << endl); + LOG(prefix << "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(d_prefix), false); if (state == vState::Secure) { - LOG(d_prefix << "Secure!" << endl); + LOG(prefix << "Secure!" << endl); return vState::Secure; } - LOG(d_prefix << vStateToString(state) << "!" << endl); + LOG(prefix << vStateToString(state) << "!" << endl); /* try again to get the missed cuts, harder this time */ - auto zState = getValidationStatus(name, false, type == QType::DS, depth); - LOG(d_prefix << "checking whether we missed a zone cut before returning a Bogus state" << endl); + 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); if (zState == vState::Secure) { /* too bad */ - LOG(d_prefix << "we are still in a Secure zone, returning " << vStateToString(state) << endl); + LOG(prefix << "we are still in a Secure zone, returning " << vStateToString(state) << endl); return state; } else { @@ -4220,7 +4220,7 @@ void SyncRes::sanitizeRecords(const std::string& prefix, LWResult& lwr, const DN } } -void SyncRes::rememberParentSetIfNeeded(const DNSName& domain, const vector& newRecords, unsigned int depth) +void SyncRes::rememberParentSetIfNeeded(const DNSName& domain, const vector& newRecords, unsigned int depth, const string& prefix) { vector existing; bool wasAuth = false; @@ -4248,7 +4248,7 @@ void SyncRes::rememberParentSetIfNeeded(const DNSName& domain, const vector(ns); if (authSet.count(content->getNS()) == 0) { - LOG(d_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; } @@ -4490,7 +4490,7 @@ RCode::rcodes_ SyncRes::updateCacheFromRecords(unsigned int depth, LWResult& lwr 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(d_prefix << ": skipping authority NS from '" << auth << "' nameservers in CNAME/DNAME answer " << i->first.name << "|" << DNSRecordContent::NumberToType(i->first.type) << endl); + LOG(prefix << ": skipping authority NS from '" << auth << "' nameservers in CNAME/DNAME answer " << i->first.name << "|" << DNSRecordContent::NumberToType(i->first.type) << endl); continue; } @@ -4513,27 +4513,27 @@ RCode::rcodes_ SyncRes::updateCacheFromRecords(unsigned int depth, LWResult& lwr vState recordState = vState::Indeterminate; if (expectSignature && shouldValidate()) { - vState initialState = getValidationStatus(i->first.name, !i->second.signatures.empty(), i->first.type == QType::DS, depth); - LOG(d_prefix << ": got initial zone status " << initialState << " for record " << i->first.name << "|" << DNSRecordContent::NumberToType(i->first.type) << endl); + 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); if (initialState == vState::Secure) { if (i->first.type == QType::DNSKEY && i->first.place == DNSResourceRecord::ANSWER && i->first.name == getSigner(i->second.signatures)) { - LOG(d_prefix << "Validating DNSKEY for " << i->first.name << endl); - recordState = validateDNSKeys(i->first.name, i->second.records, i->second.signatures, depth); + LOG(prefix << "Validating DNSKEY for " << i->first.name << endl); + recordState = validateDNSKeys(i->first.name, i->second.records, i->second.signatures, depth, prefix); } else { - LOG(d_prefix << "Validating non-additional " << QType(i->first.type).toString() << " record for " << i->first.name << endl); - recordState = validateRecordsWithSigs(depth, qname, qtype, i->first.name, QType(i->first.type), i->second.records, i->second.signatures); + LOG(prefix << "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(d_prefix << "Skipping validation because the current state is " << recordState << endl); + LOG(prefix << "Skipping validation because the current state is " << recordState << endl); } - LOG(d_prefix << "Validation result is " << recordState << ", current state is " << state << endl); + LOG(prefix << "Validation result is " << recordState << ", current state is " << state << endl); if (state != recordState) { - updateValidationState(state, recordState); + updateValidationState(state, recordState, prefix); } } @@ -4585,7 +4585,7 @@ RCode::rcodes_ SyncRes::updateCacheFromRecords(unsigned int depth, LWResult& lwr if (doCache) { // Check if we are going to replace a non-auth (parent) NS recordset if (isAA && i->first.type == QType::NS && s_save_parent_ns_set) { - rememberParentSetIfNeeded(i->first.name, i->second.records, depth); + rememberParentSetIfNeeded(i->first.name, i->second.records, depth, prefix); } g_recCache->replace(d_now.tv_sec, i->first.name, i->first.type, i->second.records, i->second.signatures, authorityRecs, i->first.type == QType::DS ? true : isAA, auth, i->first.place == DNSResourceRecord::ANSWER ? ednsmask : boost::none, d_routingTag, recordState, remoteIP, d_refresh); @@ -4628,14 +4628,14 @@ RCode::rcodes_ SyncRes::updateCacheFromRecords(unsigned int depth, LWResult& lwr return RCode::NoError; } -void SyncRes::updateDenialValidationState(vState& neValidationState, const DNSName& neName, vState& state, const dState denialState, const dState expectedState, bool isDS, unsigned int depth) +void SyncRes::updateDenialValidationState(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(d_prefix << "OPT-out denial found for " << neName << endl); + LOG(prefix << "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 @@ -4653,23 +4653,23 @@ void SyncRes::updateDenialValidationState(vState& neValidationState, const DNSNa neValidationState = vState::Insecure; } else if (denialState == dState::INSECURE) { - LOG(d_prefix << "Insecure denial found for " << neName << ", returning Insecure" << endl); + LOG(prefix << "Insecure denial found for " << neName << ", returning Insecure" << endl); neValidationState = vState::Insecure; } else { - LOG(d_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 << "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); + auto zState = getValidationStatus(neName, false, isDS, depth, prefix); if (zState != vState::Secure) { neValidationState = zState; } else { - LOG(d_prefix << "Still in a secure zone with an invalid denial for " << neName << ", returning " << vStateToString(vState::BogusInvalidDenial) << endl); + LOG(prefix << "Still in a secure zone with an invalid denial for " << neName << ", returning " << vStateToString(vState::BogusInvalidDenial) << endl); neValidationState = vState::BogusInvalidDenial; } } } - updateValidationState(state, neValidationState); + updateValidationState(state, neValidationState, prefix); } dState SyncRes::getDenialValidationState(const NegCache::NegCacheEntry& ne, const dState expectedState, bool referralToUnsigned, const string& prefix) @@ -4730,14 +4730,14 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co else { /* here we need to get the validation status of the zone telling us that the domain does not exist, ie the owner of the SOA */ - auto recordState = getValidationStatus(rec.d_name, !ne.authoritySOA.signatures.empty() || !ne.DNSSECRecords.signatures.empty(), false, depth); + 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); + updateDenialValidationState(ne.d_validationState, ne.d_name, state, denialState, dState::NXDOMAIN, false, depth, prefix); } else { ne.d_validationState = recordState; - updateValidationState(state, ne.d_validationState); + updateValidationState(state, ne.d_validationState, prefix); } } @@ -4826,7 +4826,7 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co ne.d_validationState = state; } else { - auto recordState = getValidationStatus(qname, !ne.authoritySOA.signatures.empty() || !ne.DNSSECRecords.signatures.empty(), false, depth); + auto recordState = getValidationStatus(qname, !ne.authoritySOA.signatures.empty() || !ne.DNSSECRecords.signatures.empty(), false, depth, prefix); if (recordState == vState::Secure) { /* We have a positive answer synthesized from a wildcard, we need to check that we have @@ -4841,14 +4841,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(d_prefix << "Unable to validate denial in wildcard expanded positive response found for " << qname << ", returning Insecure, res=" << res << endl); + LOG(prefix << "Unable to validate denial in wildcard expanded positive response found for " << qname << ", returning Insecure, res=" << res << endl); } else { - LOG(d_prefix << "Invalid denial in wildcard expanded positive response found for " << qname << ", returning Bogus, res=" << res << endl); + LOG(prefix << "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); + updateValidationState(state, st, prefix); /* we already stored the record with a different validation status, let's fix it */ updateValidationStatusInCache(qname, qtype, lwr.d_aabit, st); } @@ -4903,7 +4903,7 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co harvestNXRecords(lwr.d_records, ne, d_now.tv_sec, &lowestTTL); if (!vStateIsBogus(state)) { - auto recordState = getValidationStatus(newauth, !ne.authoritySOA.signatures.empty() || !ne.DNSSECRecords.signatures.empty(), true, depth); + auto recordState = getValidationStatus(newauth, !ne.authoritySOA.signatures.empty() || !ne.DNSSECRecords.signatures.empty(), true, depth, prefix); if (recordState == vState::Secure) { ne.d_auth = auth; @@ -4957,14 +4957,14 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co ne.d_validationState = state; } else { - auto recordState = getValidationStatus(qname, !ne.authoritySOA.signatures.empty() || !ne.DNSSECRecords.signatures.empty(), qtype == QType::DS, depth); + 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); + updateDenialValidationState(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); + updateValidationState(state, ne.d_validationState, prefix); } } @@ -5000,11 +5000,11 @@ bool SyncRes::processRecords(const std::string& prefix, const DNSName& qname, co 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); if (!vStateIsBogus(state)) { - auto recordState = getValidationStatus(qname, false, true, depth); + 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); + updateValidationState(state, vState::BogusMissingNegativeIndication, prefix); } } negindic = true; @@ -5354,7 +5354,7 @@ void SyncRes::handleNewTarget(const std::string& prefix, const DNSName& qname, c 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); + updateValidationState(state, cnameContext.state, prefix); } bool SyncRes::processAnswer(unsigned int depth, 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) @@ -5410,15 +5410,15 @@ bool SyncRes::processAnswer(unsigned int depth, LWResult& lwr, const DNSName& qn if (lwr.d_rcode == RCode::NXDomain) { LOG(prefix << qname << ": status=NXDOMAIN, we are done " << (negindic ? "(have negative SOA)" : "") << endl); - auto tempState = getValidationStatus(qname, negIndicHasSignatures, qtype == QType::DS, depth); + 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); + updateValidationState(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); + updateValidationState(state, tempState, prefix); } if (d_doDNSSEC) { @@ -5432,15 +5432,15 @@ bool SyncRes::processAnswer(unsigned int depth, LWResult& lwr, const DNSName& qn 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); - auto tempState = getValidationStatus(qname, negIndicHasSignatures, qtype == QType::DS, depth); + 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); + updateValidationState(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); + updateValidationState(state, tempState, prefix); } if (d_doDNSSEC) { diff --git a/pdns/recursordist/syncres.hh b/pdns/recursordist/syncres.hh index a96ee37f33..428ebe9979 100644 --- a/pdns/recursordist/syncres.hh +++ b/pdns/recursordist/syncres.hh @@ -312,10 +312,18 @@ public: int beginResolve(const DNSName& qname, QType qtype, QClass qclass, vector& ret, unsigned int depth = 0); bool tryDoT(const DNSName& qname, QType qtype, const DNSName& nsName, ComboAddress address, time_t); - void setId(int id) + void setId(int threadid) { - if (doLog()) - d_prefix = "[" + std::to_string(id) + "] "; + if (doLog()) { + d_prefix = "[" + std::to_string(threadid) + "] "; + } + } + + void setId(const string& prefix) + { + if (doLog()) { + d_prefix = "[" + prefix + "] "; + } } void setLogMode(LogMode lm) @@ -618,7 +626,7 @@ private: /* This function will check whether the answer should have the AA bit set, and will set if it should be set and isn't. This is unfortunately needed to deal with very crappy so-called DNS servers */ void fixupAnswer(const std::string& prefix, LWResult& lwr, const DNSName& qname, const QType qtype, const DNSName& auth, bool wasForwarded, bool rdQuery); - void rememberParentSetIfNeeded(const DNSName& domain, const vector& newRecords, unsigned int depth); + void rememberParentSetIfNeeded(const DNSName& domain, const vector& newRecords, unsigned int depth, const string& prefix); RCode::rcodes_ updateCacheFromRecords(unsigned int depth, LWResult& lwr, const DNSName& qname, const QType qtype, const DNSName& auth, bool wasForwarded, const boost::optional, vState& state, bool& needWildcardProof, bool& gatherWildcardProof, unsigned int& wildcardLabelsCount, bool sendRDQuery, const ComboAddress& remoteIP); bool processRecords(const std::string& prefix, const DNSName& qname, const QType qtype, const DNSName& auth, LWResult& lwr, const bool sendRDQuery, vector& ret, set& nsset, DNSName& newtarget, DNSName& newauth, bool& realreferral, bool& negindic, vState& state, const bool needWildcardProof, const bool gatherwildcardProof, const unsigned int wildcardLabelsCount, int& rcode, bool& negIndicHasSignatures, unsigned int depth); @@ -630,15 +638,15 @@ 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); - vState validateRecordsWithSigs(unsigned int depth, 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); - vState getDNSKeys(const DNSName& signer, skeyset_t& keys, bool& servFailOccurred, unsigned int depth); + void updateValidationState(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); + void updateDenialValidationState(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); - vState getValidationStatus(const DNSName& subdomain, bool wouldBeValid, bool typeIsDS, unsigned int depth); + 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); void updateValidationStatusInCache(const DNSName& qname, QType qt, bool aa, vState newState) const; void initZoneCutsFromTA(const DNSName& from, const string& prefix); size_t countSupportedDS(const dsmap_t& dsmap, const string& prefix); diff --git a/pdns/validate.cc b/pdns/validate.cc index 922cd77ce1..49d1001313 100644 --- a/pdns/validate.cc +++ b/pdns/validate.cc @@ -18,7 +18,7 @@ uint16_t g_maxNSEC3Iterations{0}; *std::get(log->v) << Logger::Warning << log->prefix << x; \ } \ else if (std::holds_alternative(log->v)) { \ - *std::get(log->v) << x; \ + *std::get(log->v) << log->prefix << x; \ } \ } #endif -- 2.47.2