Merge pull request PowerDNS#13062 from Habbie/auth-loglevel-prefix

auth: add loglevel-show setting

docs/settings.rst

@@ -974,6 +974,18 @@ Corresponds to "syslog" level values (e.g. 0 = emergency, 1 = alert, 2 = critica
 Each level includes itself plus the lower levels before it.
 Not recommended to set this below 3.
 
+.. _setting-loglevel-show:
+
+``loglevel-show``
+-------------------
+
+-  Bool
+-  Default: no
+
+.. versionadded:: 4.9.0
+
+When enabled, log messages are formatted like structured logs, including their log level/priority: ``msg="Unable to launch, no backends configured for querying" prio="Error"``
+
 .. _setting-lua-axfr-script:
 
 ``lua-axfr-script``

pdns/auth-main.cc

@@ -192,6 +192,7 @@ static void declareArguments()
   ::arg().set("version-string", "PowerDNS version in packets - full, anonymous, powerdns or custom") = "full";
   ::arg().set("control-console", "Debugging switch - don't use") = "no"; // but I know you will!
   ::arg().set("loglevel", "Amount of logging. Higher is more. Do not set below 3") = "4";
+  ::arg().setSwitch("loglevel-show", "Include log level indicator in log output") = "no";
   ::arg().set("disable-syslog", "Disable logging to syslog, useful when running inside a supervisor that logs stdout") = "no";
   ::arg().set("log-timestamp", "Print timestamps in log lines") = "yes";
   ::arg().set("distributor-threads", "Default number of Distributor (backend) threads to start") = "3";
@@ -1243,6 +1244,7 @@ int main(int argc, char** argv)
     ::arg().set("domain-metadata-cache-ttl") = ::arg()["zone-metadata-cache-ttl"];
 
     g_log.setLoglevel((Logger::Urgency)(::arg().asNum("loglevel")));
+    g_log.setPrefixed(::arg().mustDo("loglevel-show"));
     g_log.disableSyslog(::arg().mustDo("disable-syslog"));
     g_log.setTimestamps(::arg().mustDo("log-timestamp"));
     g_log.toConsole((Logger::Urgency)(::arg().asNum("loglevel")));

pdns/logger.cc

@@ -19,10 +19,12 @@
  * along with this program; if not, write to the Free Software
  * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
  */
+#include <ostream>
 #ifdef HAVE_CONFIG_H
 #include "config.h"
 #endif
 
+#include <iomanip>
 #include <mutex>
 
 #include "logger.hh"
@@ -56,53 +58,65 @@ void Logger::log(const string& msg, Urgency u) noexcept
   bool mustAccount(false);
 #endif
   if (u <= consoleUrgency) {
-    char buffer[50] = "";
+    std::array<char, 50> buffer{};
+    buffer[0] = '\0';
     if (d_timestamps) {
       struct tm tm;
       time_t t;
       time(&t);
       localtime_r(&t, &tm);
-      if (strftime(buffer, sizeof(buffer), "%b %d %H:%M:%S ", &tm) == 0) {
+      if (strftime(buffer.data(), buffer.size(), "%b %d %H:%M:%S ", &tm) == 0) {
         buffer[0] = '\0';
       }
     }
 
-    string prefix;
+    string severity;
     if (d_prefixed) {
       switch (u) {
       case All:
-        prefix = "[all] ";
+        severity = "All";
         break;
       case Alert:
-        prefix = "[ALERT] ";
+        severity = "Alert";
         break;
       case Critical:
-        prefix = "[CRITICAL] ";
+        severity = "Critical";
         break;
       case Error:
-        prefix = "[ERROR] ";
+        severity = "Error";
         break;
       case Warning:
-        prefix = "[WARNING] ";
+        severity = "Warning";
         break;
       case Notice:
-        prefix = "[NOTICE] ";
+        severity = "Notice";
         break;
       case Info:
-        prefix = "[INFO] ";
+        severity = "Info";
         break;
       case Debug:
-        prefix = "[DEBUG] ";
+        severity = "Debug";
         break;
       case None:
-        prefix = "[none] ";
+        severity = "None";
         break;
       }
     }
 
-    static std::mutex m;
-    std::lock_guard<std::mutex> l(m); // the C++-2011 spec says we need this, and OSX actually does
-    clog << string(buffer) + prefix + msg << endl;
+    static std::mutex mutex;
+    std::lock_guard<std::mutex> lock(mutex); // the C++-2011 spec says we need this, and OSX actually does
+
+    // To avoid issuing multiple syscalls, we write the complete line to clog with a single << call.
+    // For that we need a buffer allocated, we might want to use writev(2) one day to avoid that.
+    ostringstream line;
+    line << buffer.data();
+    if (d_prefixed) {
+      line << "msg=" << std::quoted(msg) << " prio=" << std::quoted(severity) << endl;
+    }
+    else {
+      line << msg << endl;
+    }
+    clog << line.str() << std::flush;
 #ifndef RECURSOR
     mustAccount = true;
 #endif

pdns/logger.hh

@@ -156,7 +156,7 @@ private:
   bool opened;
   bool d_disableSyslog;
   bool d_timestamps{true};
-  bool d_prefixed{false};
+  bool d_prefixed{false}; // this used to prefix the loglevel, but now causes formatting like structured logging
 };
 
 Logger& getLogger();