]> git.ipfire.org Git - thirdparty/pdns.git/commitdiff
rec: structured-logging draft
authorCharles-Henri Bruyand <charles-henri.bruyand@open-xchange.com>
Wed, 10 Mar 2021 08:49:37 +0000 (09:49 +0100)
committerOtto <otto.moerbeek@open-xchange.com>
Wed, 28 Apr 2021 10:57:35 +0000 (12:57 +0200)
pdns/pdns_recursor.cc
pdns/recursordist/Makefile.am
pdns/recursordist/logging.cc [new file with mode: 0644]
pdns/recursordist/logging.hh [new file with mode: 0644]
pdns/recursordist/logr.hh [new file with mode: 0644]
pdns/rpzloader.cc

index 2ee539cfb642bfdd7325111264d580557f2ccba5..b1fda8118fadcdd479d9b45cbc79003bba89fb97 100644 (file)
@@ -76,6 +76,7 @@
 #include "zoneparser-tng.hh"
 #include "rec_channel.hh"
 #include "logger.hh"
+#include "logging.hh"
 #include "iputils.hh"
 #include "mplexer.hh"
 #include "config.h"
@@ -5674,13 +5675,34 @@ int main(int argc, char **argv)
       exit(0);
     }
 
-    if(!::arg().file(configname.c_str()))
-      g_log<<Logger::Warning<<"Unable to parse configuration file '"<<configname<<"'"<<endl;
+    g_slog = Logging::Logger::create([](std::unique_ptr<Logging::Entry> entry) {
+      if (entry->error) {
+        std::cout << "ERR ";
+      } else {
+        std::cout << "INFO";
+     }
+      if (entry->name) {
+        std::cout << entry->name.get() << ": ";
+      }
+      std::cout << entry->message;
+      for (auto const& v: entry->values) {
+        std::cout << " ";
+        std::cout << v.first << "=" << v.second;
+      }
+      std::cout << std::endl;
+    });
+    auto startupLog = g_slog->withName("startup");
+
+    if(!::arg().file(configname.c_str())) {
+      startupLog
+        ->withValues("config_file", Logging::Loggable(configname))
+        ->error("No such file", "Unable to parse configuration file");
+    }
 
     ::arg().parse(argc,argv);
 
     if( !::arg()["chroot"].empty() && !::arg()["api-config-dir"].empty() ) {
-      g_log<<Logger::Error<<"Using chroot and enabling the API is not possible"<<endl;
+      startupLog->info("Cannot use chroot and enable the API at the same time");
       exit(EXIT_FAILURE);
     }
 
@@ -5693,13 +5715,13 @@ int main(int argc, char **argv)
 
     if(::arg().asNum("threads")==1) {
       if (::arg().mustDo("pdns-distributes-queries")) {
-        g_log<<Logger::Warning<<"Only one thread, no need to distribute queries ourselves"<<endl;
+        startupLog->v(1)->info("Only one thread, no need to distribute queries ourselves");
         ::arg().set("pdns-distributes-queries")="no";
       }
     }
 
     if(::arg().mustDo("pdns-distributes-queries") && ::arg().asNum("distributor-threads") <= 0) {
-      g_log<<Logger::Warning<<"Asked to run with pdns-distributes-queries set but no distributor threads, raising to 1"<<endl;
+      startupLog->v(1)->info("Asked to run with pdns-distributes-queries set but no distributor threads, raising to 1");
       ::arg().set("distributor-threads")="1";
     }
 
index bd39f48fe504c7ced04192f7fc81430bda8be5fc..5175204b60379b9c28a0138c9d1713f6602e69d2 100644 (file)
@@ -130,6 +130,7 @@ pdns_recursor_SOURCES = \
        lazy_allocator.hh \
        lock.hh \
        logger.hh logger.cc \
+       logging.hh logging.cc logr.hh \
        lua-base4.cc lua-base4.hh \
        lua-recursor4-ffi.hh \
        lua-recursor4.cc lua-recursor4.hh \
@@ -255,6 +256,7 @@ testrunner_SOURCES = \
        iputils.cc iputils.hh \
        ixfr.cc ixfr.hh \
        logger.cc logger.hh \
+       logging.hh logging.cc logr.hh \
        misc.cc misc.hh \
        mtasker_context.cc \
        namespaces.hh \
