Provide more spans for input processing

Signed-off-by: Otto Moerbeek <otto.moerbeek@open-xchange.com>

diff --git a/pdns/recursordist/pdns_recursor.cc b/pdns/recursordist/pdns_recursor.cc
index 4ac18ec19bdac6906527d342a35c20969af97ad3..62788544a52596cbe4e82cd8558dc228123db77c 100644 (file)
--- a/pdns/recursordist/pdns_recursor.cc
+++ b/pdns/recursordist/pdns_recursor.cc
@@ -1778,6 +1778,7 @@ void startDoResolve(void* arg) // NOLINT(readability-function-cognitive-complexi
       t_Counters.updateSnap(g_regressionTestMode);
     }
 
+    auto match = resolver.d_eventTrace.add(RecEventTrace::AnswerSent);
     if (!comboWriter->d_tcp) {
       struct msghdr msgh{};
       struct iovec iov{};
@@ -1799,7 +1800,7 @@ void startDoResolve(void* arg) // NOLINT(readability-function-cognitive-complexi
       tcpGuard.setHandled();
     }
 
-    resolver.d_eventTrace.add(RecEventTrace::AnswerSent);
+    resolver.d_eventTrace.add(RecEventTrace::AnswerSent, 0, false, match);
 
     // Now do the per query changing part of the protobuf message
     if (t_protobufServers.servers && !(luaconfsLocal->protobufExportConfig.taggedOnly && appliedPolicy.getName().empty() && comboWriter->d_policyTags.empty())) {
@@ -2140,6 +2141,9 @@ bool expectProxyProtocol(const ComboAddress& from, const ComboAddress& listenAdd
 // mappedSource: the address we assume the query is coming from. Differs from source if table based mapping has been applied
 static string* doProcessUDPQuestion(const std::string& question, const ComboAddress& fromaddr, const ComboAddress& destaddr, ComboAddress source, ComboAddress destination, const ComboAddress& mappedSource, struct timeval tval, int fileDesc, std::vector<ProxyProtocolValue>& proxyProtocolValues, RecEventTrace& eventTrace, pdns::trace::InitialSpanInfo& otTrace) // NOLINT(readability-function-cognitive-complexity): https://github.com/PowerDNS/pdns/issues/12791
 {
+  auto newParent = eventTrace.add(RecEventTrace::ProcessUDP);
+  auto oldParent = eventTrace.setParent(newParent);
+  RecEventTrace::EventScope traceScope(oldParent, eventTrace);
   RecThreadInfo::self().incNumberOfDistributedQueries();
   gettimeofday(&g_now, nullptr);
   if (tval.tv_sec != 0) {
@@ -2220,6 +2224,7 @@ static string* doProcessUDPQuestion(const std::string& question, const ComboAddr
     // We do not have a SyncRes specific Lua context at this point yet, so ok to use t_pdl
     if (needEDNSParse || (t_pdl && (t_pdl->hasGettagFunc() || t_pdl->hasGettagFFIFunc())) || dnsheader->opcode == static_cast<unsigned>(Opcode::Notify)) {
       try {
+        auto parseMatch = eventTrace.add(RecEventTrace::PacketParse);
         EDNSOptionViewMap ednsOptions;
 
         ecsFound = false;
@@ -2229,12 +2234,14 @@ static string* doProcessUDPQuestion(const std::string& question, const ComboAddr
                           (g_gettagNeedsEDNSOptions || SyncRes::eventTraceEnabled(SyncRes::event_trace_to_ot)) ? &ednsOptions : nullptr,
                           ednsVersion);
 
+        eventTrace.add(RecEventTrace::PacketParse, 0, false, parseMatch);
         qnameParsed = true;
         ecsParsed = true;
 
         if (SyncRes::eventTraceEnabled(SyncRes::event_trace_to_ot)) {
           pdns::trace::extractOTraceIDs(ednsOptions, otTrace);
         }
+
         if (t_pdl) {
           try {
             if (t_pdl->hasGettagFFIFunc()) {
@@ -2289,6 +2296,7 @@ static string* doProcessUDPQuestion(const std::string& question, const ComboAddr
                             "qname", Logging::Loggable(qname), "qtype", Logging::Loggable(QType(qtype)),
                             "source", Logging::Loggable(source), "remote", Logging::Loggable(fromaddr));
         }
+        match = eventTrace.add(RecEventTrace::AnswerSent);
         struct msghdr msgh{};
         struct iovec iov{};
         cmsgbuf_aligned cbuf{};
@@ -2299,8 +2307,8 @@ static string* doProcessUDPQuestion(const std::string& question, const ComboAddr
           addCMsgSrcAddr(&msgh, &cbuf, &destaddr, 0);
         }
         int sendErr = sendOnNBSocket(fileDesc, &msgh);
-        eventTrace.add(RecEventTrace::AnswerSent);
-
+        eventTrace.add(RecEventTrace::AnswerSent, sendErr, false, match);
+        traceScope.close(0);
         if (t_protobufServers.servers && logResponse && (!luaconfsLocal->protobufExportConfig.taggedOnly || (pbData && pbData->d_tagged))) {
           protobufLogResponse(qname, qtype, dnsheader, luaconfsLocal, pbData, tval, false, source, destination, mappedSource, ednssubnet, uniqueId, requestorId, deviceId, deviceName, meta, eventTrace, otTrace, policyTags);
         }
@@ -2404,6 +2412,7 @@ static string* doProcessUDPQuestion(const std::string& question, const ComboAddr
   comboWriter->d_responsePaddingDisabled = responsePaddingDisabled;
   comboWriter->d_meta = std::move(meta);
 
+  traceScope.close(0);
   comboWriter->d_eventTrace = std::move(eventTrace);
   comboWriter->d_otTrace = std::move(otTrace);
 
@@ -2442,7 +2451,7 @@ static void handleNewUDPQuestion(int fileDesc, FDMultiplexer::funcparam_t& /* va
       // established the reference point, get an absolute TS as close as possible to the
       // eventTrace start of trace time.
       auto traceTS = pdns::trace::timestamp();
-      eventTrace.add(RecEventTrace::ReqRecv);
+      auto match = eventTrace.add(RecEventTrace::ReqRecv);
       if (SyncRes::eventTraceEnabled(SyncRes::event_trace_to_ot)) {
         otTrace.clear();
         otTrace.start_time_unix_nano = traceTS;
@@ -2592,6 +2601,7 @@ static void handleNewUDPQuestion(int fileDesc, FDMultiplexer::funcparam_t& /* va
             destination = destaddr;
           }
 
+          eventTrace.add(RecEventTrace::ReqRecv, 0, false, match);
           if (RecThreadInfo::weDistributeQueries()) {
             std::string localdata = data;
             distributeAsyncFunction(data, [localdata = std::move(localdata), fromaddr, destaddr, source, destination, mappedSource, tval, fileDesc, proxyProtocolValues, eventTrace, otTrace]() mutable {

diff --git a/pdns/recursordist/rec-eventtrace.cc b/pdns/recursordist/rec-eventtrace.cc
index 8b1be8f529a7dae97b06475b4ce61208ac0c70ae..33cde98d62363c2d1209f263871de787d55061a0 100644 (file)
--- a/pdns/recursordist/rec-eventtrace.cc
+++ b/pdns/recursordist/rec-eventtrace.cc
@@ -40,6 +40,9 @@ const std::unordered_map<RecEventTrace::EventType, std::string> RecEventTrace::s
   NameEntry(LuaNXDomain),
   NameEntry(LuaPostResolveFFI),
   NameEntry(AuthRequest),
+  NameEntry(PacketParse),
+  NameEntry(ProcessUDP),
+  NameEntry(ProcessTCP),
 };
 
 using namespace pdns::trace;

diff --git a/pdns/recursordist/rec-eventtrace.hh b/pdns/recursordist/rec-eventtrace.hh
index a661f5afc3c86850fe0371fec1c2de59461915c4..74117f0e6eefbadaff52c5337e91e55265beb4a4 100644 (file)
--- a/pdns/recursordist/rec-eventtrace.hh
+++ b/pdns/recursordist/rec-eventtrace.hh
@@ -56,6 +56,9 @@ public:
     LuaPostResolveFFI = 110,
 
     AuthRequest = 120,
+    PacketParse = 121,
+    ProcessUDP = 122,
+    ProcessTCP = 123,
   };
 
   static const std::unordered_map<EventType, std::string> s_eventNames;

diff --git a/pdns/recursordist/rec-tcp.cc b/pdns/recursordist/rec-tcp.cc
index 6d26f2b417ee8890ccb8caf136d9fd7d646e1446..fa7c9a7264f7fe9728c99f5d71127a98f61e772a 100644 (file)
--- a/pdns/recursordist/rec-tcp.cc
+++ b/pdns/recursordist/rec-tcp.cc
@@ -311,6 +311,10 @@ static void doProcessTCPQuestion(std::unique_ptr<DNSComboWriter>& comboWriter, s
     comboWriter->d_otTrace.clear();
     comboWriter->d_otTrace.start_time_unix_nano = traceTS;
   }
+  auto newParent = comboWriter->d_eventTrace.add(RecEventTrace::ProcessTCP);
+  auto oldParent = comboWriter->d_eventTrace.setParent(newParent);
+  RecEventTrace::EventScope traceScope(oldParent, comboWriter->d_eventTrace);
+
   auto luaconfsLocal = g_luaconfs.getLocal();
   if (checkProtobufExport(luaconfsLocal)) {
     needEDNSParse = true;
@@ -321,12 +325,14 @@ static void doProcessTCPQuestion(std::unique_ptr<DNSComboWriter>& comboWriter, s
   if (needEDNSParse || (t_pdl && (t_pdl->hasGettagFFIFunc() || t_pdl->hasGettagFunc())) || comboWriter->d_mdp.d_header.opcode == static_cast<unsigned>(Opcode::Notify)) {
 
     try {
+      auto parseMatch = comboWriter->d_eventTrace.add(RecEventTrace::PacketParse);
       EDNSOptionViewMap ednsOptions;
       comboWriter->d_ecsParsed = true;
       comboWriter->d_ecsFound = false;
       getQNameAndSubnet(conn->data, &qname, &qtype, &qclass,
                         comboWriter->d_ecsFound, &comboWriter->d_ednssubnet,
                         (g_gettagNeedsEDNSOptions || SyncRes::eventTraceEnabled(SyncRes::event_trace_to_ot)) ? &ednsOptions : nullptr, ednsVersion);
+      comboWriter->d_eventTrace.add(RecEventTrace::PacketParse, 0, false, parseMatch);
       qnameParsed = true;
 
       if (SyncRes::eventTraceEnabled(SyncRes::event_trace_to_ot)) {
@@ -452,13 +458,15 @@ static void doProcessTCPQuestion(std::unique_ptr<DNSComboWriter>& comboWriter, s
                             "source", Logging::Loggable(comboWriter->d_source), "remote", Logging::Loggable(comboWriter->d_remote));
         }
 
+        auto answerMatch = comboWriter->d_eventTrace.add(RecEventTrace::AnswerSent);
         bool hadError = sendResponseOverTCP(comboWriter, response);
         finishTCPReply(comboWriter, hadError, false);
         struct timeval now{};
         Utility::gettimeofday(&now, nullptr);
         uint64_t spentUsec = uSec(now - start);
         t_Counters.at(rec::Histogram::cumulativeAnswers)(spentUsec);
-        comboWriter->d_eventTrace.add(RecEventTrace::AnswerSent);
+        comboWriter->d_eventTrace.add(RecEventTrace::AnswerSent, 0, false, answerMatch);
+        traceScope.close(0);
 
         if (t_protobufServers.servers && comboWriter->d_logResponse && (!luaconfsLocal->protobufExportConfig.taggedOnly || (pbData && pbData->d_tagged))) {
           struct timeval tval{
@@ -500,6 +508,7 @@ static void doProcessTCPQuestion(std::unique_ptr<DNSComboWriter>& comboWriter, s
       t_fdm->setReadTTD(fileDesc, ttd, g_tcpTimeout);
     }
     tcpGuard.keep();
+    traceScope.close(0);
     g_multiTasker->makeThread(startDoResolve, comboWriter.release()); // deletes dc
   } // good query
 }

diff --git a/pdns/recursordist/syncres.cc b/pdns/recursordist/syncres.cc
index e7c8ae1ffaca7ac3dc809d4234e92040fb2cd940..27ce77b7d62cd8ba22e344de8c85c6615477778c 100644 (file)
--- a/pdns/recursordist/syncres.cc
+++ b/pdns/recursordist/syncres.cc
@@ -5453,7 +5453,7 @@ bool SyncRes::doResolveAtThisIP(const std::string& prefix, const DNSName& qname,
       LOG(prefix << qname << ": Adding EDNS Client Subnet Mask " << ednsmask->toString() << " to query" << endl);
       s_ecsqueries++;
     }
-    auto match = d_eventTrace.add(RecEventTrace::AuthRequest, qname.toLogString() + '/' + qtype.toString(), true, 0);
+    auto match = d_eventTrace.add(RecEventTrace::AuthRequest, qname.toLogString() + '/' + qtype.toString() + '/' + remoteIP.toString(), true, 0);
     updateQueryCounts(prefix, qname, remoteIP, doTCP, doDoT);
     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!