From 77499b052f23392d331de23de0d41d21fadb0ee3 Mon Sep 17 00:00:00 2001 From: Bert Hubert Date: Fri, 11 Jan 2013 13:07:40 +0000 Subject: [PATCH] implement & document 'rec_control trace-regex' which allows specific queries to be fully traced for debugging purposes. git-svn-id: svn://svn.powerdns.com/pdns/trunk/pdns@3044 d19b8d6e-7fed-0310-83ef-9ca221ded41b --- pdns/docs/pdns.xml | 28 +++++ pdns/pdns_recursor.cc | 68 ++++++++++-- pdns/rec_channel_rec.cc | 4 + pdns/syncres.cc | 241 ++++++++++++++++++++-------------------- pdns/syncres.hh | 34 ++++-- 5 files changed, 236 insertions(+), 139 deletions(-) diff --git a/pdns/docs/pdns.xml b/pdns/docs/pdns.xml index 8ed1dda76..5a7e4a822 100644 --- a/pdns/docs/pdns.xml +++ b/pdns/docs/pdns.xml @@ -12967,6 +12967,34 @@ sql> insert into domainmetadata (domain_id, kind, content) values (7,'ALLOW-AXFR defaults to 0. + + + trace-regex regex + + + Queries matching this regular expression will generate + voluminous tracing output. Be aware that matches from the + packet cache will still not generate tracing. To unset the + regex, pass 'trace-regex' without a new regex. + + + The regular expression is matched against domain queries + terminated with a '.'. So, for example the regex + 'powerdns.com$' will not match a query for + 'www.powerdns.com', since the attempted match will be with + 'www.powerdns.com.'. + + + In addition, since this is a regular expression, to + exclusively match queries for 'www.powerdns.com', one + should escape the dots: '^www\.powerdns\.com\.$'. + + + Multiple matches can be chained with the | operator. For + example, to match all queries for Dutch (.nl) and German + (.de) domain names, use: '\.nl\.$|\.de\.$'. + + wipe-cache domain0. [domain1. domain2.] diff --git a/pdns/pdns_recursor.cc b/pdns/pdns_recursor.cc index e315e5260..3c4b7b73f 100644 --- a/pdns/pdns_recursor.cc +++ b/pdns/pdns_recursor.cc @@ -1,6 +1,6 @@ /* PowerDNS Versatile Database Driven Nameserver - Copyright (C) 2003 - 2012 PowerDNS.COM BV + Copyright (C) 2003 - 2013 PowerDNS.COM BV This program is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License version 2 @@ -78,6 +78,7 @@ unsigned int g_networkTimeoutMsec; bool g_logCommonErrors; __thread shared_ptr* t_pdl; __thread RemoteKeeper* t_remotes; +__thread shared_ptr* t_traceRegex; RecursorControlChannel s_rcc; // only active in thread 0 @@ -510,8 +511,14 @@ void startDoResolve(void *p) pw.getHeader()->rd=dc->d_mdp.d_header.rd; SyncRes sr(dc->d_now); - if(!g_quiet) - L<getTid()<<"] " << (dc->d_tcp ? "TCP " : "") << "question for '"<d_mdp.d_qname<<"|" + bool tracedQuery=false; // we could consider letting Lua know about this too + if(t_traceRegex->get() && (*t_traceRegex)->match(dc->d_mdp.d_qname)) { + sr.setLogMode(SyncRes::Store); + tracedQuery=true; + } + + if(!g_quiet || tracedQuery) + L<getTid()<<"] " << (dc->d_tcp ? "TCP " : "") << "question for '"<d_mdp.d_qname<<"|" <d_mdp.d_qtype)<<"' from "<getRemote()<getTid()); @@ -540,10 +547,18 @@ void startDoResolve(void *p) (*t_pdl)->postresolve(dc->d_remote, g_listenSocketsAddresses[dc->d_socket], dc->d_mdp.d_qname, QType(dc->d_mdp.d_qtype), ret, res, &variableAnswer); } } - - uint32_t minTTL=std::numeric_limits::max(); + + string trace(sr.getTrace()); + if(!trace.empty()) { + vector lines; + boost::split(lines, trace, boost::is_any_of("\n")); + BOOST_FOREACH(const string& line, lines) { + if(!line.empty()) + L<rcode=RCode::ServFail; // no commit here, because no record @@ -552,7 +567,7 @@ void startDoResolve(void *p) else { pw.getHeader()->rcode=res; updateRcodeStats(res); - + if(ret.size()) { orderAndShuffle(ret); @@ -1054,7 +1069,7 @@ void usr1Handler(int) void usr2Handler(int) { - SyncRes::setLog(true); + SyncRes::setDefaultLogMode(SyncRes::Log); g_quiet=false; ::arg().set("quiet")="no"; @@ -1309,6 +1324,7 @@ void handleRCC(int fd, FDMultiplexer::funcparam_t& var) string msg=s_rcc.recv(&remote); RecursorControlParser rcp; RecursorControlParser::func_t* command; + string answer=rcp.getAnswer(msg, &command); try { s_rcc.send(answer, &remote); @@ -1533,6 +1549,29 @@ string doQueueReloadLuaScript(vector::const_iterator begin, vector(doReloadLuaScript); } +string* pleaseUseNewTraceRegex(const std::string& newRegex) +try +{ + if(newRegex.empty()) { + t_traceRegex->reset(); + return new string("unset\n"); + } + else { + (*t_traceRegex) = shared_ptr(new Regex(newRegex)); + return new string("ok\n"); + } +} +catch(AhuException& ae) +{ + return new string(ae.reason+"\n"); +} + +string doTraceRegex(vector::const_iterator begin, vector::const_iterator end) +{ + return broadcastAccFunction(boost::bind(pleaseUseNewTraceRegex, begin!=end ? *begin : "")); +} + + void* recursorThread(void*); void* pleaseSupplantACLs(NetmaskGroup *ng) @@ -1672,12 +1711,16 @@ int serviceMain(int argc, char*argv[]) L< addrs; if(!::arg()["query-local-address6"].empty()) { @@ -1786,7 +1829,7 @@ int serviceMain(int argc, char*argv[]) pthread_t tid; L<(); + + t_remotes = new RemoteKeeper(); t_remotes->remotes.resize(::arg().asNum("remotes-ringbuffer-entries") / g_numThreads); @@ -1965,7 +2011,7 @@ int main(int argc, char **argv) ::arg().set("aaaa-additional-processing","turn on to do AAAA additional processing (slow)")="off"; ::arg().set("local-port","port to listen on")="53"; ::arg().set("local-address","IP addresses to listen on, separated by spaces or commas. Also accepts ports.")="127.0.0.1"; - ::arg().set("trace","if we should output heaps of logging")="off"; + ::arg().set("trace","if we should output heaps of logging. set to 'fail' to only log failing domains")="off"; ::arg().set("daemon","Operate as a daemon")="yes"; ::arg().set("log-common-errors","If we should log rather common errors")="yes"; ::arg().set("chroot","switch to chroot jail")=""; diff --git a/pdns/rec_channel_rec.cc b/pdns/rec_channel_rec.cc index 7d969d3ba..8ba94df43 100644 --- a/pdns/rec_channel_rec.cc +++ b/pdns/rec_channel_rec.cc @@ -575,6 +575,7 @@ string RecursorControlParser::getAnswer(const string& question, RecursorControlP "reload-acls reload ACLS\n" "reload-lua-script [filename] (re)load Lua script\n" "reload-zones reload all auth and forward zones\n" +"trace-regex regex emit resolution trace for matching queries\n" "top-remotes show top remotes\n" "unload-lua-script unload Lua script\n" "wipe-cache domain0 [domain1] .. wipe domain data from cache\n"; @@ -611,6 +612,9 @@ string RecursorControlParser::getAnswer(const string& question, RecursorControlP if(cmd=="reload-lua-script") return doQueueReloadLuaScript(begin, end); + if(cmd=="trace-regex") + return doTraceRegex(begin, end); + if(cmd=="unload-lua-script") { vector empty; empty.push_back(string()); diff --git a/pdns/syncres.cc b/pdns/syncres.cc index f2c1c1528..5b2892e91 100644 --- a/pdns/syncres.cc +++ b/pdns/syncres.cc @@ -1,6 +1,6 @@ /* PowerDNS Versatile Database Driven Nameserver - Copyright (C) 2003 - 2011 PowerDNS.COM BV + Copyright (C) 2003 - 2013 PowerDNS.COM BV This program is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License version 2 as published @@ -56,9 +56,9 @@ bool SyncRes::s_doIPv6; bool SyncRes::s_nopacketcache; string SyncRes::s_serverID; -bool SyncRes::s_log; +SyncRes::LogMode SyncRes::s_lm; -#define LOG if(s_log) L<&ret, int depth, int& res) { string prefix; - if(s_log) { + if(doLog()) { prefix=d_prefix; prefix.append(depth, ' '); } - LOG<domainmap->end()) { - LOG< range; range=iter->second.d_records.equal_range(tie(qname)); // partial lookup @@ -158,12 +159,12 @@ bool SyncRes::doOOBResolve(const string &qname, const QType &qtype, vectorsecond.d_records.find(make_tuple(authdomain, QType(QType::SOA))); if(ziter!=iter->second.d_records.end()) { DNSResourceRecord rr=*ziter; @@ -171,15 +172,15 @@ bool SyncRes::doOOBResolve(const string &qname, const QType &qtype, vectorfirst) && chopOffDotted(wcarddomain)) { - LOG<second.d_records.equal_range(make_tuple("*."+wcarddomain)); if(range.first==range.second) continue; @@ -192,7 +193,7 @@ bool SyncRes::doOOBResolve(const string &qname, const QType &qtype, vectorsecond.d_records.find(make_tuple(authdomain, QType(QType::SOA))); if(ziter!=iter->second.d_records.end()) { DNSResourceRecord rr=*ziter; @@ -219,7 +220,7 @@ bool SyncRes::doOOBResolve(const string &qname, const QType &qtype, vectormodeSetAt && ednsstatus->modeSetAt + 3600 < d_now.tv_sec) { *ednsstatus=SyncRes::EDNSStatus(); - // cerr<<"Resetting EDNS Status for "<mode == EDNSStatus::UNKNOWN) @@ -294,7 +295,7 @@ int SyncRes::asyncresolveWrapper(const ComboAddress& ip, const string& domain, i int ret; for(int tries = 0; tries < 3; ++tries) { - // cerr<<"Remote '"<d_rcode == RCode::FormErr) { - // cerr<<"Downgrading to EDNSNOPING because of FORMERR!"<d_haveEDNS) { if(mode != EDNSStatus::EDNSIGNORANT) { mode = EDNSStatus::EDNSIGNORANT; - // cerr<<"We find that "<d_rcode == RCode::FormErr) { - // cerr<<"Downgrading to mode 4, FORMERR!"<modeSetAt=d_now.tv_sec; - // cerr<<"Result: ret="<d_haveEDNS<<", EDNS-PING correct: "<d_pingCorrect<<", new mode: "<d_haveEDNS<<", EDNS-PING correct: "<d_pingCorrect<<", new mode: "<&ret, int depth, set& beenthere) { string prefix; - if(s_log) { + if(doLog()) { prefix=d_prefix; prefix.append(depth, ' '); } @@ -386,7 +387,7 @@ int SyncRes::doResolve(const string &qname, const QType &qtype, vectordomainmap->end()) { @@ -398,7 +399,7 @@ int SyncRes::doResolve(const string &qname, const QType &qtype, vector SyncRes::getAs(const string &qname, int depth, set&bestns, bool* flawedNSSet, int depth, set& beenthere) { string prefix, subdomain(qname); - if(s_log) { + if(doLog()) { prefix=d_prefix; prefix.append(depth, ' '); } bestns.clear(); do { - LOG< ns; *flawedNSSet = false; if(t_RC->get(d_now.tv_sec, subdomain, QType(QType::NS), &ns) > 0) { @@ -511,20 +512,20 @@ void SyncRes::getBestNSFromCache(const string &qname, set&bes DNSResourceRecord rr=*k; rr.content=k->content; if(!dottedEndsOn(rr.content, subdomain) || t_RC->get(d_now.tv_sec, rr.content, s_doIPv6 ? QType(QType::ADDR) : QType(QType::A), - s_log ? &aset : 0) > 5) { + doLog() ? &aset : 0) > 5) { bestns.insert(rr); - LOG< '"< '"<content<<") which we miss or is expired"<content<<") which we miss or is expired"<&bes GetBestNSAnswer answer; answer.qname=qname; answer.bestns=bestns; if(beenthere.count(answer)) { - LOG<::const_iterator j=beenthere.begin();j!=beenthere.end();++j) - LOG<qname<<" ("<<(unsigned int)j->bestns.size()<<")"<::const_iterator j=beenthere.begin();j!=beenthere.end();++j) { + LOG(prefix<qname<<" ("<<(unsigned int)j->bestns.size()<<")"<&ret, int depth, int &res) { string prefix; - if(s_log) { + if(doLog()) { prefix=d_prefix; prefix.append(depth, ' '); } if(depth>10) { - LOG< cset; if(t_RC->get(d_now.tv_sec, qname,QType(QType::CNAME),&cset) > 0) { for(set::const_iterator j=cset.begin();j!=cset.end();++j) { if(j->ttl>(unsigned int) d_now.tv_sec) { - LOG<content<<"'"<content<<"'"<d_ttd) { sttl=ni->d_ttd - d_now.tv_sec; if(ni->d_qtype.getCode()) { - LOG<d_qname<<"' for another "<d_qname<<"' for another "<d_qname<<"' for another "<d_qname<<"' for another "<negcache, ni); } } @@ -679,9 +681,9 @@ bool SyncRes::doCacheCheck(const string &qname, const QType &qtype, vectorget(d_now.tv_sec, sqname, sqt, &cset) > 0) { - LOG<::const_iterator j=cset.begin();j!=cset.end();++j) { - LOG<content; + LOG(j->content); if(j->ttl>(unsigned int) d_now.tv_sec) { DNSResourceRecord rr=*j; rr.ttl-=d_now.tv_sec; @@ -690,23 +692,23 @@ bool SyncRes::doCacheCheck(const string &qname, const QType &qtype, vector SyncRes::shuffleInSpeedOrder(set speedOrder so(speeds); stable_sort(rnameservers.begin(),rnameservers.end(), so); - if(s_log) { - L<::const_iterator i=rnameservers.begin();i!=rnameservers.end();++i) { if(i!=rnameservers.begin()) { - L<<", "; - if(!((i-rnameservers.begin())%3)) - L< nameservers, string auth, bool flawedNSSet, const string &qname, const QType &qtype, vector&ret, int depth, set&beenthere) { string prefix; - if(s_log) { + if(doLog()) { prefix=d_prefix; prefix.append(depth, ' '); } - LOG< rnameservers=shuffleInSpeedOrder(nameservers, s_log ? (prefix+qname+": ") : string() ); + vector rnameservers=shuffleInSpeedOrder(nameservers, doLog() ? (prefix+qname+": ") : string() ); for(vector::const_iterator tns=rnameservers.begin();;++tns) { if(tns==rnameservers.end()) { - LOG<doAgeCache(d_now.tv_sec, auth, QType::NS, 10)) g_stats.nsSetInvalidations++; } return -1; } if(pdns_iequals(qname, *tns) && qtype.getCode()==QType::A && rnameservers.size() > 1) { - LOG< nameservers, string auth, bool sendRDQuery=false; LWResult lwr; if(tns->empty()) { - LOG<empty()) { @@ -856,32 +857,33 @@ int SyncRes::doResolveAt(set nameservers, string auth, } if(remoteIPs.empty()) { - LOG<toString(); + if(remoteIP != remoteIPs.begin()) { + LOG(", "); + } + LOG(remoteIP->toString()); } - LOG<toStringWithPort() <<", asking '"<toStringWithPort() <<", asking '"<throttle.shouldThrottle(d_now.tv_sec, make_tuple(*remoteIP, qname, qtype.getCode()))) { - LOG<match(&*remoteIP)) { - LOG<toString() << ", blocked by 'dont-query' setting" << endl; + LOG(prefix<toString() << ", blocked by 'dont-query' setting" << endl); s_dontqueries++; continue; } @@ -889,7 +891,7 @@ int SyncRes::doResolveAt(set nameservers, string auth, s_outqueries++; d_outqueries++; TryTCP: if(doTCP) { - LOG<toStringWithPort() <toStringWithPort() < nameservers, string auth, doTCP, sendRDQuery, &d_now, &lwr); // <- we go out on the wire! if(resolveret != 1) { if(resolveret==0) { - LOG< nameservers, string auth, break; // this IP address worked! wasLame:; // well, it didn't - LOG<toString() <<") is lame for '"<toString() <<") is lame for '"<throttle.throttle(d_now.tv_sec, make_tuple(*remoteIP, qname, qtype.getCode()), 60, 100); // lame } } @@ -937,27 +939,25 @@ int SyncRes::doResolveAt(set nameservers, string auth, if(lwr.d_tcbit) { if(!doTCP) { doTCP=true; - LOG<throttle.throttle(d_now.tv_sec,make_tuple(*remoteIP, qname, qtype.getCode()),60,3); // servfail continue; } - LOG<toString() <<"), rcode="<toString() <<"), rcode="<sin4.sin_family==AF_INET6) lwr.d_usec/=3; */ // cout<<"msec: "<nsSpeeds[*tns].submit(*remoteIP, lwr.d_usec, &d_now); } @@ -968,23 +968,23 @@ int SyncRes::doResolveAt(set nameservers, string auth, // reap all answers from this packet that are acceptable for(LWResult::res_t::iterator i=lwr.d_result.begin();i != lwr.d_result.end();++i) { if(i->qtype.getCode() == QType::OPT) { - LOG<qname<<"' from '"<qname<<"' from '"<qname<<"|"<qtype.getName()<<"|"<content<<"' from '"<qname<<"|"<qtype.getName()<<"|"<content<<"' from '"<qtype.getCode()==QType::ANY) { - LOG<<"NO! - we don't accept 'ANY' data"<qname, auth)) { if(lwr.d_aabit && lwr.d_rcode==RCode::NoError && i->d_place==DNSResourceRecord::ANSWER && ::arg().contains("delegation-only",auth)) { - LOG<<"NO! Is from delegation-only zone"<ttl=min(s_maxcachettl, i->ttl); @@ -1000,7 +1000,7 @@ int SyncRes::doResolveAt(set nameservers, string auth, } } else - LOG<<"NO!"< nameservers, string auth, t_RC->replace(d_now.tv_sec, i->first.first, i->first.second, i->second, lwr.d_aabit); } set nsset; - LOG< nameservers, string auth, for(LWResult::res_t::iterator i=lwr.d_result.begin();i!=lwr.d_result.end();++i) { if(i->d_place==DNSResourceRecord::AUTHORITY && i->qtype.getCode()==QType::SOA && lwr.d_rcode==RCode::NXDomain && dottedEndsOn(qname,i->qname) && dottedEndsOn(i->qname, auth)) { - LOG<ttl = min(i->ttl, s_maxnegttl); if(!newtarget.length()) // only add a SOA if we're not going anywhere after this @@ -1056,7 +1056,7 @@ int SyncRes::doResolveAt(set nameservers, string auth, ) { - LOG<content<<"|"<qtype.getName()<<"'"<content<<"|"<qtype.getName()<<"'"< nameservers, string auth, else if(i->d_place==DNSResourceRecord::AUTHORITY && dottedEndsOn(qname,i->qname) && i->qtype.getCode()==QType::NS) { if(moreSpecificThan(i->qname,auth)) { newauth=i->qname; - LOG<qname<<"' -> '"<content<<"'"<qname<<"' -> '"<content<<"'"<qname<<"' -> '"<content<<"', had '"<qname<<"' -> '"<content<<"', had '"<content); } else if(!done && i->d_place==DNSResourceRecord::AUTHORITY && dottedEndsOn(qname,i->qname) && i->qtype.getCode()==QType::SOA && lwr.d_rcode==RCode::NoError) { - LOG<qtype.getName()+"'") <qtype.getName()+"'") < ttl = min(s_maxnegttl, i->ttl); @@ -1095,33 +1095,33 @@ int SyncRes::doResolveAt(set nameservers, string auth, } if(done){ - LOG< 10) { - LOG< beenthere2; return doResolve(newtarget, qtype, ret, depth + 1, beenthere2); } if(lwr.d_rcode==RCode::NXDomain) { - LOG<& ret) if(k->d_place==DNSResourceRecord::AUTHORITY && k->qtype==QType(QType::SOA)) return; - // LOG< addit; for(vector::const_iterator k=ret.begin();k!=ret.end();++k) if( (k->d_place==DNSResourceRecord::ANSWER && (k->qtype==QType(QType::MX) || k->qtype==QType(QType::SRV))) || ((k->d_place==DNSResourceRecord::AUTHORITY || k->d_place==DNSResourceRecord::ANSWER) && k->qtype==QType(QType::NS))) { - LOG<content<<"|"<qtype.getName()<<"' needs IP for additional processing"<content<<"|"<qtype.getName()<<"' needs IP for additional processing"< beenthere; vector > fields; vstringtok(fields, k->content, " "); @@ -1181,7 +1181,7 @@ void SyncRes::addCruft(const string &qname, vector& ret) } } } - LOG<& ret, int depth) @@ -1208,6 +1208,5 @@ int directResolve(const std::string& qname, const QType& qtype, int qclass, vect SyncRes sr(now); int res = sr.beginResolve(qname, QType(qtype), qclass, ret); - cerr<<"Result: "<&ret); void setId(int id) { - if(s_log) + if(doLog()) d_prefix="["+itoa(id)+"] "; } - static void setLog(bool log) + static void setDefaultLogMode(LogMode lm) + { + s_lm = lm; + } + + void setLogMode(LogMode lm) + { + d_lm = lm; + } + + bool doLog() { - s_log=log; + return d_lm != LogNone; } + void setCacheOnly(bool state=true) { d_cacheonly=state; @@ -195,6 +208,11 @@ public: d_doEDNS0=state; } + string getTrace() const + { + return d_trace.str(); + } + int asyncresolveWrapper(const ComboAddress& ip, const string& domain, int type, bool doTCP, bool sendRDQuery, struct timeval* now, LWResult* res); static void doEDNSDumpAndClose(int fd); @@ -333,7 +351,8 @@ public: static unsigned int s_packetcacheservfailttl; static bool s_nopacketcache; static string s_serverID; - + + struct StaticStorage { negcache_t negcache; nsspeeds_t nsSpeeds; @@ -361,11 +380,13 @@ private: vector getAs(const string &qname, int depth, set& beenthere); private: + ostringstream d_trace; string d_prefix; - static bool s_log; bool d_cacheonly; bool d_nocache; bool d_doEDNS0; + static LogMode s_lm; + LogMode d_lm; struct GetBestNSAnswer { @@ -523,12 +544,11 @@ struct RemoteKeeper }; extern __thread RemoteKeeper* t_remotes; string doQueueReloadLuaScript(vector::const_iterator begin, vector::const_iterator end); +string doTraceRegex(vector::const_iterator begin, vector::const_iterator end); void parseACLs(); extern RecursorStats g_stats; extern unsigned int g_numThreads; - - std::string reloadAuthAndForwards(); ComboAddress parseIPAndPort(const std::string& input, uint16_t port); ComboAddress getQueryLocalAddress(int family, uint16_t port); -- 2.40.0