diff --git a/pdns/recursordist/logging.cc b/pdns/recursordist/logging.cc
new file mode 100644 (file)
index 0000000..b5da367
--- /dev/null
@@ -0,0 +1,140 @@
+/**
+ * This file is part of PowerDNS or dnsdist.
+ * Copyright -- PowerDNS.COM B.V. and its contributors
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of version 2 of the GNU General Public License as
+ * published by the Free Software Foundation.
+ *
+ * In addition, for the avoidance of any doubt, permission is granted to
+ * link this program with OpenSSL and to (re)distribute the binaries
+ * produced as the result of such linking.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
+ */
+
+#include "logging.hh"
+
+namespace Logging
+{
+
+  std::shared_ptr<Logger> Logger::getptr()
+  {
+    return shared_from_this();
+  }
+
+  bool Logger::enabled()
+  {
+    return true;
+  }
+
+  void Logger::info(const std::string& msg)
+  {
+    logMessage(msg, boost::none);
+  }
+
+  void Logger::logMessage(const std::string& msg, boost::optional<const std::string> err)
+  {
+    if (_level > _verbosity) {
+      return ;
+    }
+    auto entry = std::unique_ptr<Entry>(new Entry());
+    entry->level = _level;
+    entry->name = _name;
+    entry->message = msg;
+    entry->error = err;
+    auto parent = _parent;
+    entry->values.insert(_values.begin(), _values.end());
+    while (parent) {
+      entry->values.insert(parent->_values.begin(), parent->_values.end());
+      parent = parent->_parent;
+    }
+    _callback(std::move(entry));
+  }
+
+  void Logger::error(const std::string& err, const std::string& msg)
+  {
+    logMessage(msg, err);
+  }
+
+  std::shared_ptr<Logr::Logger> Logger::v(size_t level)
+  {
+    auto res = std::make_shared<Logger>(getptr(), boost::none, level + _level, _callback);
+    res->setVerbosity(getVerbosity());
+    return res;
+  }
+
+  std::shared_ptr<Logr::Logger> Logger::withValues(const std::string& key, const Logr::Loggable& value)
+  {
+    auto res = std::make_shared<Logger>(getptr(), _name.get(), _level, _callback);
+    res->_values.insert({key, value.to_string()});
+    res->setVerbosity(getVerbosity());
+    return res;
+  }
+
+  template struct Loggable<DNSName>;
+  template struct Loggable<ComboAddress>;
+  template struct Loggable<std::string>;
+
+  template <>
+  std::string Loggable<DNSName>::to_string() const {
+    return _t.toLogString();
+  }
+  template <>
+  std::string Loggable<ComboAddress>::to_string() const {
+    return _t.toLogString();
+  }
+  template <>
+  std::string Loggable<std::string>::to_string() const {
+    return _t;
+  }
+
+  std::shared_ptr<Logr::Logger> Logger::withName(const std::string& name)
+  {
+    std::shared_ptr<Logger> res;
+    if (_name) {
+      res = std::make_shared<Logger>(getptr(), _name.get() + "." + name, _level, _callback);
+    } else {
+      res = std::make_shared<Logger>(getptr(), name, _level, _callback);
+    }
+    res->setVerbosity(getVerbosity());
+    return res;
+  }
+  std::shared_ptr<Logger> Logger::create(EntryLogger callback)
+  {
+    return std::make_shared<Logger>(callback);
+  }
+  std::shared_ptr<Logger> Logger::create(EntryLogger callback, const std::string& name)
+  {
+    return std::make_shared<Logger>(callback, name);
+  }
+
+  size_t Logger::getVerbosity() const
+  {
+    return _verbosity;
+  }
+
+  void Logger::setVerbosity(size_t verbosity)
+  {
+    _verbosity = verbosity;
+  }
+
+  Logger::Logger(EntryLogger callback) : _callback(callback)
+  {
+  }
+  Logger::Logger(EntryLogger callback, boost::optional<const std::string> name) : _callback(callback), _name(name)
+  {
+  }
+  Logger::Logger(std::shared_ptr<Logger> parent, boost::optional<const std::string> name, size_t lvl,  EntryLogger callback) : _parent(parent), _callback(callback), _name(name), _level(lvl)
+  {
+  }
+};
+
+std::shared_ptr<Logging::Logger> g_slog{nullptr};
diff --git a/pdns/recursordist/logging.hh b/pdns/recursordist/logging.hh
new file mode 100644 (file)
index 0000000..b851728
--- /dev/null
@@ -0,0 +1,102 @@
+/*
+ * This file is part of PowerDNS or dnsdist.
+ * Copyright -- PowerDNS.COM B.V. and its contributors
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of version 2 of the GNU General Public License as
+ * published by the Free Software Foundation.
+ *
+ * In addition, for the avoidance of any doubt, permission is granted to
+ * link this program with OpenSSL and to (re)distribute the binaries
+ * produced as the result of such linking.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
+ */
+
+#pragma once
+
+#include <map>
+#include <memory>
+#include <string>
+#include <sstream>
+#include <boost/optional.hpp>
+
+#include "logr.hh"
+#include "dnsname.hh"
+#include "iputils.hh"
+
+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
+    std::map<std::string, std::string> values;
+  };
+
+  template <typename T>
+  struct Loggable : public Logr::Loggable
+  {
+    const T& _t;
+    Loggable(const T& v): _t(v) {
+    }
+    std::string to_string() const {
+      std::ostringstream oss;
+      oss << _t;
+      return oss.str();
+    }
+  };
+  template <>
+  std::string Loggable<DNSName>::to_string() const;
+  template <>
+  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) {}
+
+  typedef void(*EntryLogger)(std::unique_ptr<Entry>);
+
+  class Logger: public Logr::Logger, public std::enable_shared_from_this<Logger>
+  {
+  public:
+    virtual bool enabled();
+    virtual void info(const std::string& msg);
+    virtual void error(const std::string& err, const std::string& msg);
+    virtual std::shared_ptr<Logr::Logger> v(size_t level);
+
+    std::shared_ptr<Logr::Logger> withValues(const std::string& key, const Logr::Loggable& value);
+    virtual std::shared_ptr<Logr::Logger> withName(const std::string& name);
+
+    static std::shared_ptr<Logger> create(EntryLogger callback);
+    static std::shared_ptr<Logger> create(EntryLogger callback, const std::string& name);
+
+    Logger(EntryLogger callback);
+    Logger(EntryLogger callback, boost::optional<const std::string> name);
+    Logger(std::shared_ptr<Logger> parent, boost::optional<const std::string> name, size_t lvl,  EntryLogger callback);
+
+    size_t getVerbosity() const;
+    void setVerbosity(size_t verbosity);
+  private:
+    void logMessage(const std::string& msg, boost::optional<const std::string> err);
+    std::shared_ptr<Logger> getptr();
+
+    std::shared_ptr<Logger> _parent{nullptr};
+    EntryLogger _callback;
+    boost::optional<std::string> _name;
+    std::map<std::string, std::string> _values;
+    size_t _verbosity{0};
+    size_t _level{0};
+  };
+}
+
+extern std::shared_ptr<Logging::Logger> g_slog;
diff --git a/pdns/recursordist/logr.hh b/pdns/recursordist/logr.hh
new file mode 100644 (file)
index 0000000..2345c3f
--- /dev/null
@@ -0,0 +1,77 @@
+/*
+ * This file is part of PowerDNS or dnsdist.
+ * Copyright -- PowerDNS.COM B.V. and its contributors
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of version 2 of the GNU General Public License as
+ * published by the Free Software Foundation.
+ *
+ * In addition, for the avoidance of any doubt, permission is granted to
+ * link this program with OpenSSL and to (re)distribute the binaries
+ * produced as the result of such linking.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
+ */
+
+#pragma once
+
+#include <string>
+#include <memory>
+
+// Minimal logging API based on https://github.com/go-logr/logr
+
+namespace Logr {
+  struct Loggable {
+    virtual std::string to_string() const = 0;
+  };
+
+  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() = 0;
+
+    // Info logs a non-error message with the given key/value pairs as context.
+    //
+    // The msg argument should be used to add some constant description to
+    // the log line.  The key/value pairs can then be used to add additional
+    // variable information.  The key/value pairs should alternate string
+    // keys and arbitrary values.
+    virtual void info(const std::string& msg) = 0;
+
+    // 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
+    // package documentations for more information).
+    //
+    // The msg field should be used to add context to any underlying error,
+    // while the err field should be used to attach the actual error that
+    // triggered this log line, if present.
+    virtual void error(const std::string& err, const std::string& msg) = 0;
+
+    // V returns an Logger value for a specific verbosity level, relative to
+    // this Logger.  In other words, V values are additive.  V higher verbosity
+    // level means a log message is less important.  It's illegal to pass a log
+    // level less than zero.
+    virtual std::shared_ptr<Logger> v(size_t level) = 0;
+
+    // WithValues adds some key-value pairs of context to a logger.
+    // See Info for documentation on how key/value pairs work.
+    virtual std::shared_ptr<Logger> withValues(const std::string& key, const Loggable& value) = 0;
+
+    // WithName adds a new element to the logger's name.
+    // Successive calls with WithName continue to append
+    // suffixes to the logger's name.  It's strongly recommended
+    // that name segments contain only letters, digits, and hyphens
+    // (see the package documentation for more information).
+    virtual std::shared_ptr<Logger> withName(const std::string& name) = 0;
+  };
+}
index 7d521ca6a0728d7ba37a2b931bb26a102c1fd589..3c27c1cd968b56c180b064494b70f29ed3bf2f83 100644 (file)
@@ -5,6 +5,7 @@
 #include "syncres.hh"
 #include "axfr-retriever.hh"
 #include "logger.hh"
