]> git.ipfire.org Git - thirdparty/pdns.git/commitdiff
Start of eventTrace code.
authorOtto <otto.moerbeek@open-xchange.com>
Wed, 16 Jun 2021 10:34:01 +0000 (12:34 +0200)
committerOtto <otto.moerbeek@open-xchange.com>
Wed, 13 Oct 2021 12:31:29 +0000 (14:31 +0200)
Missing: config, many trace points, protobuf export.

pdns/lua-recursor4.cc
pdns/lua-recursor4.hh
pdns/pdns_recursor.cc
pdns/recursordist/Makefile.am
pdns/recursordist/rec-eventtrace.cc [new file with mode: 0644]
pdns/recursordist/rec-eventtrace.hh [new file with mode: 0644]
pdns/recursordist/test-syncres_cc.cc
pdns/syncres.cc
pdns/syncres.hh

index 98244c9da6c939879d2c0f482e5d966739a27c90..235e6b405e1481b5ba1421dc1e860cb118d5366f 100644 (file)
@@ -502,32 +502,47 @@ void RecursorLua4::maintenance() const
   }
 }
 
-bool RecursorLua4::prerpz(DNSQuestion& dq, int& ret) const
+bool RecursorLua4::prerpz(DNSQuestion& dq, int& ret, RecEventTrace& et) const
 {
-  return genhook(d_prerpz, dq, ret);
+  et.add(RecEventTrace::LuaPreRPZ);
+  bool ok = genhook(d_prerpz, dq, ret);
+  et.add(RecEventTrace::LuaPreRPZ, ok, false);
+  return ok;
 }
 
-bool RecursorLua4::preresolve(DNSQuestion& dq, int& ret) const
+bool RecursorLua4::preresolve(DNSQuestion& dq, int& ret, RecEventTrace& et) const
 {
-  return genhook(d_preresolve, dq, ret);
+  et.add(RecEventTrace::LuaPreResolve);
+  bool ok = genhook(d_preresolve, dq, ret);
+  et.add(RecEventTrace::LuaPreResolve, ok, false);
+  return ok;
 }
 
-bool RecursorLua4::nxdomain(DNSQuestion& dq, int& ret) const
+bool RecursorLua4::nxdomain(DNSQuestion& dq, int& ret, RecEventTrace& et) const
 {
-  return genhook(d_nxdomain, dq, ret);
+  et.add(RecEventTrace::LuaNXDomain);
+  bool ok = genhook(d_nxdomain, dq, ret);
+  et.add(RecEventTrace::LuaNXDomain, ok, false);
+  return ok;
 }
 
-bool RecursorLua4::nodata(DNSQuestion& dq, int& ret) const
+bool RecursorLua4::nodata(DNSQuestion& dq, int& ret, RecEventTrace& et) const
 {
-  return genhook(d_nodata, dq, ret);
+  et.add(RecEventTrace::LuaNoData);
+  bool ok = genhook(d_nodata, dq, ret);
+  et.add(RecEventTrace::LuaNoData, ok, false);
+  return ok;
 }
 
-bool RecursorLua4::postresolve(DNSQuestion& dq, int& ret) const
+bool RecursorLua4::postresolve(DNSQuestion& dq, int& ret, RecEventTrace& et) const
 {
-  return genhook(d_postresolve, dq, ret);
+  et.add(RecEventTrace::LuaPostResolve);
+  bool ok = genhook(d_postresolve, dq, ret);
+  et.add(RecEventTrace::LuaPostResolve, ok, false);
+  return ok;
 }
 
