Merge pull request PowerDNS#17358 from miodvallat/verboseview

auth: some views traces

Author: Habbie

modules/remotebackend/test-remotebackend.cc

@@ -45,6 +45,7 @@
 #include "test-remotebackend-keys.hh"
 
 bool g_slogStructured{false};
+bool g_logDNSQueries{false};
 
 extern std::unique_ptr<DNSBackend> backendUnderTest;
 

pdns/auth-main.cc

@@ -105,6 +105,7 @@ const char* funnytext = "*******************************************************
 
 bool g_anyToTcp;
 bool g_8bitDNS;
+bool g_logDNSQueries;
 #ifdef HAVE_LUA_RECORDS
 bool g_doLuaRecord;
 int g_luaRecordExecLimit;
@@ -568,6 +569,7 @@ static void sendout(std::unique_ptr<DNSPacket>& a, Logr::log_t slog, int start)
 }
 
 //! The qthread receives questions over the internet via the Nameserver class, and hands them to the Distributor for further processing
+// NOLINTNEXTLINE(readability-function-cognitive-complexity)
 static void qthread(unsigned int num)
 {
   std::shared_ptr<Logr::Logger> slog;
@@ -594,7 +596,6 @@ static void qthread(unsigned int num)
 
     int diff{};
     int start{};
-    bool logDNSQueries = ::arg().mustDo("log-dns-queries");
     shared_ptr<UDPNameserver> NS; // NOLINT(readability-identifier-length)
     std::string buffer;
     ComboAddress accountremote;
@@ -652,7 +653,7 @@ static void qthread(unsigned int num)
 
         S.ringAccount("queries", question.qdomain, question.qtype);
         S.ringAccount("remotes", question.getInnerRemote());
-        if (logDNSQueries) {
+        if (g_logDNSQueries) {
           if (g_slogStructured) {
             if (question.d_ednsRawPacketSizeLimit > 0 && question.getMaxReplyLen() != (unsigned int)question.d_ednsRawPacketSizeLimit) {
               slog->info(Logr::Notice, "Query received", "remote", Logging::Loggable(question.getRemoteString()), "query", Logging::Loggable(question.qdomain), "type", Logging::Loggable(question.qtype), "dnssec", Logging::Loggable(question.d_dnssecOk), "max reply length", Logging::Loggable(question.getMaxReplyLen()), "raw packet size limit", Logging::Loggable(question.d_ednsRawPacketSizeLimit));
@@ -669,17 +670,22 @@ static void qthread(unsigned int num)
           }
         }
 
+        bool logAtNewline{false};
         if (PC.enabled() && (question.d.opcode != Opcode::Notify && question.d.opcode != Opcode::Update) && question.couldBeCached()) {
           start = diff;
           std::string view{};
           if (g_views) {
+            if (!g_slogStructured) {
+              g_log << endl;
+              logAtNewline = true; // because of getViewFromNetwork below
+            }
             Netmask netmask(accountremote);
             view = g_zoneCache.getViewFromNetwork(&netmask);
           }
           bool haveSomething = PC.get(question, cached, view); // does the PacketCache recognize this question?
           if (haveSomething) {
-            if (logDNSQueries) {
-              SLOG(g_log << ": packetcache HIT" << endl,
+            if (g_logDNSQueries) {
+              SLOG(g_log << (logAtNewline ? "" : ": ") << "packetcache HIT" << endl,
                    slog->info(Logr::Notice, "packetcache HIT"));
             }
             cached.setRemote(&question.d_remote); // inlined
@@ -706,17 +712,17 @@ static void qthread(unsigned int num)
         }
 
         if (distributor->isOverloaded()) {
-          if (logDNSQueries) {
-            SLOG(g_log << ": Dropped query, backends are overloaded" << endl,
+          if (g_logDNSQueries) {
+            SLOG(g_log << (logAtNewline ? "" : ": ") << "Dropped query, backends are overloaded" << endl,
                  slog->info(Logr::Notice, "Dropped query, backends are overloaded"));
           }
           overloadDrops++;
           continue;
         }
 
-        if (logDNSQueries) {
+        if (g_logDNSQueries) {
           if (PC.enabled()) {
-            SLOG(g_log << ": packetcache MISS" << endl,
+            SLOG(g_log << (logAtNewline ? "" : ": ") << "packetcache MISS" << endl,
                  slog->info(Logr::Notice, "packetcache MISS"));
           }
           else {
@@ -772,6 +778,7 @@ static void mainthread()
 
   g_anyToTcp = ::arg().mustDo("any-to-tcp");
   g_8bitDNS = ::arg().mustDo("8bit-dns");
+  g_logDNSQueries = ::arg().mustDo("log-dns-queries");
 #ifdef HAVE_LUA_RECORDS
   g_doLuaRecord = ::arg().mustDo("enable-lua-records");
   g_LuaRecordSharedState = (::arg()["enable-lua-records"] == "shared");
@@ -968,6 +975,7 @@ static void mainthread()
   UeberBackend::go();
 
   // Setup the zone cache
+  g_zoneCache.setSLog(slog);
   g_zoneCache.setRefreshInterval(::arg().asNum("zone-cache-refresh-interval"));
   try {
     UeberBackend B;

pdns/auth-main.hh

@@ -46,6 +46,7 @@ extern CommunicatorClass Communicator;
 void carbonDumpThread(Logr::log_t slog); // Implemented in auth-carbon.cc. Avoids having an auth-carbon.hh declaring exactly one function.
 extern bool g_anyToTcp;
 extern bool g_8bitDNS;
+extern bool g_logDNSQueries;
 extern NetmaskGroup g_proxyProtocolACL;
 extern size_t g_proxyProtocolMaximumSize;
 #ifdef HAVE_LUA_RECORDS

pdns/auth-zonecache.cc

@@ -29,6 +29,8 @@
 #include "statbag.hh"
 #include "arguments.hh"
 #include "cachecleaner.hh"
+#include "auth-main.hh"
+
 extern StatBag S;
 
 AuthZoneCache::AuthZoneCache(size_t mapsCount) :
@@ -71,6 +73,10 @@ std::string AuthZoneCache::getViewFromNetwork(Netmask* net)
   string view{};
 
   if (net == nullptr || net->empty()) {
+    if (g_logDNSQueries) {
+      SLOG(g_log << Logger::Notice << "missing or empty netmask, unable to pick a view" << endl,
+           d_log->info(Logr::Notice, "Missing or empty netmask, unable to pick a view"));
+    }
     return view;
   }
 
@@ -82,12 +88,21 @@ std::string AuthZoneCache::getViewFromNetwork(Netmask* net)
       *net = netview->first;
       // ...and which view it covers.
       view = netview->second;
+      if (g_logDNSQueries) {
+        SLOG(g_log << Logger::Notice << "netmask " << net->toString() << " matches view '" << view << "'" << endl,
+             d_log->info(Logr::Notice, "matching view", "netmask", Logging::Loggable(net), "view", Logging::Loggable(view)));
+      }
+      return view;
     }
   }
   catch (...) {
     // this handles the "empty" case, but might hide other errors
   }
 
+  if (g_logDNSQueries) {
+    SLOG(g_log << Logger::Notice << "no view found matching netmask " << net->toString() << endl,
+         d_log->info(Logr::Notice, "no view found", "netmask", Logging::Loggable(net)));
+  }
   return view;
 }
 

pdns/auth-zonecache.hh

@@ -78,6 +78,11 @@ public:
 
   void clear();
 
+  void setSLog(Logr::log_t log)
+  {
+    d_log = log;
+  }
+
 private:
   SharedLockGuarded<NetmaskTree<string>> d_nets;
   SharedLockGuarded<ViewsMap> d_views;
@@ -121,6 +126,8 @@ private:
     bool d_replacePending{false};
   };
   LockGuarded<PendingData> d_pending;
+
+  std::shared_ptr<Logr::Logger> d_log;
 };
 
 extern AuthZoneCache g_zoneCache;

pdns/ixfrdist.cc

@@ -70,6 +70,7 @@ AuthPacketCache PC;
 // NOLINTNEXTLINE(readability-identifier-length)
 AuthQueryCache QC;
 AuthZoneCache g_zoneCache;
+bool g_logDNSQueries{false};
 
 ArgvMap &arg()
 {

pdns/pdnsutil.cc

@@ -63,6 +63,7 @@ namespace po = boost::program_options;
 po::variables_map g_vm;
 
 bool g_slogStructured{false};
+bool g_logDNSQueries{false};
 static Logger::Urgency s_logUrgency;
 
 string g_programname="pdns";

pdns/tcpreceiver.cc

@@ -264,7 +264,6 @@ void TCPNameserver::doConnection(int fd, Logr::log_t slog)
 
     DLOG(SLOG(g_log<<"TCP Connection accepted on fd "<<fd<<endl,
               slog->info(Logr::Debug, "TCP Connection accepted", "fd", Logging::Loggable(fd))));
-    bool logDNSQueries= ::arg().mustDo("log-dns-queries");
     if (g_proxyProtocolACL.match(remote)) {
       unsigned int remainingTime = 0;
       PacketBuffer proxyData;
@@ -398,7 +397,7 @@ void TCPNameserver::doConnection(int fd, Logr::log_t slog)
       std::unique_ptr<DNSPacket> reply;
       auto cached = make_unique<DNSPacket>(slog, false);
       std::shared_ptr<Logr::Logger> slogger;
-      if(logDNSQueries)  {
+      if(g_logDNSQueries)  {
         if (g_slogStructured) {
           slogger = slog->withValues("remote", Logging::Loggable(packet->getRemoteString()), "query", Logging::Loggable(packet->qdomain), "type", Logging::Loggable(packet->qtype), "dnssecok", Logging::Loggable(packet->d_dnssecOk), "bufsize", Logging::Loggable(packet->getMaxReplyLen()));
 	}
@@ -408,16 +407,21 @@ void TCPNameserver::doConnection(int fd, Logr::log_t slog)
         }
       }
 
+      bool logAtNewline{false};
       if (PC.enabled()) {
         if (packet->couldBeCached()) {
           std::string view{};
           if (g_views) {
+            if (!g_slogStructured) {
+              g_log << endl;
+              logAtNewline = true; // because of getViewFromNetwork below
+            }
             Netmask netmask(packet->getInnerRemote());
             view = g_zoneCache.getViewFromNetwork(&netmask);
           }
           if (PC.get(*packet, *cached, view)) { // short circuit - does the PacketCache recognize this question?
-            if(logDNSQueries) {
-              SLOG(g_log<<": packetcache HIT"<<endl,
+            if(g_logDNSQueries) {
+              SLOG(g_log << (logAtNewline ? "" : ": ") << "packetcache HIT"<<endl,
                    slogger->info(Logr::Notice, "Received TCP query", "packetcache", Logging::Loggable("hit")));
             }
             cached->setRemote(&packet->d_remote);
@@ -430,12 +434,12 @@ void TCPNameserver::doConnection(int fd, Logr::log_t slog)
             continue;
           }
         }
-        if(logDNSQueries) {
-          SLOG(g_log<<": packetcache MISS"<<endl,
+        if(g_logDNSQueries) {
+          SLOG(g_log<< (logAtNewline ? "" : ": ") << "packetcache MISS"<<endl,
                slogger->info(Logr::Notice, "Received TCP query", "packetcache", Logging::Loggable("miss")));
         }
       } else {
-        if (logDNSQueries) {
+        if (g_logDNSQueries) {
           SLOG(g_log<<endl,
                slogger->info(Logr::Notice, "Received TCP query"));
         }

pdns/testrunner.cc

@@ -19,6 +19,7 @@ AuthQueryCache QC;
 AuthZoneCache g_zoneCache;
 uint16_t g_maxNSEC3Iterations{0};
 bool g_slogStructured{false};
+bool g_logDNSQueries{false};
 
 ArgvMap& arg()
 {