+#include "logging.hh"
 #include "rec-lua-conf.hh"
 #include "rpzloader.hh"
 #include "zoneparser-tng.hh"
@@ -188,9 +189,12 @@ 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)
 {
-  g_log<<Logger::Warning<<"Loading RPZ zone '"<<zoneName<<"' from "<<primary.toStringWithPort()<<endl;
-  if(!tt.name.empty())
-    g_log<<Logger::Warning<<"With TSIG key '"<<tt.name<<"' of algorithm '"<<tt.algo<<"'"<<endl;
+
+  auto logger = g_slog->withName("rpz")->withValues("zone", Logging::Loggable(zoneName))->withValues("primary", Logging::Loggable(primary));
+  logger->info("Loading RPZ from nameserver");
+  if(!tt.name.empty()) {
+    logger->withValues("tsig_key_name", Logging::Loggable(tt.name))->withValues("tsig_key_algorithm", Logging::Loggable(tt.algo))->info("Using TSIG key for authentication");
+  }
 
   ComboAddress local(localAddress);
   if (local == ComboAddress())
@@ -224,11 +228,11 @@ static shared_ptr<SOARecordContent> loadRPZFromServer(const ComboAddress& primar
       throw PDNSException("Total AXFR time exceeded!");
     }
     if(last != time(0)) {
-      g_log<<Logger::Info<<"Loaded & indexed "<<nrecords<<" policy records so far for RPZ zone '"<<zoneName<<"'"<<endl;
+      logger->withValues("nrecords", Logging::Loggable(nrecords))->info("RPZ load in progress");
       last=time(0);
     }
   }
