From: Otto <otto.moerbeek@open-xchange.com>
Date: Mon, 17 May 2021 09:29:08 +0000 (+0200)
Subject: Introduce "Priority", which maps to the Urgency of the existing
X-Git-Tag: dnsdist-1.7.0-alpha1~122^2~2
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=49f30160855e3bc569fb073c2563e4c061dd90bc;p=thirdparty%2Fpdns.git

Introduce "Priority", which maps to the Urgency of the existing
logger.

If Priority is set, pass the Entry to the backend for now.
(to be revisited).

In the rpzloader example, pass a logger object to functions,
so that they can add their data to an existing logger, showing
how a structured log object could be used.
---

diff --git a/pdns/pdns_recursor.cc b/pdns/pdns_recursor.cc
index b64d416cfb..3caf539bf2 100644
--- a/pdns/pdns_recursor.cc
+++ b/pdns/pdns_recursor.cc
@@ -5419,13 +5419,18 @@ static void loggerBackend(const Logging::Entry& entry) {
   if (entry.name) {
     buf << " subsystem=" << std::quoted(entry.name.get());
   }
+  buf << " level=" << entry.level;
+  if (entry.d_priority) {
+    buf << " prio=" << static_cast<int>(entry.d_priority);
+  }
   char timebuf[64];
   buf << " ts=" << std::quoted(toTimestampStringMilli(entry.d_timestamp, timebuf, sizeof(timebuf)));
   for (auto const& v: entry.values) {
     buf << " ";
     buf << v.first << "=" << std::quoted(v.second);
   }
-  g_log << Logger::Urgency(entry.level) << buf.str() << endl;
+  Logger::Urgency u = entry.d_priority ? Logger::Urgency(entry.d_priority) : Logger::Info;
+  g_log << u << buf.str() << endl;
 }
 
 
diff --git a/pdns/recursordist/logging.cc b/pdns/recursordist/logging.cc
index f9b5c58e5a..60c363357e 100644
--- a/pdns/recursordist/logging.cc
+++ b/pdns/recursordist/logging.cc
@@ -32,23 +32,34 @@ namespace Logging
     return shared_from_this();
   }
 
