From: Otto Moerbeek <otto.moerbeek@open-xchange.com>
Date: Mon, 30 May 2022 14:57:26 +0000 (+0200)
Subject: Structured logging for dns64 and simliar functions using directResolve()
X-Git-Tag: auth-4.8.0-alpha0~70^2~1
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=759d43fb8f42c6f81556596fd2683adf3cc6c4bb;p=thirdparty%2Fpdns.git

Structured logging for dns64 and simliar functions using directResolve()
---

diff --git a/pdns/pdns_recursor.cc b/pdns/pdns_recursor.cc
index e888a88da9..9f15a4494d 100644
--- a/pdns/pdns_recursor.cc
+++ b/pdns/pdns_recursor.cc
@@ -587,7 +587,7 @@ static void sendNODLookup(Logr::log_t nodlogger, const DNSName& dname)
     }
     nodlogger->v(10)->info(Logr::Debug, "Sending NOD lookup", "nodqname", Logging::Loggable(qname));
     vector<DNSRecord> dummy;
-    directResolve(qname, QType::A, QClass::IN, dummy, nullptr, false);
+    directResolve(qname, QType::A, QClass::IN, dummy, nullptr, false, nodlogger);
   }
 }
 
@@ -635,7 +635,8 @@ int followCNAMERecords(vector<DNSRecord>& ret, const QType qtype, int rcode)
     return rcode;
   }
 
