Some more conversions to structured logging

diff --git a/pdns/logging.hh b/pdns/logging.hh
index d8ff96a2d78fbd2e918e8cf0923f22966ca1e541..75a7ac48b7f4e1a416e977129c7a8b65aa3e51cd 100644 (file)
--- a/pdns/logging.hh
+++ b/pdns/logging.hh
@@ -73,6 +73,8 @@ template <>
 std::string Loggable<std::string>::to_string() const;
 template <>
 std::string Loggable<std::vector<std::string>>::to_string() const;
+template <>
+std::string Loggable<std::set<int>>::to_string() const;
 
 // Loggable<std::string>::Loggable(const std::string& v): _t(v) {}
 

diff --git a/pdns/recursordist/logging.cc b/pdns/recursordist/logging.cc
index f6083df59c5bbc656fe3069db5cca1799d1ea75d..6ac2bcc4dc7d4d4e3fe6fd9d7d7f3133b1b9b6e4 100644 (file)
--- a/pdns/recursordist/logging.cc
+++ b/pdns/recursordist/logging.cc
@@ -143,6 +143,23 @@ std::string Loggable<std::vector<std::string>>::to_string() const
   return oss.str();
 }
 
+template <>
+std::string Loggable<std::set<int>>::to_string() const
+{
+  std::ostringstream oss;
+  bool first = true;
+  for (const auto& e : _t) {
+    if (!first) {
+      oss << ' ';
+    }
+    else {
+      first = false;
+    }
+    oss << e;
+  }
+  return oss.str();
+}
+
 std::shared_ptr<Logr::Logger> Logger::withName(const std::string& name) const
 {
   std::shared_ptr<Logger> res;

diff --git a/pdns/recursordist/rec-main.cc b/pdns/recursordist/rec-main.cc
index 9adb6a4afc3a9c7e3e4ef4fcc5491a97ce1121dd..06e4c86a013119f03baf506271bbe9bbe44a3c06 100644 (file)
--- a/pdns/recursordist/rec-main.cc
+++ b/pdns/recursordist/rec-main.cc
@@ -111,14 +111,15 @@ unsigned int RecThreadInfo::s_numDistributorThreads;
 unsigned int RecThreadInfo::s_numWorkerThreads;
 thread_local unsigned int RecThreadInfo::t_id;
 
-static std::map<unsigned int, std::set<int>> parseCPUMap()
+static std::map<unsigned int, std::set<int>> parseCPUMap(std::shared_ptr<Logr::Logger>& log)
 {
   std::map<unsigned int, std::set<int>> result;
 
   const std::string value = ::arg()["cpu-map"];
 
   if (!value.empty() && !isSettingThreadCPUAffinitySupported()) {
-    g_log << Logger::Warning << "CPU mapping requested but not supported, skipping" << endl;
+    SLOG(g_log << Logger::Warning << "CPU mapping requested but not supported, skipping" << endl,
+         log->info(Logr::Warning, "CPU mapping requested but not supported, skipping"));
     return result;
   }
 
@@ -147,14 +148,15 @@ static std::map<unsigned int, std::set<int>> parseCPUMap()
       }
     }
     catch (const std::exception& e) {
-      g_log << Logger::Error << "Error parsing cpu-map entry '" << part << "': " << e.what() << endl;
+      SLOG(g_log << Logger::Error << "Error parsing cpu-map entry '" << part << "': " << e.what() << endl,
+           log->error(Logr::Error, e.what(), "Error parsing cpu-map entry", "entry", Logging::Loggable(part)));
     }
   }
 
   return result;
 }
 
