rec: remove the possiblility to disable structured logging

Author: omoerbeek

pdns/logging.hh

@@ -206,8 +206,10 @@ private:
 
 extern std::shared_ptr<Logging::Logger> g_slog;
 
-// Prefer structured logging?
-extern bool g_slogStructured;
+// Prefer structured logging? Since 5.1.0, we always do. We keep a const, to allow for step-by-step
+// removal of old style logging code (for recursor-only code). Note that code shared with auth still uses
+// old-style, so the SLOG calls should remain for shared code.
+constexpr bool g_slogStructured = true;
 
 // A helper macro to switch between old-style logging and new-style (structured logging)
 // A typical use:

pdns/recursordist/docs/upgrade.rst

@@ -10,7 +10,12 @@ When upgrading several versions, please read **all** notes applying to the upgra
 Changed settings
 ----------------
 
-For YAML settings only: the type of the :ref:`setting-yaml-incoming.edns_padding_from` and :ref:`setting-yaml-incoming.proxy_protocol_from` has been changed from ``String`` to ``Sequence of Subnet``.
+- For YAML settings only: the type of the :ref:`setting-yaml-incoming.edns_padding_from` and :ref:`setting-yaml-incoming.proxy_protocol_from` has been changed from ``String`` to ``Sequence of Subnet``.
+
+- Disabling :ref:`setting-structured-logging` is no longer supported.
+
+Changed Settings
+^^^^^^^^^^^^^^^^
 
 5.0.2 to 5.0.3, 4.9.3 to 4.9.4 and 4.8.6 to 4.8.7
 -------------------------------------------------

pdns/recursordist/logging.cc

@@ -156,4 +156,3 @@ Logger::~Logger()
 };
 
 std::shared_ptr<Logging::Logger> g_slog{nullptr};
-bool g_slogStructured = true;

pdns/recursordist/rec-main.cc

@@ -3082,7 +3082,6 @@ int main(int argc, char** argv)
     // Pick up options given on command line to setup logging asap.
     g_quiet = ::arg().mustDo("quiet");
     s_logUrgency = (Logger::Urgency)::arg().asNum("loglevel");