-bool RecursorLua4::preoutquery(const ComboAddress& ns, const ComboAddress& requestor, const DNSName& query, const QType& qtype, bool isTcp, vector<DNSRecord>& res, int& ret) const
+bool RecursorLua4::preoutquery(const ComboAddress& ns, const ComboAddress& requestor, const DNSName& query, const QType& qtype, bool isTcp, vector<DNSRecord>& res, int& ret, RecEventTrace& et) const
 {
   bool variableAnswer = false;
   bool wantsRPZ = false;
@@ -535,8 +550,10 @@ bool RecursorLua4::preoutquery(const ComboAddress& ns, const ComboAddress& reque
   bool addPaddingToResponse = false;
   RecursorLua4::DNSQuestion dq(ns, requestor, query, qtype.getCode(), isTcp, variableAnswer, wantsRPZ, logQuery, addPaddingToResponse);
   dq.currentRecords = &res;
-
-  return genhook(d_preoutquery, dq, ret);
+  et.add(RecEventTrace::LuaPreOutQuery);
+  bool ok = genhook(d_preoutquery, dq, ret);
+  et.add(RecEventTrace::LuaPreOutQuery, ok, false);
+  return ok;
 }
 
 bool RecursorLua4::ipfilter(const ComboAddress& remote, const ComboAddress& local, const struct dnsheader& dh) const
index a1ff21e89d860e5feae1e98ee220970ef6077cc6..b3d409f906e49bb301cd9764b58bf10ed0cd27d9 100644 (file)
@@ -35,6 +35,7 @@
 #include "lua-base4.hh"
 #include "proxy-protocol.hh"
 #include "noinitvector.hh"
+#include "rec-eventtrace.hh"
 
 #include <unordered_map>
 
@@ -185,13 +186,13 @@ public:
   unsigned int gettag_ffi(FFIParams&) const;
 
   void maintenance() const;
-  bool prerpz(DNSQuestion& dq, int& ret) const;
-  bool preresolve(DNSQuestion& dq, int& ret) const;
-  bool nxdomain(DNSQuestion& dq, int& ret) const;
-  bool nodata(DNSQuestion& dq, int& ret) const;
-  bool postresolve(DNSQuestion& dq, int& ret) const;
+  bool prerpz(DNSQuestion& dq, int& ret, RecEventTrace&) const;
+  bool preresolve(DNSQuestion& dq, int& ret, RecEventTrace&) const;
+  bool nxdomain(DNSQuestion& dq, int& ret, RecEventTrace&) const;
+  bool nodata(DNSQuestion& dq, int& ret, RecEventTrace&) const;
+  bool postresolve(DNSQuestion& dq, int& ret, RecEventTrace&) const;
 
-  bool preoutquery(const ComboAddress& ns, const ComboAddress& requestor, const DNSName& query, const QType& qtype, bool isTcp, vector<DNSRecord>& res, int& ret) const;
+  bool preoutquery(const ComboAddress& ns, const ComboAddress& requestor, const DNSName& query, const QType& qtype, bool isTcp, vector<DNSRecord>& res, int& ret, RecEventTrace& et) const;
   bool ipfilter(const ComboAddress& remote, const ComboAddress& local, const struct dnsheader&) const;
 
   bool policyHitEventFilter(const ComboAddress& remote, const DNSName& qname, const QType& qtype, bool tcp, DNSFilterEngine::Policy& policy, std::unordered_set<std::string>& tags, std::unordered_map<std::string, bool>& discardedPolicies) const;
index 2133fa57e96a4bf469a4f4d4e40c7272fb285062..50e9c82162f9f2a137f3e2a90232c76f9430e27f 100644 (file)
 #include "rec-protozero.hh"
 
 #include "xpf.hh"
+#include "rec-eventtrace.hh"
 
 typedef map<ComboAddress, uint32_t, ComboAddress::addressOnlyLessThan> tcpClientCounts_t;
 
@@ -337,6 +338,7 @@ struct DNSComboWriter {
      d_local holds our own. */
   ComboAddress d_local;
   ComboAddress d_destination;
+  RecEventTrace d_eventTrace;
   boost::uuids::uuid d_uuid;
   string d_requestorId;
   string d_deviceId;
@@ -1683,6 +1685,7 @@ static void startDoResolve(void *p)
     uint32_t minTTL = dc->d_ttlCap;
 
     SyncRes sr(dc->d_now);
+    sr.d_eventTrace = std::move(dc->d_eventTrace);
     sr.setId(MT->getTid());
 
     bool DNSSECOK=false;
@@ -1781,7 +1784,7 @@ static void startDoResolve(void *p)
     }
 
     if (t_pdl) {
-      t_pdl->prerpz(dq, res);
+      t_pdl->prerpz(dq, res, sr.d_eventTrace);
     }
 
     // Check if the client has a policy attached to it
@@ -1828,7 +1831,7 @@ static void startDoResolve(void *p)
     }
 
     // if there is a RecursorLua active, and it 'took' the query in preResolve, we don't launch beginResolve