-static void setCPUMap(const std::map<unsigned int, std::set<int>>& cpusMap, unsigned int n, pthread_t tid)
+static void setCPUMap(const std::map<unsigned int, std::set<int>>& cpusMap, unsigned int n, pthread_t tid, std::shared_ptr<Logr::Logger>& log)
 {
   const auto& cpuMapping = cpusMap.find(n);
   if (cpuMapping == cpusMap.cend()) {
@@ -162,24 +164,34 @@ static void setCPUMap(const std::map<unsigned int, std::set<int>>& cpusMap, unsi
   }
   int rc = mapThreadToCPUList(tid, cpuMapping->second);
   if (rc == 0) {
-    g_log << Logger::Info << "CPU affinity for thread " << n << " has been set to CPU map:";
-    for (const auto cpu : cpuMapping->second) {
-      g_log << Logger::Info << " " << cpu;
+    if (!g_slogStructured) {
+      g_log << Logger::Info << "CPU affinity for thread " << n << " has been set to CPU map:";
+      for (const auto cpu : cpuMapping->second) {
+        g_log << Logger::Info << " " << cpu;
+      }
+      g_log << Logger::Info << endl;
+    }
+    else {
+      log->info(Logr::Info,  "CPU affinity has been set", "thread", Logging::Loggable(n), "cpumap", Logging::Loggable(cpuMapping->second));
     }
-    g_log << Logger::Info << endl;
   }
   else {
-    g_log << Logger::Warning << "Error setting CPU affinity for thread " << n << " to CPU map:";
-    for (const auto cpu : cpuMapping->second) {
-      g_log << Logger::Info << " " << cpu;
+    if (!g_slogStructured) {
+      g_log << Logger::Warning << "Error setting CPU affinity for thread " << n << " to CPU map:";
+      for (const auto cpu : cpuMapping->second) {
+        g_log << Logger::Info << " " << cpu;
+      }
+      g_log << Logger::Info << ' ' << strerror(rc) << endl;
+    }
+    else {
+      log->info(Logr::Warning, "Error setting CPU affinity", "thread", Logging::Loggable(n), "cpumap", Logging::Loggable(cpuMapping->second));
     }
-    g_log << Logger::Info << ' ' << strerror(rc) << endl;
   }
 }
 
 static void recursorThread();
 
-void RecThreadInfo::start(unsigned int id, const string& tname, const std::map<unsigned int, std::set<int>>& cpusMap)
+void RecThreadInfo::start(unsigned int id, const string& tname, const std::map<unsigned int, std::set<int>>& cpusMap, std::shared_ptr<Logr::Logger>& log)
 {
   name = tname;
   thread = std::thread([id, tname] {
@@ -188,14 +200,14 @@ void RecThreadInfo::start(unsigned int id, const string& tname, const std::map<u
     setThreadName(threadPrefix + tname);
     recursorThread();
   });
-  setCPUMap(cpusMap, id, thread.native_handle());
+  setCPUMap(cpusMap, id, thread.native_handle(), log);
 }
 
 int RecThreadInfo::runThreads(std::shared_ptr<Logr::Logger>& log)
 {
   int ret = EXIT_SUCCESS;
   unsigned int currentThreadId = 1;
-  const auto cpusMap = parseCPUMap();
+  const auto cpusMap = parseCPUMap(log);
 
   if (RecThreadInfo::numDistributors() + RecThreadInfo::numWorkers() == 1) {
     SLOG(g_log << Logger::Warning << "Operating with single distributor/worker thread" << endl,
@@ -204,10 +216,10 @@ int RecThreadInfo::runThreads(std::shared_ptr<Logr::Logger>& log)
     /* This thread handles the web server, carbon, statistics and the control channel */
     auto& handlerInfo = RecThreadInfo::info(0);
     handlerInfo.setHandler();
-    handlerInfo.start(0, "web+stat", cpusMap);
+    handlerInfo.start(0, "web+stat", cpusMap, log);
     auto& taskInfo = RecThreadInfo::info(2);
     taskInfo.setTaskThread();
-    taskInfo.start(2, "taskThread", cpusMap);
+    taskInfo.start(2, "taskThread", cpusMap, log);
 
     auto& info = RecThreadInfo::info(currentThreadId);
     info.setListener();
@@ -248,7 +260,7 @@ int RecThreadInfo::runThreads(std::shared_ptr<Logr::Logger>& log)
            log->info(Logr::Notice, "Launching distributor threads", "count", Logging::Loggable(RecThreadInfo::numDistributors())));
       for (unsigned int n = 0; n < RecThreadInfo::numDistributors(); ++n) {
         auto& info = RecThreadInfo::info(currentThreadId);
-        info.start(currentThreadId++, "distr", cpusMap);
+        info.start(currentThreadId++, "distr", cpusMap, log);
       }
     }
     SLOG(g_log << Logger::Warning << "Launching " << RecThreadInfo::numWorkers() << " worker threads" << endl,
@@ -256,18 +268,18 @@ int RecThreadInfo::runThreads(std::shared_ptr<Logr::Logger>& log)
 
     for (unsigned int n = 0; n < RecThreadInfo::numWorkers(); ++n) {
       auto& info = RecThreadInfo::info(currentThreadId);
-      info.start(currentThreadId++, "worker", cpusMap);
+      info.start(currentThreadId++, "worker", cpusMap, log);
     }
 
     for (unsigned int n = 0; n < RecThreadInfo::numTaskThreads(); ++n) {
       auto& info = RecThreadInfo::info(currentThreadId);
-      info.start(currentThreadId++, "taskThread", cpusMap);
+      info.start(currentThreadId++, "taskThread", cpusMap, log);
     }
 
     /* This thread handles the web server, carbon, statistics and the control channel */
     auto& info = RecThreadInfo::info(0);
     info.setHandler();
-    info.start(0, "web+stat", cpusMap);
+    info.start(0, "web+stat", cpusMap, log);
 
     for (auto& ti : RecThreadInfo::infos()) {
       ti.thread.join();
@@ -279,11 +291,12 @@ int RecThreadInfo::runThreads(std::shared_ptr<Logr::Logger>& log)
   return ret;
 }
 
-void RecThreadInfo::makeThreadPipes()
+void RecThreadInfo::makeThreadPipes(std::shared_ptr<Logr::Logger>& log)
 {
   auto pipeBufferSize = ::arg().asNum("distribution-pipe-buffer-size");
   if (pipeBufferSize > 0) {
-    g_log << Logger::Info << "Resizing the buffer of the distribution pipe to " << pipeBufferSize << endl;
+    SLOG(g_log << Logger::Info << "Resizing the buffer of the distribution pipe to " << pipeBufferSize << endl,
+         log->info(Logr::Info, "Resizing the buffer of the distribution pipe", "size", Logging::Loggable(pipeBufferSize)));
   }
 
   /* thread 0 is the handler / SNMP, worker threads start at 1 */
@@ -317,10 +330,12 @@ void RecThreadInfo::makeThreadPipes()
     if (pipeBufferSize > 0) {
       if (!setPipeBufferSize(threadInfo.pipes.writeQueriesToThread, pipeBufferSize)) {
         int err = errno;
-        g_log << Logger::Warning << "Error resizing the buffer of the distribution pipe for thread " << n << " to " << pipeBufferSize << ": " << strerror(err) << endl;
+        SLOG(g_log << Logger::Warning << "Error resizing the buffer of the distribution pipe for thread " << n << " to " << pipeBufferSize << ": " << strerror(err) << endl,
+             log->error(Logr::Warning, err, "Error resizing the buffer of the distribution pipe for thread", "thread", Logging::Loggable(n), "size", Logging::Loggable(pipeBufferSize)));
         auto existingSize = getPipeBufferSize(threadInfo.pipes.writeQueriesToThread);
         if (existingSize > 0) {
-          g_log << Logger::Warning << "The current size of the distribution pipe's buffer for thread " << n << " is " << existingSize << endl;
+          SLOG(g_log << Logger::Warning << "The current size of the distribution pipe's buffer for thread " << n << " is " << existingSize << endl,
+               log->info(Logr::Warning, "The current size of the distribution pipe's buffer for thread", "thread", Logging::Loggable(n), "size", Logging::Loggable(existingSize)));
         }
       }
     }
@@ -1756,7 +1771,7 @@ static int serviceMain(int argc, char* argv[], std::shared_ptr<Logr::Logger>& lo
   startLuaConfigDelayedThreads(delayedLuaThreads, g_luaconfs.getCopy().generation);
   delayedLuaThreads.rpzPrimaryThreads.clear(); // no longer needed
 
-  RecThreadInfo::makeThreadPipes();
+  RecThreadInfo::makeThreadPipes(log);
 
   g_tcpTimeout = ::arg().asNum("client-tcp-timeout");
   g_maxTCPPerClient = ::arg().asNum("max-tcp-per-client");

diff --git a/pdns/recursordist/rec-main.hh b/pdns/recursordist/rec-main.hh
index 7ee40a64e06eee682fd61a101f642f51cefebeb4..7fe9a1568d82fed33d78834d8ba9e621ef1430b3 100644 (file)
--- a/pdns/recursordist/rec-main.hh
+++ b/pdns/recursordist/rec-main.hh
@@ -447,7 +447,7 @@ public:
   }
 
   static int runThreads(std::shared_ptr<Logr::Logger>&);
-  static void makeThreadPipes();
+  static void makeThreadPipes(std::shared_ptr<Logr::Logger>&);
 
   void setExitCode(int e)
   {
@@ -468,7 +468,7 @@ public:
   uint64_t numberOfDistributedQueries{0};
 
 private:
-  void start(unsigned int id, const string& name, const std::map<unsigned int, std::set<int>>& cpusMap);
+  void start(unsigned int id, const string& name, const std::map<unsigned int, std::set<int>>& cpusMap, std::shared_ptr<Logr::Logger>&);
 
   std::string name;
   std::thread thread;
@@ -480,7 +480,7 @@ private:
   bool listener{false};
   // process queries
   bool worker{false};
-  // run async tasks: from TastQueue and ZoneToCache
+  // run async tasks: from TaskQueue and ZoneToCache
   bool taskThread{false};
 
   static thread_local unsigned int t_id;

diff --git a/pdns/reczones.cc b/pdns/reczones.cc
index 228e70d094fb1e40ba1a7b9def8b7de78dd2304b..091a706bf3f3a779e10332de66479b270fb13697 100644 (file)
--- a/pdns/reczones.cc
+++ b/pdns/reczones.cc
@@ -53,9 +53,11 @@ bool primeHints(time_t ignored)
 
   time_t now = time(nullptr);
 
+  auto log = g_slog->withName("config");
   const string hintfile = ::arg()["hint-file"];
   if (hintfile == "no") {
-    g_log << Logger::Debug << "Priming root disabled by hint-file=no" << endl;
+    SLOG(g_log << Logger::Debug << "Priming root disabled by hint-file=no" << endl,
+         log->info(Logr::Debug, "Priming root disabled by hint-file=no"));
     return true;
   }
   if (hintfile.empty()) {
@@ -146,7 +148,6 @@ bool primeHints(time_t ignored)
         break;
       }
     }
-    auto log = g_slog->withName("config");
     if (SyncRes::s_doIPv4 && !SyncRes::s_doIPv6 && !reachableA) {
       SLOG(g_log << Logger::Error << "Running IPv4 only but no IPv4 root hints" << endl,
            log->info(Logr::Error, "Running IPv4 only but no IPv4 root hints"));
@@ -546,7 +547,8 @@ std::tuple<std::shared_ptr<SyncRes::domainmap_t>, std::shared_ptr<notifyset_t>>
 
     ifstream ifs(fname.c_str());
     if (!ifs) {
-      g_log << Logger::Warning << "Could not open " << fname << " for reading" << endl;
+      SLOG(g_log << Logger::Warning << "Could not open " << fname << " for reading" << endl,
+           log->error(Logr::Warning,  "Could not open file for reading", "file", Logging::Loggable(fname)));
     }
     else {
       string searchSuffix = ::arg()["export-etc-hosts-search-suffix"];
@@ -602,7 +604,8 @@ std::tuple<std::shared_ptr<SyncRes::domainmap_t>, std::shared_ptr<notifyset_t>>
   }
 
   if (auto anff = ::arg()["allow-notify-for-file"]; !anff.empty()) {
-    g_log << Logger::Warning << "Reading NOTIFY-allowed zones from '" << anff << "'" << endl;
+    SLOG(g_log << Logger::Warning << "Reading NOTIFY-allowed zones from '" << anff << "'" << endl,
+         log->info(Logr::Notice, "Reading NOTIFY-allowed zones from file", "file", Logging::Loggable(anff)));
     auto fp = std::unique_ptr<FILE, int (*)(FILE*)>(fopen(anff.c_str(), "r"), fclose);
     if (!fp) {
       throw PDNSException("Error opening allow-notify-for-file '" + anff + "': " + stringerror());