-  rcode = directResolve(target, qtype, QClass::IN, resolved, t_pdl);
+  auto log = g_slog->withName("lua")->withValues("method", Logging::Loggable("followCNAMERecords"));
+  rcode = directResolve(target, qtype, QClass::IN, resolved, t_pdl, log);
 
   if (g_dns64Prefix && qtype == QType::AAAA && answerIsNOData(qtype, rcode, resolved)) {
     rcode = getFakeAAAARecords(target, *g_dns64Prefix, resolved);
@@ -651,11 +652,12 @@ int followCNAMERecords(vector<DNSRecord>& ret, const QType qtype, int rcode)
 
 int getFakeAAAARecords(const DNSName& qname, ComboAddress prefix, vector<DNSRecord>& ret)
 {
+  auto log = g_slog->withName("dns64")->withValues("method", Logging::Loggable("getAAAA"));
   /* we pass a separate vector of records because we will be resolving the initial qname
      again, possibly encountering the same CNAME(s), and we don't want to trigger the CNAME
      loop detection. */
   vector<DNSRecord> newRecords;
-  int rcode = directResolve(qname, QType::A, QClass::IN, newRecords, t_pdl);
+  int rcode = directResolve(qname, QType::A, QClass::IN, newRecords, t_pdl, log);
 
   ret.reserve(ret.size() + newRecords.size());
   for (auto& record : newRecords) {
@@ -735,7 +737,8 @@ int getFakePTRRecords(const DNSName& qname, vector<DNSRecord>& ret)
   rr.d_content = std::make_shared<CNAMERecordContent>(newquery);
   ret.push_back(rr);
 
-  int rcode = directResolve(DNSName(newquery), QType::PTR, QClass::IN, ret, t_pdl);
+  auto log = g_slog->withName("dns64")->withValues("method", Logging::Loggable("getPTR"));
+  int rcode = directResolve(DNSName(newquery), QType::PTR, QClass::IN, ret, t_pdl, log);
 
   g_stats.dns64prefixanswers++;
   return rcode;
diff --git a/pdns/syncres.cc b/pdns/syncres.cc
index 6a0c26b182..19528bd5aa 100644
--- a/pdns/syncres.cc
+++ b/pdns/syncres.cc
@@ -5626,13 +5626,15 @@ void SyncRes::parseEDNSSubnetAddFor(const std::string& subnetlist)
 }
 
 // used by PowerDNSLua - note that this neglects to add the packet count & statistics back to pdns_recursor.cc
-int directResolve(const DNSName& qname, const QType qtype, const QClass qclass, vector<DNSRecord>& ret, shared_ptr<RecursorLua4> pdl)
+int directResolve(const DNSName& qname, const QType qtype, const QClass qclass, vector<DNSRecord>& ret, shared_ptr<RecursorLua4> pdl, Logr::log_t log)
 {
-  return directResolve(qname, qtype, qclass, ret, pdl, SyncRes::s_qnameminimization);
+  return directResolve(qname, qtype, qclass, ret, pdl, SyncRes::s_qnameminimization, log);
 }
 
-int directResolve(const DNSName& qname, const QType qtype, const QClass qclass, vector<DNSRecord>& ret, shared_ptr<RecursorLua4> pdl, bool qm)
+int directResolve(const DNSName& qname, const QType qtype, const QClass qclass, vector<DNSRecord>& ret, shared_ptr<RecursorLua4> pdl, bool qm, Logr::log_t slog)
 {
+  auto log = slog->withValues("qname", Logging::Loggable(qname), "qtype", Logging::Loggable(qtype));
+
   struct timeval now;
   gettimeofday(&now, 0);
 
@@ -5643,27 +5645,33 @@ int directResolve(const DNSName& qname, const QType qtype, const QClass qclass,
   }
 
   int res = -1;
+  const std::string msg = "Failed to resolve";
   try {
     res = sr.beginResolve(qname, qtype, qclass, ret, 0);
   }
   catch(const PDNSException& e) {
-    g_log<<Logger::Error<<"Failed to resolve "<<qname<<", got pdns exception: "<<e.reason<<endl;
+    SLOG(g_log<<Logger::Error<<"Failed to resolve "<<qname<<", got pdns exception: "<<e.reason<<endl,
+         log->error(Logr::Error, e.reason, msg, "exception", Logging::Loggable("PDNSException")));
     ret.clear();
   }
   catch(const ImmediateServFailException& e) {
-    g_log<<Logger::Error<<"Failed to resolve "<<qname<<", got ImmediateServFailException: "<<e.reason<<endl;
+    SLOG(g_log<<Logger::Error<<"Failed to resolve "<<qname<<", got ImmediateServFailException: "<<e.reason<<endl,
+         log->error(Logr::Error, e.reason, msg, "exception", Logging::Loggable("ImmediateServFailException")));
     ret.clear();
   }
   catch(const PolicyHitException& e) {
-    g_log<<Logger::Error<<"Failed to resolve "<<qname<<", got a policy hit"<<endl;
+    SLOG(g_log<<Logger::Error<<"Failed to resolve "<<qname<<", got a policy hit"<<endl,
+         log->error(Logr::Error, "Policy Hit", msg, "exception", Logging::Loggable("PolicyHitException")));
     ret.clear();
   }
   catch(const std::exception& e) {
-    g_log<<Logger::Error<<"Failed to resolve "<<qname<<", got STL error: "<<e.what()<<endl;
+    SLOG(g_log<<Logger::Error<<"Failed to resolve "<<qname<<", got STL error: "<<e.what()<<endl,
+         log->error(Logr::Error, e.what(), msg, "exception", Logging::Loggable("std::exception")));
     ret.clear();
   }
   catch(...) {
-    g_log<<Logger::Error<<"Failed to resolve "<<qname<<", got an exception"<<endl;
+    SLOG(g_log<<Logger::Error<<"Failed to resolve "<<qname<<", got an exception"<<endl,
+         log->error(Logr::Error, "Exception", msg));
     ret.clear();
   }
 
diff --git a/pdns/syncres.hh b/pdns/syncres.hh
index 4ec3e51906..58759b8864 100644
--- a/pdns/syncres.hh
+++ b/pdns/syncres.hh
@@ -909,8 +909,8 @@ typedef std::function<void*(void)> pipefunc_t;
 void broadcastFunction(const pipefunc_t& func);
 void distributeAsyncFunction(const std::string& question, const pipefunc_t& func);
 
-int directResolve(const DNSName& qname, const QType qtype, const QClass qclass, vector<DNSRecord>& ret, shared_ptr<RecursorLua4> pdl);
-int directResolve(const DNSName& qname, const QType qtype, const QClass qclass, vector<DNSRecord>& ret, shared_ptr<RecursorLua4> pdl, bool qm);
+int directResolve(const DNSName& qname, const QType qtype, const QClass qclass, vector<DNSRecord>& ret, shared_ptr<RecursorLua4> pdl, Logr::log_t);
+int directResolve(const DNSName& qname, const QType qtype, const QClass qclass, vector<DNSRecord>& ret, shared_ptr<RecursorLua4> pdl, bool qm, Logr::log_t);
 int followCNAMERecords(std::vector<DNSRecord>& ret, const QType qtype, int oldret);
 int getFakeAAAARecords(const DNSName& qname, ComboAddress prefix, vector<DNSRecord>& ret);
 int getFakePTRRecords(const DNSName& qname, vector<DNSRecord>& ret);