-    if (!t_pdl || !t_pdl->preresolve(dq, res)) {
+    if (!t_pdl || !t_pdl->preresolve(dq, res, sr.d_eventTrace)) {
 
       if (!g_dns64PrefixReverse.empty() && dq.qtype == QType::PTR && dq.qname.isPartOf(g_dns64PrefixReverse)) {
         res = getFakePTRRecords(dq.qname, ret);
@@ -1917,7 +1920,7 @@ static void startDoResolve(void *p)
       if (t_pdl || (g_dns64Prefix && dq.qtype == QType::AAAA && !vStateIsBogus(dq.validationState))) {
         if (res == RCode::NoError) {
           if (answerIsNOData(dc->d_mdp.d_qtype, res, ret)) {
-            if (t_pdl && t_pdl->nodata(dq, res)) {
+            if (t_pdl && t_pdl->nodata(dq, res, sr.d_eventTrace)) {
               shouldNotValidate = true;
               auto policyResult = handlePolicyHit(appliedPolicy, dc, sr, res, ret, pw);
               if (policyResult == PolicyResult::HaveAnswer) {
@@ -1933,7 +1936,7 @@ static void startDoResolve(void *p)
             }
           }
        }
-       else if (res == RCode::NXDomain && t_pdl && t_pdl->nxdomain(dq, res)) {
+       else if (res == RCode::NXDomain && t_pdl && t_pdl->nxdomain(dq, res, sr.d_eventTrace)) {
           shouldNotValidate = true;
           auto policyResult = handlePolicyHit(appliedPolicy, dc, sr, res, ret, pw);
           if (policyResult == PolicyResult::HaveAnswer) {
@@ -1944,7 +1947,7 @@ static void startDoResolve(void *p)
           }
         }
 
-       if (t_pdl && t_pdl->postresolve(dq, res)) {
+       if (t_pdl && t_pdl->postresolve(dq, res, sr.d_eventTrace)) {
           shouldNotValidate = true;
           auto policyResult = handlePolicyHit(appliedPolicy, dc, sr, res, ret, pw);
           // haveAnswer case redundant
@@ -2334,6 +2337,11 @@ static void startDoResolve(void *p)
       bool hadError = sendResponseOverTCP(dc, packet);
       finishTCPReply(dc, hadError, true);
     }
+    // Protobuf sending should be here...
+    sr.d_eventTrace.add(RecEventTrace::AnswerSent);
+    if (sr.d_eventTrace.enabled()) {
+      g_log << Logger::Info << sr.d_eventTrace.toString() << endl;
+    }
 
     // Originally this code used a mix of floats, doubles, uint64_t with different units.
     // Now it always uses an integral number of microseconds, except for averages, which use doubles
@@ -2736,6 +2744,8 @@ static void handleRunningTCPQuestion(int fd, FDMultiplexer::funcparam_t& var)
       bool logQuery = false;
       bool qnameParsed = false;
 
+      dc->d_eventTrace.setEnabled(true);
+      dc->d_eventTrace.add(RecEventTrace::RecRecv);
       auto luaconfsLocal = g_luaconfs.getLocal();
       if (checkProtobufExport(luaconfsLocal)) {
         needECS = true;
@@ -2764,9 +2774,12 @@ static void handleRunningTCPQuestion(int fd, FDMultiplexer::funcparam_t& var)
               if (t_pdl->d_gettag_ffi) {
                 RecursorLua4::FFIParams params(qname, qtype, dc->d_destination, dc->d_source, dc->d_ednssubnet.source, dc->d_data, dc->d_policyTags, dc->d_records, ednsOptions, dc->d_proxyProtocolValues, requestorId, deviceId, deviceName, dc->d_routingTag, dc->d_rcode, dc->d_ttlCap, dc->d_variable, true, logQuery, dc->d_logResponse, dc->d_followCNAMERecords, dc->d_extendedErrorCode, dc->d_extendedErrorExtra, dc->d_responsePaddingDisabled, dc->d_meta);
                 dc->d_tag = t_pdl->gettag_ffi(params);
+                dc->d_eventTrace.add(RecEventTrace::LuaGetTagFFI, dc->d_tag, false);
               }
               else if (t_pdl->d_gettag) {
+                dc->d_eventTrace.add(RecEventTrace::LuaGetTag);
                 dc->d_tag = t_pdl->gettag(dc->d_source, dc->d_ednssubnet.source, dc->d_destination, qname, qtype, &dc->d_policyTags, dc->d_data, ednsOptions, true, requestorId, deviceId, deviceName, dc->d_routingTag, dc->d_proxyProtocolValues);
+                dc->d_eventTrace.add(RecEventTrace::LuaGetTag, dc->d_tag, false);
               }
             }
             catch(const std::exception& e)  {
@@ -2812,7 +2825,10 @@ static void handleRunningTCPQuestion(int fd, FDMultiplexer::funcparam_t& var)
       }
 
       if (t_pdl) {
-        if (t_pdl->ipfilter(dc->d_source, dc->d_destination, *dh)) {
+        dc->d_eventTrace.add(RecEventTrace::LuaIPFilter);
+        bool ipf = t_pdl->ipfilter(dc->d_source, dc->d_destination, *dh);
+        dc->d_eventTrace.add(RecEventTrace::LuaIPFilter, ipf, false);
+        if (ipf) {
           if (!g_quiet) {
             g_log<<Logger::Notice<<t_id<<" ["<<MT->getTid()<<"/"<<MT->numProcesses()<<"] DROPPED TCP question from "<<dc->d_source.toStringWithPort()<<(dc->d_source != dc->d_remote ? " (via "+dc->d_remote.toStringWithPort()+")" : "")<<" based on policy"<<endl;
           }
@@ -2857,7 +2873,9 @@ static void handleRunningTCPQuestion(int fd, FDMultiplexer::funcparam_t& var)
         /* It might seem like a good idea to skip the packet cache lookup if we know that the answer is not cacheable,
            but it means that the hash would not be computed. If some script decides at a later time to mark back the answer
            as cacheable we would cache it with a wrong tag, so better safe than sorry. */
+        dc->d_eventTrace.add(RecEventTrace::PCacheCheck);
         bool cacheHit = checkForCacheHit(qnameParsed, dc->d_tag, conn->data, qname, qtype, qclass, g_now, response, dc->d_qhash, pbData, true, dc->d_source);
+        dc->d_eventTrace.add(RecEventTrace::PCacheCheck, cacheHit, false);
 
         if (cacheHit) {
           if (t_protobufServers && dc->d_logResponse && !(luaconfsLocal->protobufExportConfig.taggedOnly && pbData && !pbData->d_tagged)) {
@@ -2875,6 +2893,10 @@ static void handleRunningTCPQuestion(int fd, FDMultiplexer::funcparam_t& var)
           Utility::gettimeofday(&now, nullptr);
           uint64_t spentUsec = uSec(now - start);
           g_stats.cumulativeAnswers(spentUsec);
+          dc->d_eventTrace.add(RecEventTrace::AnswerSent);
+          if (dc->d_eventTrace.enabled()) {
+            g_log << Logger::Info << dc->d_eventTrace.toString() << endl;
+          }
         } else {
           // No cache hit, setup for startDoResolve() in an mthread
           ++conn->d_requestsInFlight;
@@ -2970,7 +2992,7 @@ static void handleNewTCPQuestion(int fd, FDMultiplexer::funcparam_t& )
   }
 }
 
-static string* doProcessUDPQuestion(const std::string& question, const ComboAddress& fromaddr, const ComboAddress& destaddr, ComboAddress source, ComboAddress destination, struct timeval tv, int fd, std::vector<ProxyProtocolValue>& proxyProtocolValues)
+static string* doProcessUDPQuestion(const std::string& question, const ComboAddress& fromaddr, const ComboAddress& destaddr, ComboAddress source, ComboAddress destination, struct timeval tv, int fd, std::vector<ProxyProtocolValue>& proxyProtocolValues, RecEventTrace& eventTrace)
 {
   gettimeofday(&g_now, nullptr);
   if (tv.tv_sec) {
@@ -3063,9 +3085,12 @@ static string* doProcessUDPQuestion(const std::string& question, const ComboAddr
               RecursorLua4::FFIParams params(qname, qtype, destination, source, ednssubnet.source, data, policyTags, records, ednsOptions, proxyProtocolValues, requestorId, deviceId, deviceName, routingTag, rcode, ttlCap, variable, false, logQuery, logResponse, followCNAMEs, extendedErrorCode, extendedErrorExtra, responsePaddingDisabled, meta);
 
               ctag = t_pdl->gettag_ffi(params);
+              eventTrace.add(RecEventTrace::LuaGetTagFFI, ctag, false);
             }
             else if (t_pdl->d_gettag) {
+              eventTrace.add(RecEventTrace::LuaGetTag);
               ctag = t_pdl->gettag(source, ednssubnet.source, destination, qname, qtype, &policyTags, data, ednsOptions, false, requestorId, deviceId, deviceName, routingTag, proxyProtocolValues);
+              eventTrace.add(RecEventTrace::LuaGetTag, ctag, false);
             }
           }
           catch (const std::exception& e)  {
@@ -3096,7 +3121,9 @@ static string* doProcessUDPQuestion(const std::string& question, const ComboAddr
     /* It might seem like a good idea to skip the packet cache lookup if we know that the answer is not cacheable,
        but it means that the hash would not be computed. If some script decides at a later time to mark back the answer
        as cacheable we would cache it with a wrong tag, so better safe than sorry. */
+    eventTrace.add(RecEventTrace::PCacheCheck);
     bool cacheHit = checkForCacheHit(qnameParsed, ctag, question, qname, qtype, qclass, g_now, response, qhash, pbData, false, source);
+    eventTrace.add(RecEventTrace::PCacheCheck, cacheHit, false);
     if (cacheHit) {
       if (t_protobufServers && logResponse && !(luaconfsLocal->protobufExportConfig.taggedOnly && pbData && !pbData->d_tagged)) {
         protobufLogResponse(dh, luaconfsLocal, pbData, tv, false, source, destination, ednssubnet, uniqueId, requestorId, deviceId, deviceName, meta);
@@ -3115,6 +3142,10 @@ static string* doProcessUDPQuestion(const std::string& question, const ComboAddr
         addCMsgSrcAddr(&msgh, &cbuf, &destaddr, 0);
       }
       int sendErr = sendOnNBSocket(fd, &msgh);
+      eventTrace.add(RecEventTrace::AnswerSent);
+      if (eventTrace.enabled()) {
+        g_log << Logger::Info << eventTrace.toString() << endl;
+      }
       if (sendErr && g_logCommonErrors) {
         g_log << Logger::Warning << "Sending UDP reply to client " << source.toStringWithPort()
               << (source != fromaddr ? " (via " + fromaddr.toStringWithPort() + ")" : "") << " failed with: "
@@ -3135,7 +3166,10 @@ static string* doProcessUDPQuestion(const std::string& question, const ComboAddr
   }
 
   if (t_pdl) {
-    if (t_pdl->ipfilter(source, destination, *dh)) {
+    eventTrace.add(RecEventTrace::LuaIPFilter);
+    bool ipf = t_pdl->ipfilter(source, destination, *dh);
+    eventTrace.add(RecEventTrace::LuaIPFilter, ipf, false);
+    if (ipf) {
       if (!g_quiet) {
        g_log<<Logger::Notice<<t_id<<" ["<<MT->getTid()<<"/"<<MT->numProcesses()<<"] DROPPED question from "<<source.toStringWithPort()<<(source != fromaddr ? " (via "+fromaddr.toStringWithPort()+")" : "")<<" based on policy"<<endl;
       }
@@ -3183,7 +3217,9 @@ static string* doProcessUDPQuestion(const std::string& question, const ComboAddr
   dc->d_responsePaddingDisabled = responsePaddingDisabled;
   dc->d_meta = std::move(meta);
 
+  dc->d_eventTrace = std::move(eventTrace);
   MT->makeThread(startDoResolve, (void*) dc.release()); // deletes dc
+
   return 0;
 }
 
@@ -3201,6 +3237,7 @@ static void handleNewUDPQuestion(int fd, FDMultiplexer::funcparam_t& var)
   cmsgbuf_aligned cbuf;
   bool firstQuery = true;
   std::vector<ProxyProtocolValue> proxyProtocolValues;
+  RecEventTrace eventTrace;
 
   for(size_t queriesCounter = 0; queriesCounter < s_maxUDPQueriesPerRound; queriesCounter++) {
     bool proxyProto = false;
@@ -3210,6 +3247,9 @@ static void handleNewUDPQuestion(int fd, FDMultiplexer::funcparam_t& var)
     fillMSGHdr(&msgh, &iov, &cbuf, sizeof(cbuf), &data[0], data.size(), &fromaddr);
 
     if((len=recvmsg(fd, &msgh, 0)) >= 0) {
+      eventTrace.clear();
+      eventTrace.setEnabled(true);
+      eventTrace.add(RecEventTrace::RecRecv);
 
       firstQuery = false;
 
@@ -3335,12 +3375,13 @@ static void handleNewUDPQuestion(int fd, FDMultiplexer::funcparam_t& var)
 
           if(g_weDistributeQueries) {
             std::string localdata = data;
-            distributeAsyncFunction(data, [localdata, fromaddr, dest, source, destination, tv, fd, proxyProtocolValues]() mutable
-              { return doProcessUDPQuestion(localdata, fromaddr, dest, source, destination, tv, fd, proxyProtocolValues); });
+            distributeAsyncFunction(data, [localdata, fromaddr, dest, source, destination, tv, fd, proxyProtocolValues, eventTrace]() mutable {
+              return doProcessUDPQuestion(localdata, fromaddr, dest, source, destination, tv, fd, proxyProtocolValues, eventTrace);
+            });
           }
           else {
             ++s_threadInfos[t_id].numberOfDistributedQueries;
-            doProcessUDPQuestion(data, fromaddr, dest, source, destination, tv, fd, proxyProtocolValues);
+            doProcessUDPQuestion(data, fromaddr, dest, source, destination, tv, fd, proxyProtocolValues, eventTrace);
           }
         }
       }
index 9c157f43c07e31b9e5f99991576e475f7651a5af..593fd7d76275ad2e2ccde5bf47e52dc0042d5d7b 100644 (file)
@@ -159,6 +159,7 @@ pdns_recursor_SOURCES = \
        query-local-address.hh query-local-address.cc \
        rcpgenerator.cc rcpgenerator.hh \
        rec-carbon.cc \
+       rec-eventtrace.cc rec-eventtrace.hh \
        rec-lua-conf.hh rec-lua-conf.cc \
        rec-protozero.cc rec-protozero.hh \
        rec-snmp.hh rec-snmp.cc \
@@ -277,6 +278,7 @@ testrunner_SOURCES = \
        qtype.cc qtype.hh \
        query-local-address.hh query-local-address.cc \
        rcpgenerator.cc \
+       rec-eventtrace.cc rec-eventtrace.hh \
        rec-zonetocache.cc rec-zonetocache.hh \
        recpacketcache.cc recpacketcache.hh \
        recursor_cache.cc recursor_cache.hh \
diff --git a/pdns/recursordist/rec-eventtrace.cc b/pdns/recursordist/rec-eventtrace.cc
new file mode 100644 (file)
index 0000000..c5ceca4
--- /dev/null
@@ -0,0 +1,44 @@
+/*
+ * This file is part of PowerDNS or dnsdist.
+ * Copyright -- PowerDNS.COM B.V. and its contributors
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of version 2 of the GNU General Public License as
+ * published by the Free Software Foundation.
+ *
+ * In addition, for the avoidance of any doubt, permission is granted to
+ * link this program with OpenSSL and to (re)distribute the binaries
+ * produced as the result of such linking.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
+ */
+#include "rec-eventtrace.hh"
+
+#define NameEntry(M) \
+  {                  \
+    M, #M            \
+  }
+
+const std::map<RecEventTrace::EventType, std::string> RecEventTrace::s_eventNames = {
+  NameEntry(Processing),
+  NameEntry(RecRecv),
+  NameEntry(DistPipe),
+  NameEntry(PCacheCheck),
+  NameEntry(SyncRes),
+  NameEntry(AnswerSent),
+  NameEntry(LuaGetTag),
+  NameEntry(LuaGetTagFFI),
+  NameEntry(LuaIPFilter),
+  NameEntry(LuaPreRPZ),
+  NameEntry(LuaPreResolve),
+  NameEntry(LuaPreOutQuery),
+  NameEntry(LuaPostResolve),
+  NameEntry(LuaNoData),
+  NameEntry(LuaNXDomain)};
diff --git a/pdns/recursordist/rec-eventtrace.hh b/pdns/recursordist/rec-eventtrace.hh
new file mode 100644 (file)
index 0000000..569a573
--- /dev/null
@@ -0,0 +1,210 @@
+/*
+ * This file is part of PowerDNS or dnsdist.
+ * Copyright -- PowerDNS.COM B.V. and its contributors
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of version 2 of the GNU General Public License as
+ * published by the Free Software Foundation.
+ *
+ * In addition, for the avoidance of any doubt, permission is granted to
+ * link this program with OpenSSL and to (re)distribute the binaries
+ * produced as the result of such linking.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
+ */
+#pragma once
+
+#include "namespaces.hh"
+#include <optional>
+#include <time.h>
+#include <variant>
+
+class RecEventTrace
+{
+public:
+  enum EventType : uint8_t
+  {
+    // Don't forget to add a new entry to the table in the .cc file!
+    Processing = 1,
+    RecRecv = 2,
+    DistPipe = 3,
+    PCacheCheck = 4,
+    SyncRes = 5,
+    AnswerSent = 6,
+    LuaGetTag = 50,
+    LuaGetTagFFI = 51,
+    LuaIPFilter = 52,
+    LuaPreRPZ = 53,
+    LuaPreResolve = 54,
+    LuaPreOutQuery = 55,
+    LuaPostResolve = 56,
+    LuaNoData = 57,
+    LuaNXDomain = 58
+  };
+
+  static const std::map<EventType, std::string> s_eventNames;
+
+  RecEventTrace()
+  {
+    reset();
+  }
+
+  RecEventTrace(const RecEventTrace& old) :
+    d_events(std::move(old.d_events)),
+    d_base(old.d_base),
+    d_status(old.d_status)
+  {
+    old.d_status = Invalid;
+  }
+  RecEventTrace(RecEventTrace&& old) :
+    d_events(std::move(old.d_events)),
+    d_base(old.d_base),
+    d_status(old.d_status)
+  {
+    old.d_status = Invalid;
+  }
+  RecEventTrace& operator=(const RecEventTrace& old) = delete;
+  RecEventTrace& operator=(RecEventTrace&& old)
+  {
+    d_events = std::move(old.d_events);
+    d_base = old.d_base;
+    d_status = old.d_status;
+    old.d_status = Invalid;
+    return *this;
+  }
+
+  typedef std::variant<std::nullopt_t, bool, int32_t, uint32_t, std::string> Value_t;
+
+  static std::string toString(const EventType v)
+  {
+    return s_eventNames.at(v);
+  }
+
+  static std::string toString(const Value_t& v)
+  {
+    if (std::holds_alternative<std::nullopt_t>(v)) {
+      return "";
+    }
+    else if (std::holds_alternative<bool>(v)) {
+      return std::to_string(std::get<bool>(v));
+    }
+    else if (std::holds_alternative<int32_t>(v)) {
+      return std::to_string(std::get<int32_t>(v));
+    }
+    else if (std::holds_alternative<uint32_t>(v)) {
+      return std::to_string(std::get<uint32_t>(v));
+    }
+    else if (std::holds_alternative<std::string>(v)) {
+      return std::get<std::string>(v);
+    }
+    return "?";
+  }
+
+  struct Entry
+  {
+    Entry(Value_t& v, EventType e, bool start, uint32_t ts) :
+      d_value(v), d_ts(ts), d_event(e), d_start(start)
+    {
+    }
+    Value_t d_value;
+    uint64_t d_ts;
+    EventType d_event;
+    bool d_start;
+
+    std::string toString() const
+    {
+      std::string v = RecEventTrace::toString(d_value);
+      if (!v.empty()) {
+        v = "," + v;
+      }
+      return RecEventTrace::toString(d_event) + "(" + std::to_string(d_ts) + v + (d_start ? ")" : ",done)");
+    }
+  };
+
+  void setEnabled(bool flag)
+  {
+    assert(d_status != Invalid);
+    d_status = flag ? Enabled : Disabled;
+  }
+
+  bool enabled() const
+  {
+    return d_status == Enabled;
+  }
+
+  void add(EventType e, Value_t v, bool start)
+  {
+    assert(d_status != Invalid);
+    if (d_status == Disabled) {
+      return;
+    }
+    struct timespec ts;
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    uint64_t stamp = ts.tv_nsec + ts.tv_sec * 1000000000;
+    stamp -= d_base;
+    d_events.emplace_back(v, e, start, stamp);
+  }
+
+  void add(EventType e)
+  {
+    add(e, Value_t(std::nullopt), true);
+  }
+
+  template <class T>
+  void add(EventType e, T v, bool start)
+  {
+    add(e, Value_t(v), start);
+  }
+
+  void clear()
+  {
+    d_events.clear();
+    reset();
+  }
+  void reset()
+  {
+    struct timespec ts;
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    d_base = ts.tv_nsec + ts.tv_sec * 1000000000;
+    d_status = Disabled;
+  }
+
+  std::string toString() const
+  {
+    assert(d_status != Invalid);
+    if (d_status == Disabled) {
+      return "Disabled\n";
+    }
+    std::string ret = "eventTrace [";
+    bool first = true;
+    for (const auto& e : d_events) {
+      if (first) {
+        first = false;
+      }
+      else {
+        ret += "; ";
+      }
+      ret += e.toString();
+    }
+    ret += ']';
+    return ret;
+  }
+
+private:
+  std::vector<Entry> d_events;
+  uint64_t d_base;
+  enum Status
+  {
+    Disabled,
+    Invalid,
+    Enabled
+  };
+  mutable Status d_status{Disabled};
+};
index ba81b99920a4bd1aae0c9622ee756eca00d27c93..a18e206d99c73f4e9f98e8dbcfdf9918e6222aa8 100644 (file)
@@ -39,7 +39,7 @@ void BaseLua4::getFeatures(Features&)
 {
 }
 
-bool RecursorLua4::preoutquery(const ComboAddress& ns, const ComboAddress& requestor, const DNSName& query, const QType& qtype, bool isTcp, vector<DNSRecord>& res, int& ret) const
+bool RecursorLua4::preoutquery(const ComboAddress& ns, const ComboAddress& requestor, const DNSName& query, const QType& qtype, bool isTcp, vector<DNSRecord>& res, int& ret, RecEventTrace& et) const
 {
   return false;
 }
index 3a9009df49a8a43fececc5ae6f42f9c79d768126..b73f21ac30f938374272b2ff6ff9a26e006dc7f0 100644 (file)
@@ -125,6 +125,7 @@ SyncRes::SyncRes(const struct timeval& now) :  d_authzonequeries(0), d_outquerie
 /** everything begins here - this is the entry point just after receiving a packet */
 int SyncRes::beginResolve(const DNSName &qname, const QType qtype, QClass qclass, vector<DNSRecord>&ret, unsigned int depth)
 {
+  d_eventTrace.add(RecEventTrace::SyncRes);
   vState state = vState::Indeterminate;
   s_queries++;
   d_wasVariable=false;
@@ -170,6 +171,7 @@ int SyncRes::beginResolve(const DNSName &qname, const QType qtype, QClass qclass
     }
   }
 
+  d_eventTrace.add(RecEventTrace::SyncRes, res, false);
   return res;
 }
 
@@ -3932,7 +3934,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)) {
+  if(d_pdl && d_pdl->preoutquery(remoteIP, d_requestor, qname, qtype, doTCP, lwr.d_records, preOutQueryRet, d_eventTrace)) {
     LOG(prefix<<qname<<": query handled by Lua"<<endl);
   }
   else {
index 1e58a8622aa8a855cd6197d0d386be4491112b7c..a750b56db652d4f3382f8e5827ce216fe8e3b417 100644 (file)
@@ -53,6 +53,7 @@
 #include "sholder.hh"
 #include "histogram.hh"
 #include "tcpiohandler.hh"
+#include "rec-eventtrace.hh"
 
 #ifdef HAVE_CONFIG_H
 #include "config.h"
@@ -793,6 +794,7 @@ public:
   DNSFilterEngine::Policy d_appliedPolicy;
   std::unordered_set<std::string> d_policyTags;
   boost::optional<string> d_routingTag;
+  RecEventTrace d_eventTrace;
 
   unsigned int d_authzonequeries;
   unsigned int d_outqueries;