-  g_log<<Logger::Info<<"Done: "<<nrecords<<" policy records active, SOA: "<<sr->getZoneRepresentation()<<endl;
+  logger->withValues("nrecords", Logging::Loggable(nrecords))->withValues("soa", Logging::Loggable(sr->getZoneRepresentation()))->info("RPZ load completed");
   return sr;
 }
 
@@ -304,17 +308,20 @@ static void setRPZZoneNewState(const std::string& zone, uint32_t serial, uint64_
 
 static bool dumpZoneToDisk(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)->withValues("destination_file", Logging::Loggable(dumpZoneFileName))->info("Dumping zone to disk");
   std::string temp = dumpZoneFileName + "XXXXXX";
   int fd = mkstemp(&temp.at(0));
   if (fd < 0) {
-    g_log<<Logger::Warning<<"Unable to open a file to dump the content of the RPZ zone "<<zoneName<<endl;
+    logger->error(strerror(errno), "Unable to create temporary file");
     return false;
   }
 
   auto fp = std::unique_ptr<FILE, int(*)(FILE*)>(fdopen(fd, "w+"), fclose);
   if (!fp) {
+    int err = errno;
     close(fd);
-    g_log<<Logger::Warning<<"Unable to open a file pointer to dump the content of the RPZ zone "<<zoneName<<endl;
+    logger->error(stringerror(err), "Unable to open file pointer");
     return false;
   }
   fd = -1;
@@ -323,27 +330,29 @@ static bool dumpZoneToDisk(const DNSName& zoneName, const std::shared_ptr<DNSFil
     newZone->dump(fp.get());
   }
   catch(const std::exception& e) {
-    g_log<<Logger::Warning<<"Error while dumping the content of the RPZ zone "<<zoneName<<": "<<e.what()<<endl;
+    logger->error(e.what(), "Error while dumping the content of the RPZ");
     return false;
   }
 
   if (fflush(fp.get()) != 0) {
-    g_log<<Logger::Warning<<"Error while flushing the content of the RPZ zone "<<zoneName<<" to the dump file: "<<stringerror()<<endl;
+    logger->error(stringerror(), "Error while flushing the content of the RPZ");
     return false;
   }
 
   if (fsync(fileno(fp.get())) != 0) {
-    g_log<<Logger::Warning<<"Error while syncing the content of the RPZ zone "<<zoneName<<" to the dump file: "<<stringerror()<<endl;
+    logger->error(stringerror(), "Error while syncing the content of the RPZ");
     return false;
   }
 
   if (fclose(fp.release()) != 0) {
-    g_log<<Logger::Warning<<"Error while writing the content of the RPZ zone "<<zoneName<<" to the dump file: "<<stringerror()<<endl;
+    logger->error(stringerror(), "Error while writing the content of the RPZ");
     return false;
   }
 
   if (rename(temp.c_str(), dumpZoneFileName.c_str()) != 0) {
-    g_log<<Logger::Warning<<"Error while moving the content of the RPZ zone "<<zoneName<<" to the dump file: "<<stringerror()<<endl;
+    logger
+      ->withValues("destination_file", Logging::Loggable(dumpZoneFileName))
+      ->error(stringerror(), "Error while moving the content of the RPZ");
     return false;
   }