]> git.ipfire.org Git - thirdparty/pdns.git/commitdiff
Merge pull request #13156 from rgacogne/ddist-log-level
authorRemi Gacogne <remi.gacogne@powerdns.com>
Fri, 24 Nov 2023 10:24:50 +0000 (11:24 +0100)
committerGitHub <noreply@github.com>
Fri, 24 Nov 2023 10:24:50 +0000 (11:24 +0100)
dnsdist: Add a structured log-like logging option

12 files changed:
.not-formatted
pdns/dnsdist-console.cc
pdns/dnsdist-lua.cc
pdns/dnsdist.cc
pdns/dnsdistdist/Makefile.am
pdns/dnsdistdist/docs/reference/config.rst
pdns/dnsdistdist/dolog.cc [new file with mode: 0644]
pdns/dnsdistdist/test-dnsdistlbpolicies_cc.cc
pdns/dolog.hh
pdns/recursordist/lwres.cc
pdns/sdig.cc
pdns/test-dnscrypt_cc.cc

index 1d1912ccd3b00bdc5a13a527cf49091b176d84bd..c711068a57caa9cd0a6ddd5d583ee184413bee83 100644 (file)
 ./pdns/dnswriter.cc
 ./pdns/dnswriter.hh
 ./pdns/doh.hh
-./pdns/dolog.hh
 ./pdns/dumresp.cc
 ./pdns/dynhandler.cc
 ./pdns/dynhandler.hh
index 437c6493d4cbb1bbcb905fdc97cc6e20724b0c7a..b3c24434562edb517216508d976b79f1c99ea794 100644 (file)
@@ -726,6 +726,7 @@ const std::vector<ConsoleKeyword> g_consoleKeywords{
   { "setServerPolicyLuaFFIPerThread", true, "name, code", "set server selection policy to one named 'name' and returned by the Lua FFI code passed in 'code'" },
   { "setServFailWhenNoServer", true, "bool", "if set, return a ServFail when no servers are available, instead of the default behaviour of dropping the query" },
   { "setStaleCacheEntriesTTL", true, "n", "allows using cache entries expired for at most n seconds when there is no backend available to answer for a query" },
+  { "setStructuredLogging", true, "value [, options]", "set whether log messages should be in structured-logging-like format" },
   { "setSyslogFacility", true, "facility", "set the syslog logging facility to 'facility'. Defaults to LOG_DAEMON" },
   { "setTCPDownstreamCleanupInterval", true, "interval", "minimum interval in seconds between two cleanups of the idle TCP downstream connections" },
   { "setTCPFastOpenKey", true, "string", "TCP Fast Open Key" },
index 396ba3e9d9035cb85ffe6add69210d4ce606fa59..e8d28dafec29f88d6db66477fc257bf01f1909c1 100644 (file)
@@ -1782,12 +1782,33 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck)
     }
     try {
       auto stream = std::ofstream(dest.c_str());
-      g_verboseStream = std::move(stream);
+      dnsdist::logging::LoggingConfiguration::setVerboseStream(std::move(stream));
     }
     catch (const std::exception& e) {
       errlog("Error while opening the verbose logging destination file %s: %s", dest, e.what());
     }
   });