-  bool Logger::enabled() const
+  bool Logger::enabled(Logr::Priority p) const
   {
-    return _level <= _verbosity;
+    return _level <= _verbosity || p != Logr::Absent;
   }
 
   void Logger::info(const std::string& msg) const
   {
-    logMessage(msg, boost::none);
+    logMessage(msg, Logr::Absent, boost::none);
+  }
+
+  void Logger::info(Logr::Priority p, const std::string& msg) const
+  {
+    logMessage(msg, p, boost::none);
   }
 
   void Logger::logMessage(const std::string& msg, boost::optional<const std::string> err) const
   {
-    if (!enabled()) {
+    return logMessage(msg, Logr::Absent, err);
+  }
+
+  void Logger::logMessage(const std::string& msg, Logr::Priority p, boost::optional<const std::string> err) const
+  {
+    if (!enabled(p)) {
       return ;
     }
     Entry entry;
     entry.level = _level;
+    entry.d_priority = p;
     Utility::gettimeofday(&entry.d_timestamp);
     entry.name = _name;
     entry.message = msg;
@@ -62,14 +73,24 @@ namespace Logging
     _callback(entry);
   }
 
+  void Logger::error(Logr::Priority p, int err, const std::string& msg) const
+  {
+    logMessage(msg, p, std::string(std::strerror(err)));
+  }
+
+  void Logger::error(Logr::Priority p, const std::string& err, const std::string& msg) const
+  {
+    logMessage(msg, p, err);
+  }
+
   void Logger::error(int err, const std::string& msg) const
   {
-    logMessage(msg, std::string(std::strerror(err)));
+    logMessage(msg, Logr::Absent, std::string(std::strerror(err)));
   }
 
   void Logger::error(const std::string& err, const std::string& msg) const
   {
-    logMessage(msg, err);
+    logMessage(msg, Logr::Absent, err);
   }
 
   std::shared_ptr<Logr::Logger> Logger::v(size_t level) const
@@ -88,6 +109,7 @@ namespace Logging
   template struct Loggable<DNSName>;
   template struct Loggable<ComboAddress>;
   template struct Loggable<std::string>;
+  template struct Loggable<size_t>;
 
   template <>
   std::string Loggable<DNSName>::to_string() const {
diff --git a/pdns/recursordist/logging.hh b/pdns/recursordist/logging.hh
index 3235a54957..25127fb897 100644
--- a/pdns/recursordist/logging.hh
+++ b/pdns/recursordist/logging.hh
@@ -36,12 +36,13 @@ namespace Logging {
 
   struct Entry
   {
-    size_t level;                    // level at which this was logged
     boost::optional<std::string> name;   // name parts joined with '.'
     std::string message;                 // message as send to log call
     boost::optional<std::string> error;  // error if .Error() was called
-    struct timeval d_timestamp;
-    std::map<std::string, std::string> values;
+    struct timeval d_timestamp;          // time of entry generation
+    std::map<std::string, std::string> values; // key-value pairs
+    size_t level;               // level at which this was logged
+    Logr::Priority d_priority;  // (syslog) priority)
   };
 
   template <typename T>
@@ -62,19 +63,22 @@ namespace Logging {
   std::string Loggable<ComboAddress>::to_string() const;
   template <>
   std::string Loggable<std::string>::to_string() const;
-//  template <>
-//  Loggable<std::string>::Loggable(const std::string& v): _t(v) {}
+
+  // Loggable<std::string>::Loggable(const std::string& v): _t(v) {}
 
   typedef void(*EntryLogger)(const Entry&);
 
   class Logger: public Logr::Logger, public std::enable_shared_from_this<const Logger>
   {
   public:
-    bool enabled() const override;
+    bool enabled(Logr::Priority) const override;
 
     void info(const std::string& msg) const override;
+    void info(Logr::Priority, const std::string& msg) const override;
     void error(int err, const std::string& msg) const override;
     void error(const std::string& err, const std::string& msg) const override;
+    void error(Logr::Priority, int err, const std::string& msg) const override;
+    void error(Logr::Priority, const std::string& err, const std::string& msg) const override;
 
     std::shared_ptr<Logr::Logger> v(size_t level) const override;
     std::shared_ptr<Logr::Logger> withValues(const std::map<std::string, std::string>& values) const override;
@@ -92,6 +96,7 @@ namespace Logging {
     void setVerbosity(size_t verbosity);
   private:
     void logMessage(const std::string& msg, boost::optional<const std::string> err) const;
+    void logMessage(const std::string& msg, Logr::Priority p, boost::optional<const std::string> err) const;
     std::shared_ptr<const Logger> getptr() const;
 
     std::shared_ptr<const Logger> _parent{nullptr};
diff --git a/pdns/recursordist/logr.hh b/pdns/recursordist/logr.hh
index c271a36e63..1583dc9c74 100644
--- a/pdns/recursordist/logr.hh
+++ b/pdns/recursordist/logr.hh
@@ -32,12 +32,25 @@ namespace Logr {
     virtual std::string to_string() const = 0;
   };
 
+  // In addition to level which specifies the amount of detail and is
+  // structered so that a derived logger always has a higher level
+  // than its parent we also have a priority/urgency field that maps
+  // to the same field of the old logger which in turns has a direct
+  // mapping to syslog priority. This is done to make it easier to
+  // move step by step to structured logging. We consider both level
+  // and priorty to select which messages are logged, amnd a backend
+  // can further use priority to pass to syslog.
+
+  enum Priority: uint8_t {
+    Absent = 0, Alert = 1, Critical = 2, Error = 3, Warning = 4, Notice = 5, Info = 6, Debug = 7
+  };
+
   class Logger {
   public:
     // Enabled tests whether this Logger is enabled.  For example, commandline
     // flags might be used to set the logging verbosity and disable some info
     // logs.
-    virtual bool enabled() const = 0;
+    virtual bool enabled(Priority) const = 0;
 
     // Info logs a non-error message with the given key/value pairs as context.
     //
@@ -46,6 +59,7 @@ namespace Logr {
     // variable information.  The key/value pairs should alternate string
     // keys and arbitrary values.
     virtual void info(const std::string& msg) const = 0;
+    virtual void info(Logr::Priority, const std::string& msg) const = 0;
 
     template<typename... Args>
     void info(const std::string& msg, const std::string& key, const Loggable& value, const Args&... args) const
@@ -54,6 +68,13 @@ namespace Logr {
       logger->info(msg);
     }
 
+    template<typename... Args>
+    void info(Priority p, const std::string& msg, const std::string& key, const Loggable& value, const Args&... args) const
+    {
+      auto logger = this->withValues(key, value, args...);
+      logger->info(p, msg);
+    }
+
     // Error logs an error, with the given message and key/value pairs as context.
     // It functions similarly to calling Info with the "error" named value, but may
     // have unique behavior, and should be preferred for logging errors (see the
@@ -64,19 +85,35 @@ namespace Logr {
     // triggered this log line, if present.
     virtual void error(const std::string& err, const std::string& msg) const = 0;
     virtual void error(int err, const std::string& msg) const = 0;
+    virtual void error(Logr::Priority, const std::string& err, const std::string& msg) const = 0;
+    virtual void error(Logr::Priority, int err, const std::string& msg) const = 0;
 
     template<typename... Args>
     void error(const std::string& err, const std::string& msg, const std::string& key, const Loggable& value, const Args&... args) const
     {
       auto logger = this->withValues(key, value, args...);
-      logger->error(err, msg);
+      logger->error(Logr::Absent, err, msg);
     }
 
     template<typename... Args>
     void error(int err, const std::string& msg, const std::string& key, const Loggable& value, const Args&... args) const
     {
       auto logger = this->withValues(key, value, args...);
-      logger->error(err, msg);
+      logger->error(Logr::Absent, err, msg);
+    }
+
+    template<typename... Args>
+    void error(Priority p, const std::string& err, const std::string& msg, const std::string& key, const Loggable& value, const Args&... args) const
+    {
+      auto logger = this->withValues(key, value, args...);
+      logger->error(p, err, msg);
+    }
+
+    template<typename... Args>
+    void error(Priority p, int err, const std::string& msg, const std::string& key, const Loggable& value, const Args&... args) const
+    {
+      auto logger = this->withValues(key, value, args...);
+      logger->error(p, err, msg);
     }
 
     // V returns an Logger value for a specific verbosity level, relative to
diff --git a/pdns/rpzloader.cc b/pdns/rpzloader.cc
index b06cf54adb..22b63ef3fa 100644
--- a/pdns/rpzloader.cc
+++ b/pdns/rpzloader.cc
@@ -187,13 +187,14 @@ static void RPZRecordToPolicy(const DNSRecord& dr, std::shared_ptr<DNSFilterEngi
   }
 }
 
-static shared_ptr<SOARecordContent> loadRPZFromServer(const ComboAddress& primary, const DNSName& zoneName, std::shared_ptr<DNSFilterEngine::Zone> zone, boost::optional<DNSFilterEngine::Policy> defpol, bool defpolOverrideLocal, uint32_t maxTTL, const TSIGTriplet& tt, size_t maxReceivedBytes, const ComboAddress& localAddress, uint16_t axfrTimeout)
+static shared_ptr<SOARecordContent> loadRPZFromServer(const shared_ptr<Logr::Logger>& plogger, const ComboAddress& primary, const DNSName& zoneName, std::shared_ptr<DNSFilterEngine::Zone> zone, boost::optional<DNSFilterEngine::Policy> defpol, bool defpolOverrideLocal, uint32_t maxTTL, const TSIGTriplet& tt, size_t maxReceivedBytes, const ComboAddress& localAddress, uint16_t axfrTimeout)
 {
 
-  auto logger = g_slog->withName("rpz")->withValues("zone", Logging::Loggable(zoneName), "primary", Logging::Loggable(primary));
-  logger->info("Loading RPZ from nameserver");
+  auto logger = plogger->withValues("primary", Logging::Loggable(primary));
+  logger->info(Logr::Info, "Loading RPZ from nameserver");
+  logger = logger->v(1);
   if(!tt.name.empty()) {
-    logger->info("Using TSIG key for authentication", "tsig_key_name", Logging::Loggable(tt.name), "tsig_key_algorithm", Logging::Loggable(tt.algo));
+    logger->info(Logr::Info, "Using TSIG key for authentication", "tsig_key_name", Logging::Loggable(tt.name), "tsig_key_algorithm", Logging::Loggable(tt.algo));
   }
 
   ComboAddress local(localAddress);
@@ -228,11 +229,11 @@ static shared_ptr<SOARecordContent> loadRPZFromServer(const ComboAddress& primar
       throw PDNSException("Total AXFR time exceeded!");
     }
     if(last != time(0)) {
-      logger->info("RPZ load in progress", "nrecords", Logging::Loggable(nrecords));
+      logger->info(Logr::Info, "RPZ load in progress", "nrecords", Logging::Loggable(nrecords));
       last=time(0);
     }
   }
-  logger->info("RPZ load completed", "nrecords", Logging::Loggable(nrecords), "soa", Logging::Loggable(sr->getZoneRepresentation()));
+  logger->info(Logr::Info, "RPZ load completed", "nrecords", Logging::Loggable(nrecords), "soa", Logging::Loggable(sr->getZoneRepresentation()));
   return sr;
 }
 
@@ -306,14 +307,14 @@ static void setRPZZoneNewState(const std::string& zone, uint32_t serial, uint64_
   stats->d_numberOfRecords = numberOfRecords;
 }
 
-static bool dumpZoneToDisk(const DNSName& zoneName, const std::shared_ptr<DNSFilterEngine::Zone>& newZone, const std::string& dumpZoneFileName)
+static bool dumpZoneToDisk(const shared_ptr<Logr::Logger>& plogger, const DNSName& zoneName, const std::shared_ptr<DNSFilterEngine::Zone>& newZone, const std::string& dumpZoneFileName)
 {
-  auto logger = g_slog->withName("rpz")->withValues("zone", Logging::Loggable(zoneName));
-  logger->v(1)->info("Dumping zone to disk", "destination_file", Logging::Loggable(dumpZoneFileName));
+  auto logger = plogger->v(1);
+  logger->info("Dumping zone to disk", "destination_file", Logging::Loggable(dumpZoneFileName));
   std::string temp = dumpZoneFileName + "XXXXXX";
   int fd = mkstemp(&temp.at(0));
   if (fd < 0) {
-    logger->error(errno, "Unable to create temporary file");
+    logger->error(Logr::Warning, errno, "Unable to create temporary file");
     return false;
   }
 
@@ -321,7 +322,7 @@ static bool dumpZoneToDisk(const DNSName& zoneName, const std::shared_ptr<DNSFil
   if (!fp) {
     int err = errno;
     close(fd);
-    logger->error(err, "Unable to open file pointer");
+    logger->error(Logr::Warning, err, "Unable to open file pointer");
     return false;
   }
   fd = -1;
@@ -330,28 +331,27 @@ static bool dumpZoneToDisk(const DNSName& zoneName, const std::shared_ptr<DNSFil
     newZone->dump(fp.get());
   }
   catch(const std::exception& e) {
-    logger->error(e.what(), "Error while dumping the content of the RPZ");
+    logger->error(Logr::Warning, e.what(), "Error while dumping the content of the RPZ");
     return false;
   }
 
   if (fflush(fp.get()) != 0) {
-    logger->error(errno, "Error while flushing the content of the RPZ");
+    logger->error(Logr::Warning, errno, "Error while flushing the content of the RPZ");
     return false;
   }
 
   if (fsync(fileno(fp.get())) != 0) {
-    logger->error(errno, "Error while syncing the content of the RPZ");
+    logger->error(Logr::Warning, errno, "Error while syncing the content of the RPZ");
     return false;
   }
 
   if (fclose(fp.release()) != 0) {
-    logger->error(errno, "Error while writing the content of the RPZ");
+    logger->error(Logr::Warning, errno, "Error while writing the content of the RPZ");
     return false;
   }
 
   if (rename(temp.c_str(), dumpZoneFileName.c_str()) != 0) {
-    logger
-      ->error(errno, "Error while moving the content of the RPZ", "destination_file", Logging::Loggable(dumpZoneFileName));
+    logger->error(Logr::Warning, errno, "Error while moving the content of the RPZ", "destination_file", Logging::Loggable(dumpZoneFileName));
     return false;
   }
 
@@ -364,10 +364,12 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, boost::optional<
   bool isPreloaded = sr != nullptr;
   auto luaconfsLocal = g_luaconfs.getLocal();
 
+  auto logger = g_slog->withName("rpz")->v(1);
+
   /* we can _never_ modify this zone directly, we need to do a full copy then replace the existing zone */
   std::shared_ptr<DNSFilterEngine::Zone> oldZone = luaconfsLocal->dfe.getZone(zoneIdx);
   if (!oldZone) {
-    g_log<<Logger::Error<<"Unable to retrieve RPZ zone with index "<<zoneIdx<<" from the configuration, exiting"<<endl;
+    logger->error(Logr::Error, "Unable to retrieve RPZ zone from configuration", "index", Logging::Loggable(zoneIdx));
     return;
   }
 
@@ -376,6 +378,9 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, boost::optional<
   DNSName zoneName = oldZone->getDomain();
   std::string polName = oldZone->getName().empty() ? oldZone->getName() : zoneName.toString();
 
+  // Now that we know the name, set it in the logger
+  logger = logger->withValues("zone", Logging::Loggable(zoneName));
+
   while (!sr) {
     /* if we received an empty sr, the zone was not really preloaded */
 
@@ -383,7 +388,7 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, boost::optional<
     std::shared_ptr<DNSFilterEngine::Zone> newZone = std::make_shared<DNSFilterEngine::Zone>(*oldZone);
     for (const auto& primary : primaries) {
       try {
-        sr = loadRPZFromServer(primary, zoneName, newZone, defpol, defpolOverrideLocal, maxTTL, tt, maxReceivedBytes, localAddress, axfrTimeout);
+        sr = loadRPZFromServer(logger, primary, zoneName, newZone, defpol, defpolOverrideLocal, maxTTL, tt, maxReceivedBytes, localAddress, axfrTimeout);
         newZone->setSerial(sr->d_st.serial);
         newZone->setRefresh(sr->d_st.refresh);
         refresh = std::max(refreshFromConf ? refreshFromConf : newZone->getRefresh(), 1U);
@@ -394,18 +399,18 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, boost::optional<
           });
 
         if (!dumpZoneFileName.empty()) {
-          dumpZoneToDisk(zoneName, newZone, dumpZoneFileName);
+          dumpZoneToDisk(logger, zoneName, newZone, dumpZoneFileName);
         }
 
         /* no need to try another primary */
         break;
       }
       catch(const std::exception& e) {
-        g_log<<Logger::Warning<<"Unable to load RPZ zone '"<<zoneName<<"' from '"<<primary<<"': '"<<e.what()<<"'. (Will try again in "<<refresh<<" seconds...)"<<endl;
+        logger->info(Logr::Warning, "Unable to load RPZ zone, will retry", "from", Logging::Loggable(primary), "exception", Logging::Loggable(e.what()), "refresh", Logging::Loggable(refresh));
         incRPZFailedTransfers(polName);
       }
       catch(const PDNSException& e) {
-        g_log<<Logger::Warning<<"Unable to load RPZ zone '"<<zoneName<<"' from '"<<primary<<"': '"<<e.reason<<"'. (Will try again in "<<refresh<<" seconds...)"<<endl;
+        logger->info(Logr::Warning, "Unable to load RPZ zone, will retry", "from", Logging::Loggable(primary), "exception", Logging::Loggable(e.reason), "refresh", Logging::Loggable(refresh));
         incRPZFailedTransfers(polName);
       }
     }
@@ -540,7 +545,7 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, boost::optional<
                         });
 
       if (!dumpZoneFileName.empty()) {
-        dumpZoneToDisk(zoneName, newZone, dumpZoneFileName);
+        dumpZoneToDisk(logger, zoneName, newZone, dumpZoneFileName);
       }
       refresh = std::max(refreshFromConf ? refreshFromConf : newZone->getRefresh(), 1U);
     }