-    g_slogStructured = ::arg().mustDo("structured-logging");
     s_structured_logger_backend = ::arg()["structured-logging-backend"];
 
     if (!g_quiet && s_logUrgency < Logger::Info) { // Logger::Info=6, Logger::Debug=7
@@ -3091,8 +3090,8 @@ int main(int argc, char** argv)
     g_log.setLoglevel(s_logUrgency);
     g_log.toConsole(s_logUrgency);
     showProductVersion();
-    if (!g_slogStructured) {
-      g_log << Logger::Warning << "Disabling structured logging is deprecated, old-style logging wil be removed in a future release" << endl;
+    if (!::arg().mustDo("structured-logging")) {
+      g_log << Logger::Error << "Disabling structured logging is not supported anymore" << endl;
     }
 
     g_yamlSettings = false;
@@ -3182,7 +3181,6 @@ int main(int argc, char** argv)
 
     g_quiet = ::arg().mustDo("quiet");
     s_logUrgency = (Logger::Urgency)::arg().asNum("loglevel");
-    g_slogStructured = ::arg().mustDo("structured-logging");
 
     if (s_logUrgency < Logger::Error) {
       s_logUrgency = Logger::Error;

pdns/recursordist/rec_control.cc

@@ -24,6 +24,7 @@
 #endif
 
 #include <iostream>
+#include <iomanip>
 #include <fcntl.h>
 
 #include "pdnsexception.hh"
@@ -32,14 +33,16 @@
 #include "namespaces.hh"
 #include "rec_channel.hh"
 #include "settings/cxxsettings.hh"
+#include "logger.hh"
+#include "logging.hh"
 
 ArgvMap& arg()
 {
   static ArgvMap arg;
   return arg;
 }
 
-static void initArguments(int argc, char** argv)
+static void initArguments(int argc, char** argv, Logr::log_t log)
 {
   arg().set("config-dir", "Location of configuration directory (recursor.conf)") = SYSCONFDIR;
 
@@ -81,11 +84,11 @@ static void initArguments(int argc, char** argv)
   case pdns::settings::rec::YamlSettingsStatus::CannotOpen:
     break;
   case pdns::settings::rec::YamlSettingsStatus::PresentButFailed:
-    cerr << "YAML config found for configname '" << yamlconfigname << "' but error ocurred processing it" << endl;
+    log->error(Logr::Error, msg, "YAML config found, but error ocurred processing it", "configname", Logging::Loggable(yamlconfigname));
     exit(1); // NOLINT(concurrency-mt-unsafe)
     break;
   case pdns::settings::rec::YamlSettingsStatus::OK:
-    cout << "YAML config found and processed for configname '" << yamlconfigname << "'" << endl;
+    log->info(Logr::Notice, "YAML config found and processed", "configname", Logging::Loggable(yamlconfigname));
     pdns::settings::rec::bridgeStructToOldStyleSettings(settings);
     break;
   }
@@ -235,9 +238,51 @@ static RecursorControlChannel::Answer showYAML(const std::string& path)
   }
 }
 
+static void recControlLoggerBackend(const Logging::Entry& entry)
+{
+  static thread_local std::stringstream buf;
+
+  // First map SL priority to syslog's Urgency
+  Logger::Urgency urg = entry.d_priority != 0 ? Logger::Urgency(entry.d_priority) : Logger::Info;
+  if (urg > Logger::Warning) {
+    // We do not log anything if the Urgency of the message is lower than the requested loglevel.
+    // Not that lower Urgency means higher number.
+    return;
+  }
+  buf.str("");
+  buf << "msg=" << std::quoted(entry.message);
+  if (entry.error) {
+    buf << " error=" << std::quoted(entry.error.get());
+  }
+
+  if (entry.name) {
+    buf << " subsystem=" << std::quoted(entry.name.get());
+  }
+  buf << " level=" << std::quoted(std::to_string(entry.level));
+  if (entry.d_priority != 0) {
+    buf << " prio=" << std::quoted(Logr::Logger::toString(entry.d_priority));
+  }
+#if 0
+  // Thread id filled in by backend, since the SL code does not know about RecursorThreads
+  // We use the Recursor thread, other threads get id 0. May need to revisit.
+  buf << " tid=" << std::quoted(std::to_string(RecThreadInfo::id()));
+  std::array<char, 64> timebuf{};
+  buf << " ts=" << std::quoted(toTimestampStringMilli(entry.d_timestamp, timebuf));
+#endif
+  for (auto const& value : entry.values) {
+    buf << " ";
+    buf << value.first << "=" << std::quoted(value.second);
+  }
+
+  cerr << buf.str() << endl;
+}
+
 int main(int argc, char** argv)
 {
-  g_slogStructured = false;
+  g_slog = Logging::Logger::create(recControlLoggerBackend);
+  auto log = g_slog->withName("config");
+  ::arg().setSLog(log);
+
   const set<string> fileCommands = {
     "dump-cache",
     "dump-edns",
@@ -252,7 +297,7 @@ int main(int argc, char** argv)
     "trace-regex",
   };
   try {
-    initArguments(argc, argv);
+    initArguments(argc, argv, log);
     string sockname = "pdns_recursor";
 
     if (arg()["config-name"] != "")
@@ -355,7 +400,7 @@ int main(int argc, char** argv)
     return receive.d_ret;
   }
   catch (PDNSException& ae) {
-    cerr << "Fatal: " << ae.reason << "\n";
+    log->error(Logr::Error, ae.reason, "Fatal");
     return 1;
   }
 }

pdns/recursordist/settings/table.py

@@ -2657,6 +2657,7 @@
  ''',
         'versionadded': '4.6.0',
         'versionchanged': ('5.0.0', 'Disabling structured logging is deprecated'),
+        'versionchanged': ('5.1.0', 'Disabling structured logging is not supported'),
     },
     {
         'name' : 'structured_logging_backend',

regression-tests.recursor/YAMLConversion/expected_result

@@ -1,2 +1 @@
-YAML config found and processed for configname './recursor.yml'
 bye nicely