From: Otto Moerbeek Date: Fri, 21 Mar 2025 11:45:11 +0000 (+0100) Subject: Better tracing X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=98028fd9deb1c6d6c65fde190748a1908e85cec1;p=thirdparty%2Fpdns.git Better tracing --- diff --git a/pdns/recursordist/lwres.cc b/pdns/recursordist/lwres.cc index cbd2f346b..fb1b8b43f 100644 --- a/pdns/recursordist/lwres.cc +++ b/pdns/recursordist/lwres.cc @@ -322,7 +322,7 @@ class BindError { }; -static bool tcpconnect(const ComboAddress& remote, const std::optional localBind, TCPOutConnectionManager::Connection& connection, bool& dnsOverTLS, const std::string& nsName) +static bool tcpconnect(const OptLog& log, const ComboAddress& remote, const std::optional localBind, TCPOutConnectionManager::Connection& connection, bool& dnsOverTLS, const std::string& nsName) { dnsOverTLS = SyncRes::s_dot_to_port_853 && remote.getPort() == 853; @@ -338,10 +338,10 @@ static bool tcpconnect(const ComboAddress& remote, const std::optional& srcmask, const ResolveContext& context, const std::shared_ptr>>& outgoingLoggers, [[maybe_unused]] const std::shared_ptr>>& fstrmLoggers, const std::set& exportTypes, LWResult* lwr, bool* chained, TCPOutConnectionManager::Connection& connection) +static LWResult::Result asyncresolve(const OptLog& log, const ComboAddress& address, const DNSName& domain, int type, bool doTCP, bool sendRDQuery, int EDNS0Level, struct timeval* now, boost::optional& srcmask, const ResolveContext& context, const std::shared_ptr>>& outgoingLoggers, [[maybe_unused]] const std::shared_ptr>>& fstrmLoggers, const std::set& exportTypes, LWResult* lwr, bool* chained, TCPOutConnectionManager::Connection& connection) { size_t len; size_t bufsize = g_outgoingEDNSBufsize; @@ -492,12 +492,12 @@ static LWResult::Result asyncresolve(const ComboAddress& address, const DNSName& addressToBindTo = found->d_localaddress; opts.emplace_back(EDNSOptionCode::COOKIE, cookieSentOut->makeOptString()); found->d_lastupdate = now->tv_sec; - cerr << "Sending stored cookie info to " << address.toString() << ": " << found->d_cookie.toDisplayString() << endl; + VLOG(log, "Sending stored cookie info to " << address.toString() << ": " << found->d_cookie.toDisplayString() << endl); break; case CookieEntry::Support::Unknown: assert(0); case CookieEntry::Support::Unsupported: - cerr << "This server does not support cookies" << endl; + VLOG(log, "Server << " << address.toString() << " does not support cookies" << endl); break; } } @@ -511,7 +511,7 @@ static LWResult::Result asyncresolve(const ComboAddress& address, const DNSName& entry.setSupport(CookieEntry::Support::Probing); lock->emplace(entry); opts.emplace_back(EDNSOptionCode::COOKIE, cookieSentOut->makeOptString()); - cerr << "We're sending new client cookie info from to " << address.toString() << ": " << entry.d_cookie.toDisplayString() << endl; + VLOG(log, "Sending new client cookie info to " << address.toString() << ": " << entry.d_cookie.toDisplayString() << endl); } } @@ -599,7 +599,7 @@ static LWResult::Result asyncresolve(const ComboAddress& address, const DNSName& // peer has closed it on error, so we retry. At some point we // *will* get a new connection, so this loop is not endless. isNew = true; // tcpconnect() might throw for new connections. In that case, we want to break the loop, scanbuild complains here, which is a false positive afaik - isNew = tcpconnect(address, addressToBindTo, connection, dnsOverTLS, nsName); + isNew = tcpconnect(log, address, addressToBindTo, connection, dnsOverTLS, nsName); ret = tcpsendrecv(address, connection, localip, vpacket, len, buf); #ifdef HAVE_FSTRM if (fstrmQEnabled) { @@ -732,12 +732,12 @@ static LWResult::Result asyncresolve(const ComboAddress& address, const DNSName& EDNSCookiesOpt received; if (received.makeFromString(opt.second)) { cookieFoundInReply = true; - cerr << "Received cookie info back from " << address.toString() << ": " << received.toDisplayString() << endl; + VLOG(log, "Received cookie info back from " << address.toString() << ": " << received.toDisplayString() << endl); auto lock = s_cookiestore.lock(); auto found = lock->find(address); if (found != lock->end()) { if (received.getClient() == cookieSentOut->getClient()) { - cerr << "Client cookie matched! Storing with localAddress " << localip.toString() << endl; + VLOG(log, "Client cookie matched! Storing with localAddress " << localip.toString() << endl); found->d_localaddress = localip; found->d_cookie = received; found->d_lastupdate = now->tv_sec; @@ -745,13 +745,14 @@ static LWResult::Result asyncresolve(const ComboAddress& address, const DNSName& uint16_t ercode = (edo.d_extRCode << 4) | lwr->d_rcode; if (ercode == ERCode::BADCOOKIE) { lwr->d_validpacket = true; + VLOG(log, "Server: " << localip.toString() << " returned BADCOOKIE " << endl); return LWResult::Result::BadCookie; // proper use of BacCookie, we did update he entry } } else { if (!doTCP) { // Server responded with a wrong client cookie, fall back to TCP - cerr << "Wrong cookie" << endl; + VLOG(log, "Server responded with wrong client cookie, fall back to TCP" << endl); lwr->d_validpacket = true; return LWResult::Result::Spoofed; } @@ -760,14 +761,14 @@ static LWResult::Result asyncresolve(const ComboAddress& address, const DNSName& } else { // We receivd cookie (we might have sent one out) but it's not in the table? - cerr << "Cookie not found back"<< endl; + VLOG(log, "Cookie not found back in table" << endl); lwr->d_rcode = RCode::FormErr; lwr->d_validpacket = false; return LWResult::Result::Success; // success - oddly enough } } else { - cerr << "Malformed cookie in reply" << endl; + VLOG(log, "Malformed cookie in reply" << endl); // Do something special if we get malformed repeatedly? And or consider current status: Supported lwr->d_rcode = RCode::FormErr; lwr->d_validpacket = false; @@ -780,7 +781,6 @@ static LWResult::Result asyncresolve(const ComboAddress& address, const DNSName& // Case: we sent out a cookie but did not get one back if (cookieSentOut && !cookieFoundInReply && !*chained) { - cerr << "No cookie in reply"<< endl; auto lock = s_cookiestore.lock(); auto found = lock->find(address); if (found != lock->end()) { @@ -788,10 +788,11 @@ static LWResult::Result asyncresolve(const ComboAddress& address, const DNSName& case CookieEntry::Support::Unknown: assert(0); case CookieEntry::Support::Probing: - cerr << "Was probing, setting support to Unsupported" << endl; + VLOG(log, "No cookie in repy, was probing, setting support to Unsupported" << endl); found->setSupport(CookieEntry::Support::Unsupported); break; case CookieEntry::Support::Unsupported: + // We could have detected the server does not support cookies in the meantime break; case CookieEntry::Support::Supported: lwr->d_validpacket = true; @@ -841,10 +842,10 @@ out: return LWResult::Result::PermanentError; } -LWResult::Result asyncresolve(const ComboAddress& address, const DNSName& domain, int type, bool doTCP, bool sendRDQuery, int EDNS0Level, struct timeval* now, boost::optional& srcmask, const ResolveContext& context, const std::shared_ptr>>& outgoingLoggers, const std::shared_ptr>>& fstrmLoggers, const std::set& exportTypes, LWResult* lwr, bool* chained) +LWResult::Result asyncresolve(const OptLog& log, const ComboAddress& address, const DNSName& domain, int type, bool doTCP, bool sendRDQuery, int EDNS0Level, struct timeval* now, boost::optional& srcmask, const ResolveContext& context, const std::shared_ptr>>& outgoingLoggers, const std::shared_ptr>>& fstrmLoggers, const std::set& exportTypes, LWResult* lwr, bool* chained) { TCPOutConnectionManager::Connection connection; - auto ret = asyncresolve(address, domain, type, doTCP, sendRDQuery, EDNS0Level, now, srcmask, context, outgoingLoggers, fstrmLoggers, exportTypes, lwr, chained, connection); + auto ret = asyncresolve(log, address, domain, type, doTCP, sendRDQuery, EDNS0Level, now, srcmask, context, outgoingLoggers, fstrmLoggers, exportTypes, lwr, chained, connection); if (doTCP) { if (connection.d_handler && lwr->d_validpacket) { diff --git a/pdns/recursordist/lwres.hh b/pdns/recursordist/lwres.hh index 053a35151..2ca661d4e 100644 --- a/pdns/recursordist/lwres.hh +++ b/pdns/recursordist/lwres.hh @@ -43,8 +43,8 @@ #include "fstrm_logger.hh" #include "resolve-context.hh" #include "noinitvector.hh" - -#include "logging.hh" +#include "logger.hh" +#include "logr.hh" // Helper to be defined by main program: queue data and log based on return value of queueData() void remoteLoggerQueueData(RemoteLoggerInterface&, const std::string&); @@ -98,7 +98,7 @@ LWResult::Result asendto(const void* data, size_t len, int flags, const ComboAdd LWResult::Result arecvfrom(PacketBuffer& packet, int flags, const ComboAddress& fromAddr, size_t& len, uint16_t qid, const DNSName& domain, uint16_t qtype, int fileDesc, const std::optional& ecs, const struct timeval& now); -LWResult::Result asyncresolve(const ComboAddress& address, const DNSName& domain, int type, bool doTCP, bool sendRDQuery, int EDNS0Level, struct timeval* now, boost::optional& srcmask, const ResolveContext& context, const std::shared_ptr>>& outgoingLoggers, const std::shared_ptr>>& fstrmLoggers, const std::set& exportTypes, LWResult* lwr, bool* chained); +LWResult::Result asyncresolve(const OptLog& log, const ComboAddress& address, const DNSName& domain, int type, bool doTCP, bool sendRDQuery, int EDNS0Level, struct timeval* now, boost::optional& srcmask, const ResolveContext& context, const std::shared_ptr>>& outgoingLoggers, const std::shared_ptr>>& fstrmLoggers, const std::set& exportTypes, LWResult* lwr, bool* chained); uint64_t dumpCookies(int fileDesc); std::string clearCookies(); void pruneCookies(time_t cutoff); diff --git a/pdns/recursordist/meson.build b/pdns/recursordist/meson.build index 74dfd3d14..0a6898289 100644 --- a/pdns/recursordist/meson.build +++ b/pdns/recursordist/meson.build @@ -129,7 +129,6 @@ common_sources += files( src_dir / 'logging.cc', src_dir / 'lua-base4.cc', src_dir / 'lua-recursor4.cc', - src_dir / 'lwres.cc', src_dir / 'misc.cc', src_dir / 'mtasker_context.cc', src_dir / 'negcache.cc', @@ -438,6 +437,7 @@ tools = { src_dir / 'rec-tcpout.cc', src_dir / 'rec-snmp.cc', src_dir / 'rec-tcp.cc', + src_dir / 'lwres.cc', mplexer_sources, ], 'manpages': ['pdns_recursor.1'], diff --git a/pdns/recursordist/pdns_recursor.cc b/pdns/recursordist/pdns_recursor.cc index 25ec0cf69..5896e3db7 100644 --- a/pdns/recursordist/pdns_recursor.cc +++ b/pdns/recursordist/pdns_recursor.cc @@ -180,13 +180,11 @@ int UDPClientSocks::makeClientSocket(int family, const std::optionaltoString() << endl; sin = *localAddress; sin.setPort(port); } else { sin = pdns::getQueryLocalAddress(family, port); // does htons for us - cerr << "Bound to random local address " << sin.toString() << endl; } if (::bind(ret, reinterpret_cast(&sin), sin.getSocklen()) >= 0) { // NOLINT(cppcoreguidelines-pro-type-reinterpret-cast) break; diff --git a/pdns/recursordist/syncres.cc b/pdns/recursordist/syncres.cc index cd56c4f8d..6c008be01 100644 --- a/pdns/recursordist/syncres.cc +++ b/pdns/recursordist/syncres.cc @@ -1437,7 +1437,7 @@ uint64_t SyncRes::doDumpDoTProbeMap(int fileDesc) For now this means we can't be clever, but will turn off DNSSEC if you reply with FormError or gibberish. */ -LWResult::Result SyncRes::asyncresolveWrapper(const ComboAddress& address, bool ednsMANDATORY, const DNSName& domain, [[maybe_unused]] const DNSName& auth, int type, bool doTCP, bool sendRDQuery, struct timeval* now, boost::optional& srcmask, LWResult* res, bool* chained, const DNSName& nsName) const +LWResult::Result SyncRes::asyncresolveWrapper(const OptLog& log, const ComboAddress& address, bool ednsMANDATORY, const DNSName& domain, [[maybe_unused]] const DNSName& auth, int type, bool doTCP, bool sendRDQuery, struct timeval* now, boost::optional& srcmask, LWResult* res, bool* chained, const DNSName& nsName) const { /* what is your QUEST? the goal is to get as many remotes as possible on the best level of EDNS support @@ -1499,7 +1499,7 @@ LWResult::Result SyncRes::asyncresolveWrapper(const ComboAddress& address, bool ret = d_asyncResolve(address, sendQname, type, doTCP, sendRDQuery, EDNSLevel, now, srcmask, ctx, res, chained); } else { - ret = asyncresolve(address, sendQname, type, doTCP, sendRDQuery, EDNSLevel, now, srcmask, ctx, d_outgoingProtobufServers, d_frameStreamServers, luaconfsLocal->outgoingProtobufExportConfig.exportTypes, res, chained); + ret = asyncresolve(log, address, sendQname, type, doTCP, sendRDQuery, EDNSLevel, now, srcmask, ctx, d_outgoingProtobufServers, d_frameStreamServers, luaconfsLocal->outgoingProtobufExportConfig.exportTypes, res, chained); } if (ret == LWResult::Result::PermanentError || LWResult::isLimitError(ret) || ret == LWResult::Result::Spoofed) { @@ -5471,8 +5471,7 @@ bool SyncRes::doResolveAtThisIP(const std::string& prefix, const DNSName& qname, } auto match = d_eventTrace.add(RecEventTrace::AuthRequest, qname.toLogString() + '/' + qtype.toString(), true, 0); updateQueryCounts(prefix, qname, remoteIP, doTCP, doDoT); - cerr << "doTCP " << doTCP << endl; - resolveret = asyncresolveWrapper(remoteIP, d_doDNSSEC, qname, auth, qtype.getCode(), + resolveret = asyncresolveWrapper(LogObject(prefix), remoteIP, d_doDNSSEC, qname, auth, qtype.getCode(), doTCP, sendRDQuery, &d_now, ednsmask, &lwr, &chained, nsName); // <- we go out on the wire! d_eventTrace.add(RecEventTrace::AuthRequest, static_cast(lwr.d_rcode), false, match); ednsStats(ednsmask, qname, prefix); @@ -5997,7 +5996,9 @@ int SyncRes::doResolveAt(NsSet& nameservers, DNSName auth, bool flawedNSSet, con gotAnswer = doResolveAtThisIP(prefix, qname, qtype, lwr, ednsmask, auth, sendRDQuery, wasForwarded, tns->first, *remoteIP, false, false, truncated, spoofed, context.extendedError); } - if (spoofed) cerr << "Got spoofed! " << spoofed << endl; + if (spoofed) { + LOG(prefix << qname << ": potentially spoofed, retrying over TCP" << endl); + } if (forceTCP || (spoofed || (gotAnswer && truncated))) { /* retry, over TCP this time */ gotAnswer = doResolveAtThisIP(prefix, qname, qtype, lwr, ednsmask, auth, sendRDQuery, wasForwarded, diff --git a/pdns/recursordist/syncres.hh b/pdns/recursordist/syncres.hh index 1427776d6..22eabb3a6 100644 --- a/pdns/recursordist/syncres.hh +++ b/pdns/recursordist/syncres.hh @@ -685,7 +685,7 @@ private: bool doSpecialNamesResolve(const DNSName& qname, QType qtype, QClass qclass, vector& ret); - LWResult::Result asyncresolveWrapper(const ComboAddress& address, bool ednsMANDATORY, const DNSName& domain, const DNSName& auth, int type, bool doTCP, bool sendRDQuery, struct timeval* now, boost::optional& srcmask, LWResult* res, bool* chained, const DNSName& nsName) const; + LWResult::Result asyncresolveWrapper(const OptLog&log, const ComboAddress& address, bool ednsMANDATORY, const DNSName& domain, const DNSName& auth, int type, bool doTCP, bool sendRDQuery, struct timeval* now, boost::optional& srcmask, LWResult* res, bool* chained, const DNSName& nsName) const; boost::optional getEDNSSubnetMask(const DNSName& name, const ComboAddress& rem); diff --git a/pdns/recursordist/test-syncres_cc.cc b/pdns/recursordist/test-syncres_cc.cc index d9ae47cb9..d5eb90b68 100644 --- a/pdns/recursordist/test-syncres_cc.cc +++ b/pdns/recursordist/test-syncres_cc.cc @@ -62,7 +62,7 @@ void RecursorLua4::getFeatures(Features& /* features */) { } -LWResult::Result asyncresolve(const ComboAddress& /* ip */, const DNSName& /* domain */, int /* type */, bool /* doTCP */, bool /* sendRDQuery */, int /* EDNS0Level */, struct timeval* /* now */, boost::optional& /* srcmask */, const ResolveContext& /* context */, const std::shared_ptr>>& /* outgoingLoggers */, const std::shared_ptr>>& /* fstrmLoggers */, const std::set& /* exportTypes */, LWResult* /* res */, bool* /* chained */) +LWResult::Result asyncresolve(const OptLog& /* log */, const ComboAddress& /* ip */, const DNSName& /* domain */, int /* type */, bool /* doTCP */, bool /* sendRDQuery */, int /* EDNS0Level */, struct timeval* /* now */, boost::optional& /* srcmask */, const ResolveContext& /* context */, const std::shared_ptr>>& /* outgoingLoggers */, const std::shared_ptr>>& /* fstrmLoggers */, const std::set& /* exportTypes */, LWResult* /* res */, bool* /* chained */) { return LWResult::Result::Timeout; }