From be9c6d51ada1d5cc90c80f6d89e7e9ebcbb35d40 Mon Sep 17 00:00:00 2001 From: Otto Moerbeek Date: Fri, 6 Jun 2025 10:05:56 +0200 Subject: [PATCH] Better processing of parent info of event traces (and Spans) Signed-off-by: Otto Moerbeek --- contrib/ProtobufLogger.py | 2 +- pdns/dnsmessage.proto | 2 + pdns/protozero-trace.hh | 10 +++- pdns/recursordist/lua-recursor4.cc | 28 +++++----- pdns/recursordist/pdns_recursor.cc | 39 +++++++------- pdns/recursordist/rec-eventtrace.cc | 80 +++++++++++++++++++-------- pdns/recursordist/rec-eventtrace.hh | 84 +++++++++++++++++++++++------ pdns/recursordist/rec-main.cc | 6 +-- pdns/recursordist/rec-tcp.cc | 20 +++---- pdns/recursordist/syncres.cc | 9 +++- pdns/recursordist/syncres.hh | 4 ++ pdns/sdig.cc | 3 +- 12 files changed, 196 insertions(+), 91 deletions(-) diff --git a/contrib/ProtobufLogger.py b/contrib/ProtobufLogger.py index cab46bdf18..56e0e9c22a 100644 --- a/contrib/ProtobufLogger.py +++ b/contrib/ProtobufLogger.py @@ -79,7 +79,7 @@ class PDNSPBConnHandler(object): print("- Posting OTData to " + oturl) headers = {'Content-Type': 'application/x-protobuf'} answer = requests.post(self._oturl, data = msg, headers = headers) - print(' - ' + answer) + print(' - ' + str(answer)) def printQueryMessage(self, message): self.printSummary(message, 'Query') diff --git a/pdns/dnsmessage.proto b/pdns/dnsmessage.proto index 465b13b875..57215b85e3 100644 --- a/pdns/dnsmessage.proto +++ b/pdns/dnsmessage.proto @@ -170,6 +170,8 @@ message PBDNSMessage { LuaNoData = 108; LuaNXDomain = 109; LuaPostResolveFFI = 110; + + AuthRequest = 120; } message Event { diff --git a/pdns/protozero-trace.hh b/pdns/protozero-trace.hh index cabe918d84..66b87b4c2b 100644 --- a/pdns/protozero-trace.hh +++ b/pdns/protozero-trace.hh @@ -331,7 +331,7 @@ inline uint64_t timestamp() { timespec now{}; clock_gettime(CLOCK_REALTIME, &now); - return (1000000000ULL* now.tv_sec) + now.tv_nsec; + return (1000000000ULL * now.tv_sec) + now.tv_nsec; } struct Span @@ -663,13 +663,19 @@ struct TracesData void encode(protozero::pbf_writer& writer) const; static TracesData decode(protozero::pbf_reader& reader); - [[nodiscard]] std::string encode() const { + [[nodiscard]] std::string encode() const + { std::string data; protozero::pbf_writer writer{data}; encode(writer); return data; } + static TracesData boilerPlate(std::string&& service, std::vector&& spans) + { + return TracesData{ + .resource_spans = {pdns::trace::ResourceSpans{.resource = {.attributes = {{"service.name", {{std::move(service)}}}}}, .scope_spans = {{.spans = std::move(spans)}}}}}; + } }; inline ArrayValue ArrayValue::decode(protozero::pbf_reader& reader) diff --git a/pdns/recursordist/lua-recursor4.cc b/pdns/recursordist/lua-recursor4.cc index ef834b0f93..66bdf9b20f 100644 --- a/pdns/recursordist/lua-recursor4.cc +++ b/pdns/recursordist/lua-recursor4.cc @@ -597,9 +597,9 @@ bool RecursorLua4::prerpz(DNSQuestion& dnsQuestion, int& ret, RecEventTrace& eve if (!d_prerpz) { return false; } - eventTrace.add(RecEventTrace::LuaPreRPZ); + auto match = eventTrace.add(RecEventTrace::LuaPreRPZ); bool isOK = genhook(d_prerpz, dnsQuestion, ret); - eventTrace.add(RecEventTrace::LuaPreRPZ, isOK, false); + eventTrace.add(RecEventTrace::LuaPreRPZ, isOK, false, match); warnDrop(dnsQuestion); return isOK; } @@ -609,9 +609,9 @@ bool RecursorLua4::preresolve(DNSQuestion& dnsQuestion, int& ret, RecEventTrace& if (!d_preresolve) { return false; } - eventTrace.add(RecEventTrace::LuaPreResolve); + auto match = eventTrace.add(RecEventTrace::LuaPreResolve); bool isOK = genhook(d_preresolve, dnsQuestion, ret); - eventTrace.add(RecEventTrace::LuaPreResolve, isOK, false); + eventTrace.add(RecEventTrace::LuaPreResolve, isOK, false, match); warnDrop(dnsQuestion); return isOK; } @@ -621,9 +621,9 @@ bool RecursorLua4::nxdomain(DNSQuestion& dnsQuestion, int& ret, RecEventTrace& e if (!d_nxdomain) { return false; } - eventTrace.add(RecEventTrace::LuaNXDomain); + auto match = eventTrace.add(RecEventTrace::LuaNXDomain); bool isOK = genhook(d_nxdomain, dnsQuestion, ret); - eventTrace.add(RecEventTrace::LuaNXDomain, isOK, false); + eventTrace.add(RecEventTrace::LuaNXDomain, isOK, false, match); warnDrop(dnsQuestion); return isOK; } @@ -633,9 +633,9 @@ bool RecursorLua4::nodata(DNSQuestion& dnsQuestion, int& ret, RecEventTrace& eve if (!d_nodata) { return false; } - eventTrace.add(RecEventTrace::LuaNoData); + auto match = eventTrace.add(RecEventTrace::LuaNoData); bool isOK = genhook(d_nodata, dnsQuestion, ret); - eventTrace.add(RecEventTrace::LuaNoData, isOK, false); + eventTrace.add(RecEventTrace::LuaNoData, isOK, false, match); warnDrop(dnsQuestion); return isOK; } @@ -645,9 +645,9 @@ bool RecursorLua4::postresolve(DNSQuestion& dnsQuestion, int& ret, RecEventTrace if (!d_postresolve) { return false; } - eventTrace.add(RecEventTrace::LuaPostResolve); + auto match = eventTrace.add(RecEventTrace::LuaPostResolve); bool isOK = genhook(d_postresolve, dnsQuestion, ret); - eventTrace.add(RecEventTrace::LuaPostResolve, isOK, false); + eventTrace.add(RecEventTrace::LuaPostResolve, isOK, false, match); warnDrop(dnsQuestion); return isOK; } @@ -663,9 +663,9 @@ bool RecursorLua4::preoutquery(const ComboAddress& nameserver, const ComboAddres bool addPaddingToResponse = false; RecursorLua4::DNSQuestion dnsQuestion(nameserver, requestor, nameserver, requestor, query, qtype.getCode(), isTcp, variableAnswer, wantsRPZ, logQuery, addPaddingToResponse, theTime); dnsQuestion.currentRecords = &res; - eventTrace.add(RecEventTrace::LuaPreOutQuery); + auto match = eventTrace.add(RecEventTrace::LuaPreOutQuery); bool isOK = genhook(d_preoutquery, dnsQuestion, ret); - eventTrace.add(RecEventTrace::LuaPreOutQuery, isOK, false); + eventTrace.add(RecEventTrace::LuaPreOutQuery, isOK, false, match); warnDrop(dnsQuestion); return isOK; } @@ -675,9 +675,9 @@ bool RecursorLua4::ipfilter(const ComboAddress& remote, const ComboAddress& loca if (!d_ipfilter) { return false; // Do not block } - eventTrace.add(RecEventTrace::LuaIPFilter); + auto match = eventTrace.add(RecEventTrace::LuaIPFilter); bool isOK = d_ipfilter(remote, local, header); - eventTrace.add(RecEventTrace::LuaIPFilter, isOK, false); + eventTrace.add(RecEventTrace::LuaIPFilter, isOK, false, match); return isOK; } diff --git a/pdns/recursordist/pdns_recursor.cc b/pdns/recursordist/pdns_recursor.cc index 9a6ba7d005..6a38e8f003 100644 --- a/pdns/recursordist/pdns_recursor.cc +++ b/pdns/recursordist/pdns_recursor.cc @@ -1388,9 +1388,9 @@ void startDoResolve(void* arg) // NOLINT(readability-function-cognitive-complexi PolicyResult policyResult = PolicyResult::NoAction; if (comboWriter->d_luaContext->hasPostResolveFFIfunc()) { RecursorLua4::PostResolveFFIHandle handle(dnsQuestion); - resolver.d_eventTrace.add(RecEventTrace::LuaPostResolveFFI); + auto match = resolver.d_eventTrace.add(RecEventTrace::LuaPostResolveFFI); bool prResult = comboWriter->d_luaContext->postresolve_ffi(handle); - resolver.d_eventTrace.add(RecEventTrace::LuaPostResolveFFI, prResult, false); + resolver.d_eventTrace.add(RecEventTrace::LuaPostResolveFFI, prResult, false, match); if (prResult) { shouldNotValidate = true; policyResult = handlePolicyHit(appliedPolicy, comboWriter, resolver, res, ret, packetWriter, tcpGuard); @@ -1815,7 +1815,10 @@ void startDoResolve(void* arg) // NOLINT(readability-function-cognitive-complexi tcpGuard.setHandled(); } - resolver.d_eventTrace.add(RecEventTrace::AnswerSent); + if (resolver.d_eventTrace.enabled()) { + resolver.d_eventTrace.add(RecEventTrace::AnswerSent); + resolver.d_eventTrace.add(RecEventTrace::CustomEvent, comboWriter->d_mdp.d_qname.toLogString() + '/' + QType(comboWriter->d_mdp.d_qtype).toString(), false, -1U); // XXX + } // 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())) { @@ -1871,14 +1874,12 @@ void startDoResolve(void* arg) // NOLINT(readability-function-cognitive-complexi } } #endif /* NOD_ENABLED */ - if (resolver.d_eventTrace.enabled() && (SyncRes::s_event_trace_enabled & SyncRes::event_trace_to_pb) != 0) { + if (resolver.d_eventTrace.enabled() && SyncRes::eventTraceEnabled(SyncRes::event_trace_to_pb)) { pbMessage.addEvents(resolver.d_eventTrace); } - if (resolver.d_eventTrace.enabled() && (SyncRes::s_event_trace_enabled & SyncRes::event_trace_to_ot) != 0) { + if (resolver.d_eventTrace.enabled() && SyncRes::eventTraceEnabled(SyncRes::event_trace_to_ot)) { resolver.d_otTrace.close(); - auto spans = resolver.d_eventTrace.convertToOT(resolver.d_otTrace); - pdns::trace::TracesData otTrace{ - .resource_spans = { pdns::trace::ResourceSpans{.resource = {.attributes = {{"service.name", {{"rec"}}}}}, .scope_spans = {{.spans = spans}}}}}; + auto otTrace = pdns::trace::TracesData::boilerPlate("rec", resolver.d_eventTrace.convertToOT(resolver.d_otTrace)); string otData = otTrace.encode(); pbMessage.setOpenTelemetryData(otData); } @@ -1887,7 +1888,7 @@ void startDoResolve(void* arg) // NOLINT(readability-function-cognitive-complexi } } - if (resolver.d_eventTrace.enabled() && (SyncRes::s_event_trace_enabled & SyncRes::event_trace_to_log) != 0) { + if (resolver.d_eventTrace.enabled() && SyncRes::eventTraceEnabled(SyncRes::event_trace_to_log)) { SLOG(g_log << Logger::Info << resolver.d_eventTrace.toString() << endl, resolver.d_slog->info(Logr::Info, resolver.d_eventTrace.toString())); // Maybe we want it to be more fancy? } @@ -2267,13 +2268,13 @@ static string* doProcessUDPQuestion(const std::string& question, const ComboAddr getQNameAndSubnet(question, &qname, &qtype, &qclass, ecsFound, &ednssubnet, - (g_gettagNeedsEDNSOptions || (SyncRes::s_event_trace_enabled & SyncRes::event_trace_to_ot) != 0) ? &ednsOptions : nullptr, + (g_gettagNeedsEDNSOptions || SyncRes::eventTraceEnabled(SyncRes::event_trace_to_ot)) ? &ednsOptions : nullptr, ednsVersion); qnameParsed = true; ecsParsed = true; - if ((SyncRes::s_event_trace_enabled & SyncRes::event_trace_to_ot) != 0) { + if (SyncRes::eventTraceEnabled(SyncRes::event_trace_to_ot)) { pdns::trace::extractOTraceIDs(ednsOptions, otTrace); } if (t_pdl) { @@ -2281,14 +2282,14 @@ static string* doProcessUDPQuestion(const std::string& question, const ComboAddr if (t_pdl->hasGettagFFIFunc()) { RecursorLua4::FFIParams params(qname, qtype, destaddr, fromaddr, destination, source, ednssubnet.getSource(), data, policyTags, records, ednsOptions, proxyProtocolValues, requestorId, deviceId, deviceName, routingTag, rcode, ttlCap, variable, false, logQuery, logResponse, followCNAMEs, extendedErrorCode, extendedErrorExtra, responsePaddingDisabled, meta); - eventTrace.add(RecEventTrace::LuaGetTagFFI); + auto match = eventTrace.add(RecEventTrace::LuaGetTagFFI); ctag = t_pdl->gettag_ffi(params); - eventTrace.add(RecEventTrace::LuaGetTagFFI, ctag, false); + eventTrace.add(RecEventTrace::LuaGetTagFFI, ctag, false, match); } else if (t_pdl->hasGettagFunc()) { - eventTrace.add(RecEventTrace::LuaGetTag); + auto match = eventTrace.add(RecEventTrace::LuaGetTag); ctag = t_pdl->gettag(source, ednssubnet.getSource(), destination, qname, qtype, &policyTags, data, ednsOptions, false, requestorId, deviceId, deviceName, routingTag, proxyProtocolValues); - eventTrace.add(RecEventTrace::LuaGetTag, ctag, false); + eventTrace.add(RecEventTrace::LuaGetTag, ctag, false, match); } } catch (const MOADNSException& moadnsexception) { @@ -2321,9 +2322,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); + auto match = eventTrace.add(RecEventTrace::PCacheCheck); bool cacheHit = checkForCacheHit(qnameParsed, ctag, question, qname, qtype, qclass, g_now, response, qhash, pbData, false, source, mappedSource); - eventTrace.add(RecEventTrace::PCacheCheck, cacheHit, false); + eventTrace.add(RecEventTrace::PCacheCheck, cacheHit, false, match); if (cacheHit) { if (!g_quiet) { SLOG(g_log << Logger::Notice << RecThreadInfo::id() << " question answered from packet cache tag=" << ctag << " from " << source.toStringWithPort() << (source != fromaddr ? " (via " + fromaddr.toStringWithPort() + ")" : "") << endl, @@ -2347,7 +2348,7 @@ static string* doProcessUDPQuestion(const std::string& question, const ComboAddr protobufLogResponse(dnsheader, luaconfsLocal, pbData, tval, false, source, destination, mappedSource, ednssubnet, uniqueId, requestorId, deviceId, deviceName, meta, eventTrace, otTrace, policyTags); } - if (eventTrace.enabled() && (SyncRes::s_event_trace_enabled & SyncRes::event_trace_to_log) != 0) { + if (eventTrace.enabled() && SyncRes::eventTraceEnabled(SyncRes::event_trace_to_log)) { SLOG(g_log << Logger::Info << eventTrace.toString() << endl, g_slogudpin->info(Logr::Info, eventTrace.toString())); // Do we want more fancy logging here? } @@ -2494,7 +2495,7 @@ static void handleNewUDPQuestion(int fileDesc, FDMultiplexer::funcparam_t& /* va // eventTrace start of trace time. auto traceTS = pdns::trace::timestamp(); eventTrace.add(RecEventTrace::ReqRecv); - if ((SyncRes::s_event_trace_enabled & SyncRes::event_trace_to_ot) != 0) { + if (SyncRes::eventTraceEnabled(SyncRes::event_trace_to_ot)) { otTrace.clear(); otTrace.start_time_unix_nano = traceTS; otTrace.name = "RecRequest"; diff --git a/pdns/recursordist/rec-eventtrace.cc b/pdns/recursordist/rec-eventtrace.cc index 38f034a0cb..fd4d4d4294 100644 --- a/pdns/recursordist/rec-eventtrace.cc +++ b/pdns/recursordist/rec-eventtrace.cc @@ -38,10 +38,35 @@ const std::unordered_map RecEventTrace::s NameEntry(LuaPostResolve), NameEntry(LuaNoData), NameEntry(LuaNXDomain), - NameEntry(LuaPostResolveFFI)}; + NameEntry(LuaPostResolveFFI), + NameEntry(AuthRequest), +}; using namespace pdns::trace; +static void addValue(const RecEventTrace::Entry& event, Span& work) +{ + if (std::holds_alternative(event.d_value)) { + return; + } + if (std::holds_alternative(event.d_value)) { + work.attributes.emplace_back(KeyValue{"value", {std::get(event.d_value)}}); + } + else if (std::holds_alternative(event.d_value)) { + work.attributes.emplace_back(KeyValue{"value", {std::get(event.d_value)}}); + } + else if (std::holds_alternative(event.d_value)) { + work.attributes.emplace_back(KeyValue{"value", {std::get(event.d_value)}}); + } + else { + work.attributes.emplace_back(KeyValue{"value", {RecEventTrace::toString(event.d_value)}}); + } +} + +// The event trace uses start-stop records which need to be mapped to opentrace spans, which is a +// list of spans. Spans can refer to other spand as their parent. I have the feeling this code is +// to complex and a brittle. Maybe we should add some extra info to the event trace records to make +// is easier to map the event trace list to the open trace list of spans. std::vector RecEventTrace::convertToOT(const Span& span) const { timespec realtime{}; @@ -53,42 +78,53 @@ std::vector RecEventTrace::convertToOT(const Span& span) cons std::vector ret; ret.reserve((d_events.size() / 2) + 1); + + // The parent of all Span ret.emplace_back(span); - std::map pairs; + + std::vector spanIDs; // mapping of span index in ret vector to SpanID + std::map ids; // mapping from event record index to index in ret vector (Spans) + + size_t index = 0; for (const auto& event : d_events) { + cerr << index << ' ' << event.toString () << ' ' << event.d_matching << endl; if (event.d_start) { + // It's an open event Span work{ .name = RecEventTrace::toString(event.d_event), .trace_id = span.trace_id, - .parent_span_id = span.span_id, .start_time_unix_nano = static_cast(event.d_ts + diff), - .end_time_unix_nano = static_cast(event.d_ts + diff), + .end_time_unix_nano = static_cast(event.d_ts + diff), // will be updated when we process the close event }; + if (event.d_parent == 0 || event.d_parent >= spanIDs.size()) { + // Use the given parent + work.parent_span_id = span.span_id; + } + else { + // The parent is coming from the events we already processed + work.parent_span_id = spanIDs.at(event.d_parent); + } + // Assign a span id. random(work.span_id); + addValue(event, work); + spanIDs.emplace_back(work.span_id); ret.emplace_back(work); - pairs[event.d_event] = ret.size() - 1; + ids[index] = ret.size() - 1; } else { - if (auto startEvent = pairs.find(event.d_event); startEvent != pairs.end()) { - auto& work = ret.at(startEvent->second); - if (!std::holds_alternative(event.d_value)) { - if (std::holds_alternative(event.d_value)) { - work.attributes.emplace_back(KeyValue{"value", {std::get(event.d_value)}}); - } - else if (std::holds_alternative(event.d_value)) { - work.attributes.emplace_back(KeyValue{"value", {std::get(event.d_value)}}); - } - else if (std::holds_alternative(event.d_value)) { - work.attributes.emplace_back(KeyValue{"value", {std::get(event.d_value)}}); - } - else { - work.attributes.emplace_back(KeyValue{"value", {toString(event.d_value)}}); - } - } + // It's a close event + if (event.d_matching == -1U) { + auto& work = ret.at(0); + addValue(event, work); + } + else if (ids.find(event.d_matching) != ids.end()) { + auto& work = ret.at(ids.at(event.d_matching)); + addValue(event, work); work.end_time_unix_nano = static_cast(event.d_ts + diff); - pairs.erase(event.d_event); + spanIDs.emplace_back(work.span_id); } } + ++index; } return ret; } diff --git a/pdns/recursordist/rec-eventtrace.hh b/pdns/recursordist/rec-eventtrace.hh index 49bee212dc..e0451795c0 100644 --- a/pdns/recursordist/rec-eventtrace.hh +++ b/pdns/recursordist/rec-eventtrace.hh @@ -56,6 +56,8 @@ public: LuaNoData = 108, LuaNXDomain = 109, LuaPostResolveFFI = 110, + + AuthRequest = 120, }; static const std::unordered_map s_eventNames; @@ -128,17 +130,19 @@ public: struct Entry { - Entry(Value_t&& v, EventType e, bool start, int64_t ts) : - d_value(std::move(v)), d_ts(ts), d_event(e), d_start(start) + Entry(Value_t&& v, EventType e, bool start, int64_t ts, size_t parent, size_t match) : + d_value(std::move(v)), d_ts(ts), d_parent(parent), d_matching(match), d_event(e), d_start(start) { } - Entry(Value_t&& v, const std::string& custom, bool start, int64_t ts) : - d_value(std::move(v)), d_custom(custom), d_ts(ts), d_event(CustomEvent), d_start(start) + Entry(Value_t&& v, const std::string& custom, bool start, int64_t ts, size_t parent, size_t match) : + d_value(std::move(v)), d_custom(custom), d_ts(ts), d_parent(parent), d_matching(match), d_event(CustomEvent), d_start(start) { } Value_t d_value; std::string d_custom; int64_t d_ts; + size_t d_parent; + size_t d_matching; EventType d_event; bool d_start; @@ -169,12 +173,13 @@ public: } template - void add(E e, Value_t&& v, bool start, int64_t stamp = 0) + size_t add(E e, Value_t&& v, bool start, size_t match, int64_t stamp = 0) { assert(d_status != Invalid); if (d_status == Disabled) { - return; + return 0; } + if (stamp == 0) { struct timespec ts; clock_gettime(CLOCK_MONOTONIC, &ts); @@ -192,32 +197,33 @@ public: d_base = stamp; } stamp -= d_base; - d_events.emplace_back(std::move(v), e, start, stamp); + d_events.emplace_back(std::move(v), e, start, stamp, d_parent, match); + return d_events.size() - 1; } template - void add(E e) + size_t add(E e) { - add(e, Value_t(std::nullopt), true); + return add(e, Value_t(std::nullopt), true, 0, 0); } // We store uint32 in an int64_t template - void add(E e, uint32_t v, bool start) + size_t add(E e, uint32_t v, bool start, size_t match) { - add(e, static_cast(v), start); + return add(e, static_cast(v), start, match, 0); } // We store int32 in an int64_t template - void add(E e, int32_t v, bool start) + size_t add(E e, int32_t v, bool start, size_t match) { - add(e, static_cast(v), start); + return add(e, static_cast(v), start, match, 0); } template - void add(E e, T v, bool start) + size_t add(E e, T v, bool start, size_t match) { - add(e, Value_t(v), start); + return add(e, Value_t(v), start, match, 0); } void clear() @@ -262,9 +268,57 @@ public: std::vector convertToOT(const pdns::trace::Span& span) const; + size_t setParent(size_t parent) + { + size_t old = d_parent; + d_parent = parent; + return old; + } + + class EventScope + { + public: + EventScope(size_t oldParent, RecEventTrace& eventTrace) : + d_eventTrace(eventTrace), + d_oldParent(oldParent) + { + if (d_eventTrace.enabled()) { + d_event = d_eventTrace.d_events.back().d_event; + d_match = d_eventTrace.d_events.size() - 1; + } + } + + void close(int64_t val) + { + if (!d_eventTrace.enabled() || d_closed) { + return; + } + d_eventTrace.setParent(d_oldParent); + d_eventTrace.add(d_event, val, false, d_match); + d_closed = true; + } + + ~EventScope() + { + close(-1); + } + EventScope(const EventScope&) = delete; + EventScope(EventScope&&) = delete; + EventScope& operator=(const EventScope&) = delete; + EventScope& operator=(EventScope&&) = delete; + + private: + RecEventTrace& d_eventTrace; + size_t d_oldParent; + size_t d_match; + EventType d_event; + bool d_closed{false}; + }; + private: std::vector d_events; int64_t d_base; + size_t d_parent{0}; enum Status : uint8_t { Disabled, diff --git a/pdns/recursordist/rec-main.cc b/pdns/recursordist/rec-main.cc index 1f9cd1beea..1175550642 100644 --- a/pdns/recursordist/rec-main.cc +++ b/pdns/recursordist/rec-main.cc @@ -602,7 +602,7 @@ void protobufLogResponse(const struct dnsheader* header, LocalStateHolder& meta, const RecEventTrace& eventTrace, - pdns::trace::Span &otTrace, + pdns::trace::Span& otTrace, const std::unordered_set& policyTags) { pdns::ProtoZero::RecMessage pbMessage(pbData ? pbData->d_message : "", pbData ? pbData->d_response : "", 64, 10); // The extra bytes we are going to add @@ -665,9 +665,7 @@ void protobufLogResponse(const struct dnsheader* header, LocalStateHolder& comboWriter, s // eventTrace start of trace time. auto traceTS = pdns::trace::timestamp(); comboWriter->d_eventTrace.add(RecEventTrace::ReqRecv); - if ((SyncRes::s_event_trace_enabled & SyncRes::event_trace_to_ot) != 0) { + if (SyncRes::eventTraceEnabled(SyncRes::event_trace_to_ot)) { comboWriter->d_otTrace.clear(); comboWriter->d_otTrace.start_time_unix_nano = traceTS; comboWriter->d_otTrace.name = "RecRequest"; @@ -332,24 +332,24 @@ static void doProcessTCPQuestion(std::unique_ptr& comboWriter, s comboWriter->d_ecsFound = false; getQNameAndSubnet(conn->data, &qname, &qtype, &qclass, comboWriter->d_ecsFound, &comboWriter->d_ednssubnet, - (g_gettagNeedsEDNSOptions || (SyncRes::s_event_trace_enabled & SyncRes::event_trace_to_ot) != 0) ? &ednsOptions : nullptr, ednsVersion); + (g_gettagNeedsEDNSOptions || SyncRes::eventTraceEnabled(SyncRes::event_trace_to_ot)) ? &ednsOptions : nullptr, ednsVersion); qnameParsed = true; - if ((SyncRes::s_event_trace_enabled & SyncRes::event_trace_to_ot) != 0) { + if (SyncRes::eventTraceEnabled(SyncRes::event_trace_to_ot)) { pdns::trace::extractOTraceIDs(ednsOptions, comboWriter->d_otTrace); } if (t_pdl) { try { if (t_pdl->hasGettagFFIFunc()) { RecursorLua4::FFIParams params(qname, qtype, comboWriter->d_local, comboWriter->d_remote, comboWriter->d_destination, comboWriter->d_source, comboWriter->d_ednssubnet.getSource(), comboWriter->d_data, comboWriter->d_gettagPolicyTags, comboWriter->d_records, ednsOptions, comboWriter->d_proxyProtocolValues, requestorId, deviceId, deviceName, comboWriter->d_routingTag, comboWriter->d_rcode, comboWriter->d_ttlCap, comboWriter->d_variable, true, logQuery, comboWriter->d_logResponse, comboWriter->d_followCNAMERecords, comboWriter->d_extendedErrorCode, comboWriter->d_extendedErrorExtra, comboWriter->d_responsePaddingDisabled, comboWriter->d_meta); - comboWriter->d_eventTrace.add(RecEventTrace::LuaGetTagFFI); + auto match = comboWriter->d_eventTrace.add(RecEventTrace::LuaGetTagFFI); comboWriter->d_tag = t_pdl->gettag_ffi(params); - comboWriter->d_eventTrace.add(RecEventTrace::LuaGetTagFFI, comboWriter->d_tag, false); + comboWriter->d_eventTrace.add(RecEventTrace::LuaGetTagFFI, comboWriter->d_tag, false, match); } else if (t_pdl->hasGettagFunc()) { - comboWriter->d_eventTrace.add(RecEventTrace::LuaGetTag); + auto match = comboWriter->d_eventTrace.add(RecEventTrace::LuaGetTag); comboWriter->d_tag = t_pdl->gettag(comboWriter->d_source, comboWriter->d_ednssubnet.getSource(), comboWriter->d_destination, qname, qtype, &comboWriter->d_gettagPolicyTags, comboWriter->d_data, ednsOptions, true, requestorId, deviceId, deviceName, comboWriter->d_routingTag, comboWriter->d_proxyProtocolValues); - comboWriter->d_eventTrace.add(RecEventTrace::LuaGetTag, comboWriter->d_tag, false); + comboWriter->d_eventTrace.add(RecEventTrace::LuaGetTag, comboWriter->d_tag, false, match); } // Copy d_gettagPolicyTags to d_policyTags, so other Lua hooks see them and can add their // own. Before storing into the packetcache, the tags in d_gettagPolicyTags will be @@ -451,9 +451,9 @@ static void doProcessTCPQuestion(std::unique_ptr& comboWriter, s /* 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. */ - comboWriter->d_eventTrace.add(RecEventTrace::PCacheCheck); + auto match = comboWriter->d_eventTrace.add(RecEventTrace::PCacheCheck); bool cacheHit = checkForCacheHit(qnameParsed, comboWriter->d_tag, conn->data, qname, qtype, qclass, g_now, response, comboWriter->d_qhash, pbData, true, comboWriter->d_source, comboWriter->d_mappedSource); - comboWriter->d_eventTrace.add(RecEventTrace::PCacheCheck, cacheHit, false); + comboWriter->d_eventTrace.add(RecEventTrace::PCacheCheck, cacheHit, false, match); if (cacheHit) { if (!g_quiet) { @@ -477,7 +477,7 @@ static void doProcessTCPQuestion(std::unique_ptr& comboWriter, s protobufLogResponse(dnsheader, luaconfsLocal, pbData, tval, true, comboWriter->d_source, comboWriter->d_destination, comboWriter->d_mappedSource, comboWriter->d_ednssubnet, comboWriter->d_uuid, comboWriter->d_requestorId, comboWriter->d_deviceId, comboWriter->d_deviceName, comboWriter->d_meta, comboWriter->d_eventTrace, comboWriter->d_otTrace, comboWriter->d_policyTags); } - if (comboWriter->d_eventTrace.enabled() && (SyncRes::s_event_trace_enabled & SyncRes::event_trace_to_log) != 0) { + if (comboWriter->d_eventTrace.enabled() && SyncRes::eventTraceEnabled(SyncRes::event_trace_to_log)) { SLOG(g_log << Logger::Info << comboWriter->d_eventTrace.toString() << endl, g_slogtcpin->info(Logr::Info, comboWriter->d_eventTrace.toString())); // More fancy? } diff --git a/pdns/recursordist/syncres.cc b/pdns/recursordist/syncres.cc index 6d29075199..d90eff9736 100644 --- a/pdns/recursordist/syncres.cc +++ b/pdns/recursordist/syncres.cc @@ -764,7 +764,10 @@ bool SyncRes::addAdditionals(QType qtype, vector& ret, unsigned int d /** 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& ret, unsigned int depth) { - d_eventTrace.add(RecEventTrace::SyncRes); + auto newParent = d_eventTrace.add(RecEventTrace::SyncRes); + auto oldParent = d_eventTrace.setParent(newParent); + RecEventTrace::EventScope traceScope(oldParent, d_eventTrace); + d_wasVariable = false; d_wasOutOfBand = false; d_cutStates.clear(); @@ -819,7 +822,7 @@ int SyncRes::beginResolve(const DNSName& qname, const QType qtype, QClass qclass d_wasVariable = true; } } - d_eventTrace.add(RecEventTrace::SyncRes, res, false); + traceScope.close(res); return res; } @@ -5550,8 +5553,10 @@ bool SyncRes::doResolveAtThisIP(const std::string& prefix, const DNSName& qname, s_ecsqueries++; } updateQueryCounts(prefix, qname, remoteIP, doTCP, doDoT); + auto match = d_eventTrace.add(RecEventTrace::AuthRequest, qname.toLogString() + '/' + qtype.toString(), true, 0); resolveret = asyncresolveWrapper(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); } diff --git a/pdns/recursordist/syncres.hh b/pdns/recursordist/syncres.hh index 0e57a26ec6..a6bb0e471a 100644 --- a/pdns/recursordist/syncres.hh +++ b/pdns/recursordist/syncres.hh @@ -574,6 +574,10 @@ public: static bool s_save_parent_ns_set; static bool s_addExtendedResolutionDNSErrors; + static bool eventTraceEnabled(int flag) + { + return (s_event_trace_enabled & flag) != 0; + } std::unordered_map d_discardedPolicies; DNSFilterEngine::Policy d_appliedPolicy; std::unordered_set d_policyTags; diff --git a/pdns/sdig.cc b/pdns/sdig.cc index 92592fa508..319a9dce96 100644 --- a/pdns/sdig.cc +++ b/pdns/sdig.cc @@ -96,7 +96,6 @@ static void fillPacket(vector& packet, const string& q, const string& t } if (otids) { opts.emplace_back(EDNSOptionCode::OTTRACEID, std::string_view(reinterpret_cast(otids->first.data()), otids->first.size())); - pdns::trace::random(otids->second); opts.emplace_back(EDNSOptionCode::OTSPANID, std::string_view(reinterpret_cast(otids->second.data()), otids->second.size())); } pw.addOpt(bufsize, 0, dnssec ? EDNSOpts::DNSSECOK : 0, opts); @@ -374,7 +373,7 @@ try { traceIDStr.resize(traceid.size()); pdns::trace::fill(traceid, traceIDStr); } - pdns::trace::SpanID spanid{}; // don't fill in yet + pdns::trace::SpanID spanid{}; // default: all zero, so no parent otdata = std::make_pair(traceid, spanid); } else { -- 2.47.2