]> git.ipfire.org Git - thirdparty/pdns.git/commitdiff
dnsdist: Add a structured log-like logging option
authorRemi Gacogne <remi.gacogne@powerdns.com>
Fri, 18 Aug 2023 12:51:53 +0000 (14:51 +0200)
committerRemi Gacogne <remi.gacogne@powerdns.com>
Tue, 21 Nov 2023 16:11:58 +0000 (17:11 +0100)
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..efe3d9d551799ffff1e4af83ddf230dc71c0b7d5 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"``)::
+
+  tm="2023-11-06T12:04:58+0100" prio="info" msg="Added downstream server 127.0.0.1:53"
+
+  And with ``levelPrefix="level"`` and ``timeFormat="numeric"``)::
+
+  tm="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..0222e14
--- /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), 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 << "tm=\"" << buffer.data() << "\" ";
+  }
+  else {
+    stream << buffer.data();
+  }
+}
+
+}
index 9d437578f77fb48fe8e71844841e38ddbf141e27..09e95df1f19269d8df3a4975d009fdc897cd54c1 100644 (file)
@@ -20,8 +20,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 bd32207806831aa8c774d31ee6a474fabfe11b4e..17af3a07b84417bbcfcbde6bcc2b4a1751ac8d5b 100644 (file)
@@ -22,6 +22,7 @@
 #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.
 */
-template<typename O>
+template <typename O>
 inline void dolog(O& outputStream, const char* str)
 {
   outputStream << str;
 }
 
-template<typename O, typename T, typename... Args>
+template <typename O, typename T, typename... Args>
 void dolog(O& outputStream, const char* formatStr, T value, const Args&... args)
 {
   while (*formatStr) {
@@ -65,14 +65,14 @@ void dolog(O& outputStream, const char* formatStr, T value, const Args&... args)
       // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic)
       if (*(formatStr + 1) == '%') {
         // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic)
-       ++formatStr;
+        ++formatStr;
       }
       else {
-       outputStream << value;
+        outputStream << value;
         // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic)
-       formatStr += 2;
-       dolog(outputStream, formatStr, args...);
-       return;
+        formatStr += 2;
+        dolog(outputStream, formatStr, args...);
+        return;
       }
     }
     // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic)
@@ -81,108 +81,203 @@ void dolog(O& outputStream, const char* formatStr, T value, const Args&... args)
 }
 
 #if !defined(RECURSOR)
-//NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables)
+// NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables)
 extern bool g_verbose;
-//NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables)
-extern bool g_syslog;
+
 #ifdef DNSDIST
-//NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables)
-extern bool g_logtimestamps;
-//NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables)
-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* formatStr, 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, 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) {
-    std::array<char,50> buffer{""};
-    time_t now{0};
-    time(&now);
-    struct tm localNow{};
-    localtime_r(&now, &localNow);
-    if (strftime(buffer.data(), buffer.size(), "%b %d %H:%M:%S ", &localNow) == 0) {
-      buffer[0] = '\0';
-    }
-    stream << buffer.data();
+  if (dnsdist::logging::LoggingConfiguration::getLogTimestamps()) {
+    dnsdist::logging::logTime(stream);
   }
-#endif
 
+  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>
+template <typename... Args>
 void verboselog(const char* formatStr, const Args&... args)
 {
 #ifdef DNSDIST
-  if (g_verboseStream) {
-    genlog(*g_verboseStream, LOG_DEBUG, false, formatStr, 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, formatStr, 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>
+template <typename... Args>
 void infolog(const char* formatStr, const Args&... args)
 {
-  genlog(std::cout, LOG_INFO, g_syslog, formatStr, args...);
+  genlog(std::cout, LOG_INFO, false, formatStr, args...);
 }
 
-template<typename... Args>
+template <typename... Args>
 void warnlog(const char* formatStr, const Args&... args)
 {
-  genlog(std::cout, LOG_WARNING, g_syslog, formatStr, args...);
+  genlog(std::cout, LOG_WARNING, false, formatStr, args...);
 }
 
-template<typename... Args>
+template <typename... Args>
 void errlog(const char* formatStr, const Args&... args)
 {
-  genlog(std::cout, LOG_ERR, g_syslog, formatStr, args...);
+  genlog(std::cout, LOG_ERR, false, formatStr, args...);
 }
 
 #else // RECURSOR
 #define g_verbose 0
-#define vinfolog if(g_verbose)infolog
+#define vinfolog \
+  if (g_verbose) \
+  infolog
 
-template<typename... Args>
+template <typename... Args>
 void infolog(const char* formatStr, const Args&... args)
 {
   g_log << Logger::Info;
   dolog(g_log, formatStr, args...);
 }
 
-template<typename... Args>
+template <typename... Args>
 void warnlog(const char* formatStr, const Args&... args)
 {
   g_log << Logger::Warning;
   dolog(g_log, formatStr, args...);
 }
 
-template<typename... Args>
+template <typename... Args>
 void errlog(const char* formatStr, const Args&... args)
 {
   g_log << Logger::Error;
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 f19010c738aee7d4d623c3ac23d87c5e50af68cd..239c560c45488ea6d3d89b09f0c72841166b0628 100644 (file)
@@ -32,9 +32,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)