+  luaCtx.writeFunction("setStructuredLogging", [](bool enable, boost::optional<LuaAssociativeTable<std::string>> options) {
+    std::string levelPrefix;
+    std::string timeFormat;
+    if (options) {
+      getOptionalValue<std::string>(options, "levelPrefix", levelPrefix);
+      if (getOptionalValue<std::string>(options, "timeFormat", timeFormat) == 1) {
+        if (timeFormat == "numeric") {
+          dnsdist::logging::LoggingConfiguration::setStructuredTimeFormat(dnsdist::logging::LoggingConfiguration::TimeFormat::Numeric);
+        }
+        else if (timeFormat == "ISO8601") {
+          dnsdist::logging::LoggingConfiguration::setStructuredTimeFormat(dnsdist::logging::LoggingConfiguration::TimeFormat::ISO8601);
+        }
+        else {
+          warnlog("Unknown value '%s' to setStructuredLogging's 'timeFormat' parameter", timeFormat);
+        }
+      }
+      checkAllParametersConsumed("setStructuredLogging", options);
+    }
+
+    dnsdist::logging::LoggingConfiguration::setStructuredLogging(enable, levelPrefix);
+  });
 
   luaCtx.writeFunction("setStaleCacheEntriesTTL", [](uint64_t ttl) {
     checkParameterBound("setStaleCacheEntriesTTL", ttl, std::numeric_limits<uint32_t>::max());
index a5c1d88735ecd0440c4970b6923c989371232f66..58d1ca0b2c123164d8bd238138817f9d5443f825 100644 (file)
 
 using std::thread;
 bool g_verbose;
-std::optional<std::ofstream> g_verboseStream{std::nullopt};
 
 uint16_t g_maxOutstanding{std::numeric_limits<uint16_t>::max()};
 uint32_t g_staleCacheEntriesTTL{0};
-bool g_syslog{true};
-bool g_logtimestamps{false};
 bool g_allowEmptyResponse{false};
 
 GlobalStateHolder<NetmaskGroup> g_ACL;
@@ -2530,7 +2527,7 @@ static void sigTermHandler(int)
      we crash trying to exit, but let's try to avoid the warnings
      in our tests.
   */
-  if (g_syslog) {
+  if (dnsdist::logging::LoggingConfiguration::getSyslog()) {
     syslog(LOG_INFO, "Exiting on user request");
   }
   std::cout<<"Exiting on user request"<<std::endl;
@@ -2654,13 +2651,13 @@ static void parseParameters(int argc, char** argv, ComboAddress& clientAddress)
       g_cmdLine.checkConfig = true;
       break;
     case 2:
-      g_syslog = false;
+      dnsdist::logging::LoggingConfiguration::setSyslog(false);
       break;
     case 3:
       g_cmdLine.beSupervised = true;
       break;
     case 4:
-      g_logtimestamps = true;
+      dnsdist::logging::LoggingConfiguration::setLogTimestamps(true);
       break;
     case 'C':
       g_cmdLine.config = optarg;
index b95fa4852649f210d3214c6314f448a06a29a623..1124a4b35769407f73326bb1cbcf995ab708a26c 100644 (file)
@@ -212,7 +212,7 @@ dnsdist_SOURCES = \
        dnstap.cc dnstap.hh \
        dnswriter.cc dnswriter.hh \
        doh.hh \
-       dolog.hh \
+       dolog.cc dolog.hh \
        doq.hh \
        ednscookies.cc ednscookies.hh \
        ednsextendederror.cc ednsextendederror.hh \
@@ -304,7 +304,7 @@ testrunner_SOURCES = \
        dnsname.cc dnsname.hh \
        dnsparser.hh dnsparser.cc \
        dnswriter.cc dnswriter.hh \
-       dolog.hh \
+       dolog.cc dolog.hh \
        ednscookies.cc ednscookies.hh \
        ednsextendederror.cc ednsextendederror.hh \
        ednsoptions.cc ednsoptions.hh \
index e43e4ff74c9a8ddaca8ae3abb645f2812c12d105..44e7d8dd937af754eedf5618ccb20b89c9d49dfc 100644 (file)
@@ -1203,6 +1203,27 @@ Status, Statistics and More
 
   * ``outputFile=path``: string - Write the output of the command to the supplied file, instead of the standard output.
 
+.. function:: setStructuredLogging(enable[, options])
+
+  .. versionadded:: 1.9.0
+
+  Set whether log messages should be in a structured-logging-like format. This is turned off by default.
+  The resulting format looks like this (when timestamps are enabled via ``--log-timestamps`` and with ``levelPrefix="prio"`` and ``timeFormat="ISO8601"``)::
+
+  ts="2023-11-06T12:04:58+0100" prio="Info" msg="Added downstream server 127.0.0.1:53"
+
+  And with ``levelPrefix="level"`` and ``timeFormat="numeric"``)::
+
+  ts="1699268815.133" level="Info" msg="Added downstream server 127.0.0.1:53"
+
+  :param bool enable: Set to true if you want to enable structured logging
+  :param table options: A table with key: value pairs with options described below.
+
+  Options:
+
+  * ``levelPrefix=prefix``: string - Set the prefix for the log level. Default is ``prio``.
+  * ``timeFormat=format``: string - Set the time format. Supported values are ``ISO8601`` and ``numeric``. Default is ``numeric``.
+
 .. function:: setVerbose(verbose)
 
   .. versionadded:: 1.8.0
diff --git a/pdns/dnsdistdist/dolog.cc b/pdns/dnsdistdist/dolog.cc
new file mode 100644 (file)
index 0000000..55a92b8
--- /dev/null
@@ -0,0 +1,96 @@
+/*
+ * 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 <mutex>
+#include <sys/time.h>
+
+#include "dolog.hh"
+
+namespace dnsdist::logging
+{
+std::optional<std::ofstream> LoggingConfiguration::s_verboseStream{std::nullopt};
+std::string LoggingConfiguration::s_structuredLevelPrefix{"prio"};
+LoggingConfiguration::TimeFormat LoggingConfiguration::s_structuredTimeFormat{LoggingConfiguration::TimeFormat::Numeric};
+bool LoggingConfiguration::s_structuredLogging{false};
+bool LoggingConfiguration::s_logTimestamps{false};
+bool LoggingConfiguration::s_syslog{false};
+
+namespace
+{
+  const char* getTimeFormat()
+  {
+    if (!dnsdist::logging::LoggingConfiguration::getStructuredLogging()) {
+      return "%b %d %H:%M:%S ";
+    }
+
+    auto format = dnsdist::logging::LoggingConfiguration::getStructuredLoggingTimeFormat();
+    if (format == dnsdist::logging::LoggingConfiguration::TimeFormat::ISO8601) {
+      return "%FT%H:%M:%S%z";
+    }
+    return nullptr;
+  }
+}
+
+void logTime(std::ostream& stream)
+{
+  std::array<char, 50> buffer{""};
+
+  if (LoggingConfiguration::getStructuredLogging() && LoggingConfiguration::getStructuredLoggingTimeFormat() == LoggingConfiguration::TimeFormat::Numeric) {
+    struct timeval now
+    {
+    };
+    gettimeofday(&now, nullptr);
+    snprintf(buffer.data(), buffer.size(), "%lld.%03ld", static_cast<long long>(now.tv_sec), static_cast<long>(now.tv_usec / 1000));
+  }
+  else {
+    const auto* timeFormat = getTimeFormat();
+    if (timeFormat == nullptr) {
+      return;
+    }
+
+    time_t now{0};
+    time(&now);
+    struct tm localNow
+    {
+    };
+    localtime_r(&now, &localNow);
+
+    {
+      // strftime is not thread safe, it can access locale information
+      static std::mutex mutex;
+      auto lock = std::lock_guard(mutex);
+
+      if (strftime(buffer.data(), buffer.size(), timeFormat, &localNow) == 0) {
+        buffer[0] = '\0';
+      }
+    }
+  }
+
+  if (dnsdist::logging::LoggingConfiguration::getStructuredLogging()) {
+    stream << "ts=" << std::quoted(buffer.data()) << " ";
+  }
+  else {
+    stream << buffer.data();
+  }
+}
+
+}
index 94594bd17bf0cc1c38a8f153fb4cd51a857fee50..813eeac44247ff246e3d888a77c811f549cf5b54 100644 (file)
@@ -23,8 +23,6 @@ DNSDistSNMPAgent* g_snmpAgent{nullptr};
 
 #if BENCH_POLICIES
 bool g_verbose{true};
-bool g_syslog{true};
-bool g_logtimestamps{false};
 #include "dnsdist-rings.hh"
 Rings g_rings;
 GlobalStateHolder<NetmaskTree<DynBlock>> g_dynblockNMG;
index dd88b6f2fbf0f8b16c6b9282ae566cab4a7a8f39..25c49521b7e3fe84d9041bce32ccfa58ebeebdfb 100644 (file)
@@ -20,7 +20,9 @@
  * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
  */
 #pragma once
+#include <array>
 #include <fstream>
+#include <iomanip>
 #include <iostream>
 #include <optional>
 #include <sstream>
 #include "logger.hh"
 #endif // RECURSOR
 
-
 /* This file is intended not to be metronome specific, and is simple example of C++2011
    variadic templates in action.
 
-   The goal is rapid easy to use logging to console & syslog. 
+   The goal is rapid easy to use logging to console & syslog.
 
-   Usage: 
+   Usage:
           string address="localhost";
           vinfolog("Got TCP connection from %s", remote);
           infolog("Bound to %s port %d", address, port);
 
    This will happily print a string to %d! Doesn't do further format processing.
 */
-
-#if !defined(RECURSOR)
-inline void dolog(std::ostream& os, const char*s)
+template <typename O>
+inline void dolog(O& outputStream, const char* str)
 {
-  os<<s;
+  outputStream << str;
 }
 
-template<typename T, typename... Args>
-void dolog(std::ostream& os, const char* s, T value, const Args&... args)
+template <typename O, typename T, typename... Args>
+void dolog(O& outputStream, const char* formatStr, T value, const Args&... args)
 {
-  while (*s) {
-    if (*s == '%') {
-      if (*(s + 1) == '%') {
-       ++s;
+  while (*formatStr) {
+    if (*formatStr == '%') {
+      // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic)
+      if (*(formatStr + 1) == '%') {
+        // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic)
+        ++formatStr;
       }
       else {
-       os << value;
-       s += 2;
-       dolog(os, s, args...);
-       return;
+        outputStream << value;
+        // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic)
+        formatStr += 2;
+        dolog(outputStream, formatStr, args...);
+        return;
       }
     }
-    os << *s++;
+    // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic)
+    outputStream << *formatStr++;
   }
 }
 
+#if !defined(RECURSOR)
+// NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables)
 extern bool g_verbose;
-extern bool g_syslog;
+
 #ifdef DNSDIST
-extern bool g_logtimestamps;
-extern std::optional<std::ofstream> g_verboseStream;
+namespace dnsdist::logging
+{
+class LoggingConfiguration
+{
+public:
+  enum class TimeFormat
+  {
+    Numeric,
+    ISO8601
+  };
+
+  static void setVerbose(bool value = true)
+  {
+    g_verbose = value;
+  }
+  static void setSyslog(bool value = true)
+  {
+    s_syslog = value;
+  }
+  static void setStructuredLogging(bool value = true, std::string levelPrefix = "")
+  {
+    s_structuredLogging = value;
+    if (value) {
+      s_structuredLevelPrefix = levelPrefix.empty() ? "prio" : std::move(levelPrefix);
+    }
+  }
+  static void setLogTimestamps(bool value = true)
+  {
+    s_logTimestamps = value;
+  }
+  static void setStructuredTimeFormat(TimeFormat format)
+  {
+    s_structuredTimeFormat = format;
+  }
+  static void setVerboseStream(std::ofstream&& stream)
+  {
+    s_verboseStream = std::move(stream);
+  }
+  static bool getVerbose()
+  {
+    return g_verbose;
+  }
+  static bool getSyslog()
+  {
+    return s_syslog;
+  }
+  static bool getLogTimestamps()
+  {
+    return s_logTimestamps;
+  }
+  static std::optional<std::ofstream>& getVerboseStream()
+  {
+    return s_verboseStream;
+  }
+  static bool getStructuredLogging()
+  {
+    return s_structuredLogging;
+  }
+  static const std::string& getStructuredLoggingLevelPrefix()
+  {
+    return s_structuredLevelPrefix;
+  }
+
+  static TimeFormat getStructuredLoggingTimeFormat()
+  {
+    return s_structuredTimeFormat;
+  }
+
+private:
+  static std::optional<std::ofstream> s_verboseStream;
+  static std::string s_structuredLevelPrefix;
+  static TimeFormat s_structuredTimeFormat;
+  static bool s_structuredLogging;
+  static bool s_logTimestamps;
+  static bool s_syslog;
+};
+
+extern void logTime(std::ostream& stream);
+}
 #endif
 
 inline void setSyslogFacility(int facility)
 {
   /* we always call openlog() right away at startup */
   closelog();
-  openlog("dnsdist", LOG_PID|LOG_NDELAY, facility);
+  openlog("dnsdist", LOG_PID | LOG_NDELAY, facility);
+}
+
+namespace
+{
+inline const char* syslogLevelToStr(int level)
+{
+  static constexpr std::array levelStrs{
+    "Emergency",
+    "Alert",
+    "Critical",
+    "Error",
+    "Warning",
+    "Notice",
+    "Info",
+    "Debug"};
+  return levelStrs.at(level);
+}
 }
 
-template<typename... Args>
-void genlog(std::ostream& stream, int level, bool doSyslog, const char* s, const Args&... args)
+template <typename... Args>
+void genlog(std::ostream& stream, [[maybe_unused]] int level, [[maybe_unused]] bool skipSyslog, const char* formatStr, const Args&... args)
 {
   std::ostringstream str;
-  dolog(str, s, args...);
+  dolog(str, formatStr, args...);
 
   auto output = str.str();
 
-  if (doSyslog) {
+#ifdef DNSDIST
+  if (!skipSyslog && dnsdist::logging::LoggingConfiguration::getSyslog()) {
+    // NOLINTNEXTLINE(cppcoreguidelines-pro-type-vararg): syslog is what it is
     syslog(level, "%s", output.c_str());
   }
 
-#ifdef DNSDIST
-  if (g_logtimestamps) {
-    char buffer[50] = "";
-    struct tm tm;
-    time_t t;
-    time(&t);
-    localtime_r(&t, &tm);
-    if (strftime(buffer, sizeof(buffer), "%b %d %H:%M:%S ", &tm) == 0) {
-      buffer[0] = '\0';
-    }
-    stream<<buffer;
+  if (dnsdist::logging::LoggingConfiguration::getLogTimestamps()) {
+    dnsdist::logging::logTime(stream);
   }
-#endif
 
-  stream<<output<<std::endl;
+  if (dnsdist::logging::LoggingConfiguration::getStructuredLogging()) {
+    stream << dnsdist::logging::LoggingConfiguration::getStructuredLoggingLevelPrefix() << "=\"" << syslogLevelToStr(level) << "\" ";
+    stream << "msg=" << std::quoted(output) << std::endl;
+  }
+  else {
+    stream << output << std::endl;
+  }
+#else
+  stream << output << std::endl;
+#endif
 }
 
-template<typename... Args>
-void verboselog(const char* s, const Args&... args)
+template <typename... Args>
+void verboselog(const char* formatStr, const Args&... args)
 {
 #ifdef DNSDIST
-  if (g_verboseStream) {
-    genlog(*g_verboseStream, LOG_DEBUG, false, s, args...);
+  if (auto& stream = dnsdist::logging::LoggingConfiguration::getVerboseStream()) {
+    genlog(*stream, LOG_DEBUG, true, formatStr, args...);
   }
   else {
 #endif /* DNSDIST */
-    genlog(std::cout, LOG_DEBUG, g_syslog, s, args...);
+    genlog(std::cout, LOG_DEBUG, false, formatStr, args...);
 #ifdef DNSDIST
   }
 #endif /* DNSDIST */
 }
 
-#define vinfolog if (g_verbose) verboselog
+#define vinfolog \
+  if (g_verbose) \
+  verboselog
 
-template<typename... Args>
-void infolog(const char* s, const Args&... args)
+template <typename... Args>
+void infolog(const char* formatStr, const Args&... args)
 {
-  genlog(std::cout, LOG_INFO, g_syslog, s, args...);
+  genlog(std::cout, LOG_INFO, false, formatStr, args...);
 }
 
-template<typename... Args>
-void warnlog(const char* s, const Args&... args)
+template <typename... Args>
+void warnlog(const char* formatStr, const Args&... args)
 {
-  genlog(std::cout, LOG_WARNING, g_syslog, s, args...);
+  genlog(std::cout, LOG_WARNING, false, formatStr, args...);
 }
 
-template<typename... Args>
-void errlog(const char* s, const Args&... args)
+template <typename... Args>
+void errlog(const char* formatStr, const Args&... args)
 {
-  genlog(std::cout, LOG_ERR, g_syslog, s, args...);
+  genlog(std::cout, LOG_ERR, false, formatStr, args...);
 }
 
 #else // RECURSOR
-
 #define g_verbose 0
+#define vinfolog \
+  if (g_verbose) \
+  infolog
 
-inline void dolog(Logger::Urgency u, const char* s)
-{
-  g_log << u << s << std::endl;
-}
-
-inline void dolog(const char* s)
-{
-  g_log << s << std::endl;
-}
-
-template<typename T, typename... Args>
-void dolog(Logger::Urgency u, const char* s, T value, const Args&... args)
-{
-  g_log << u;
-  while (*s) {
-    if (*s == '%') {
-      if (*(s + 1) == '%') {
-       ++s;
-      }
-      else {
-       g_log << value;
-       s += 2;
-       dolog(s, args...);
-       return;
-      }
-    }
-    g_log << *s++;
-  }
-}
-
-#define vinfolog if(g_verbose)infolog
-
-template<typename... Args>
-void infolog(const char* s, const Args&... args)
+template <typename... Args>
+void infolog(const char* formatStr, const Args&... args)
 {
-  dolog(Logger::Info, s, args...);
+  g_log << Logger::Info;
+  dolog(g_log, formatStr, args...);
 }
 
-template<typename... Args>
-void warnlog(const char* s, const Args&... args)
+template <typename... Args>
+void warnlog(const char* formatStr, const Args&... args)
 {
-  dolog(Logger::Warning, s, args...);
+  g_log << Logger::Warning;
+  dolog(g_log, formatStr, args...);
 }
 
-template<typename... Args>
-void errlog(const char* s, const Args&... args)
+template <typename... Args>
+void errlog(const char* formatStr, const Args&... args)
 {
-  dolog(Logger::Error, s, args...);
+  g_log << Logger::Error;
+  dolog(g_log, formatStr, args...);
 }
 
 #endif
index 5b255b298072f81f479a6c159b216ff15d1d3591..3561d11cfdda5a392753818cef6c595150cd7019 100644 (file)
@@ -94,8 +94,6 @@ void remoteLoggerQueueData(RemoteLoggerInterface& r, const std::string& data)
 #include "dnstap.hh"
 #include "fstrm_logger.hh"
 
-bool g_syslog;
-
 static bool isEnabledForQueries(const std::shared_ptr<std::vector<std::unique_ptr<FrameStreamLogger>>>& fstreamLoggers)
 {
   if (fstreamLoggers == nullptr) {
index 60d14b6bfe9128f626d5caef3097ecaba790c82a..e48e1f95bcc77f7e98bb3f80001798e97c0b5495 100644 (file)
@@ -23,7 +23,6 @@ StatBag S;
 
 // Vars below used by tcpiohandler.cc
 bool g_verbose = true;
-bool g_syslog = false;
 
 static bool hidettl = false;
 
index 5df51acc58db4ef822a076a9cba421b5aca73a86..d6d48f625c6c70d82813c9439cf0a698407f60c2 100644 (file)
@@ -35,9 +35,6 @@
 #include <unistd.h>
 
 bool g_verbose{false};
-bool g_syslog{true};
-bool g_logtimestamps{false};
-std::optional<std::ofstream> g_verboseStream{std::nullopt};
 
 BOOST_AUTO_TEST_SUITE(test_dnscrypt_cc)