Move housekeeping and associated code to strcutured logging

diff --git a/pdns/rec-lua-conf.cc b/pdns/rec-lua-conf.cc
index 305afe588a03ea0633531b7272d8b2713fa66673..cc80775ca9b0b83536577929c205b6c6bd847826 100644 (file)
--- a/pdns/rec-lua-conf.cc
+++ b/pdns/rec-lua-conf.cc
@@ -583,10 +583,11 @@ void loadRecursorLuaConfig(const std::string& fname, luaConfigDelayedThreads& de
     if (interval) {
       realInterval = static_cast<uint32_t>(*interval);
     }
+    auto log = g_slog->withName("config");
     warnIfDNSSECDisabled("Warning: reading Trust Anchors from file (readTrustAnchorsFromFile), but dnssec is set to 'off'!");
     lci.trustAnchorFileInfo.fname = fnamearg;
     lci.trustAnchorFileInfo.interval = realInterval;
-    updateTrustAnchorsFromFile(fnamearg, lci.dsAnchors);
+    updateTrustAnchorsFromFile(fnamearg, lci.dsAnchors, log);
   });
 
   Lua->writeFunction("setProtobufMasks", [&lci](const uint8_t maskV4, uint8_t maskV6) {

diff --git a/pdns/recursordist/rec-main.cc b/pdns/recursordist/rec-main.cc
index b8b6b3e65f629af17d66fefc9daa506e597427d9..fbc5eacd670f65d0e2bbaba1f42c462188cf14f0 100644 (file)
--- a/pdns/recursordist/rec-main.cc
+++ b/pdns/recursordist/rec-main.cc
@@ -1949,6 +1949,7 @@ private:
 
 static void houseKeeping(void*)
 {
+  auto log = g_slog->withName("housekeeping");
   static thread_local bool t_running; // houseKeeping can get suspended in secpoll, and be restarted, which makes us do duplicate work
 
   try {
@@ -2051,8 +2052,8 @@ static void houseKeeping(void*)
       // By default, refresh at 80% of max-cache-ttl with a minimum period of 10s
       const unsigned int minRootRefreshInterval = 10;
       static PeriodicTask rootUpdateTask{"rootUpdateTask", std::max(SyncRes::s_maxcachettl * 8 / 10, minRootRefreshInterval)};
-      rootUpdateTask.runIfDue(now, [=]() {
-        int res = SyncRes::getRootNS(now, nullptr, 0);
+      rootUpdateTask.runIfDue(now, [now, &log, minRootRefreshInterval]() {
+        int res = SyncRes::getRootNS(now, nullptr, 0, log);
         if (res == 0) {
           // Success, go back to the defaut period
           rootUpdateTask.setPeriod(std::max(SyncRes::s_maxcachettl * 8 / 10, minRootRefreshInterval));
@@ -2060,19 +2061,24 @@ static void houseKeeping(void*)
             primeRootNSZones(g_dnssecmode, 0);
           }
           catch (const std::exception& e) {
-            g_log << Logger::Error << "Exception while priming the root NS zones: " << e.what() << endl;
+            SLOG(g_log << Logger::Error << "Exception while priming the root NS zones: " << e.what() << endl,
+                 log->error(Logr::Error, e.what(), "Exception while priming the root NS zones"));
           }
           catch (const PDNSException& e) {
-            g_log << Logger::Error << "Exception while priming the root NS zones: " << e.reason << endl;
+            SLOG(g_log << Logger::Error << "Exception while priming the root NS zones: " << e.reason << endl,
+                 log->error(Logr::Error, e.reason, "Exception while priming the root NS zones"));
           }
           catch (const ImmediateServFailException& e) {
-            g_log << Logger::Error << "Exception while priming the root NS zones: " << e.reason << endl;
+            SLOG(g_log << Logger::Error << "Exception while priming the root NS zones: " << e.reason << endl,
+                 log->error(Logr::Error, e.reason, "Exception while priming the root NS zones"));
           }
           catch (const PolicyHitException& e) {
-            g_log << Logger::Error << "Policy hit while priming the root NS zones" << endl;
+            SLOG(g_log << Logger::Error << "Policy hit while priming the root NS zones" << endl,
+                 log->info(Logr::Error, "Policy hit while priming the root NS zones"));
           }
           catch (...) {
-            g_log << Logger::Error << "Exception while priming the root NS zones" << endl;
+            SLOG(g_log << Logger::Error << "Exception while priming the root NS zones" << endl,
+                 log->info(Logr::Error, "Exception while priming the root NS zones"));
           }
         }
         else {
@@ -2085,24 +2091,29 @@ static void houseKeeping(void*)
 
       static PeriodicTask secpollTask{"secpollTask", 3600};
       static time_t t_last_secpoll;
-      secpollTask.runIfDue(now, []() {
+      secpollTask.runIfDue(now, [&log]() {
         try {
-          doSecPoll(&t_last_secpoll);
+          doSecPoll(&t_last_secpoll, log);
         }
         catch (const std::exception& e) {
-          g_log << Logger::Error << "Exception while performing security poll: " << e.what() << endl;
+          SLOG(g_log << Logger::Error << "Exception while performing security poll: " << e.what() << endl,
+               log->error(Logr::Error, e.what(), "Exception while performing security poll"));
         }
         catch (const PDNSException& e) {
-          g_log << Logger::Error << "Exception while performing security poll: " << e.reason << endl;
+          SLOG(g_log << Logger::Error << "Exception while performing security poll: " << e.reason << endl,
+               log->error(Logr::Error, e.reason, "Exception while performing security poll"));
         }
         catch (const ImmediateServFailException& e) {
-          g_log << Logger::Error << "Exception while performing security poll: " << e.reason << endl;
+          SLOG(g_log << Logger::Error << "Exception while performing security poll: " << e.reason << endl,
+               log->error(Logr::Error, e.reason, "Exception while performing security poll"));
         }
         catch (const PolicyHitException& e) {
-          g_log << Logger::Error << "Policy hit while performing security poll" << endl;
+          SLOG(g_log << Logger::Error << "Policy hit while performing security poll" << endl,
+               log->info(Logr::Error, "Policy hit while performing security poll"));
         }
         catch (...) {
-          g_log << Logger::Error << "Exception while performing security poll" << endl;
+          SLOG(g_log << Logger::Error << "Exception while performing security poll" << endl,
+               log->info(Logr::Error, "Exception while performing security poll"));
         }
       });
 
@@ -2114,19 +2125,21 @@ static void houseKeeping(void*)
       }
       // interval might have ben updated
       trustAnchorTask.setPeriod(std::max(1U, luaconfsLocal->trustAnchorFileInfo.interval) * 3600);
-      trustAnchorTask.runIfDue(now, [&luaconfsLocal]() {
+      trustAnchorTask.runIfDue(now, [&luaconfsLocal, &log]() {
         if (!luaconfsLocal->trustAnchorFileInfo.fname.empty() && luaconfsLocal->trustAnchorFileInfo.interval != 0) {
-          g_log << Logger::Debug << "Refreshing Trust Anchors from file" << endl;
+          SLOG(g_log << Logger::Debug << "Refreshing Trust Anchors from file" << endl,
+               log->info(Logr::Debug, "Refreshing Trust Anchors from file"));
           try {
             map<DNSName, dsmap_t> dsAnchors;
-            if (updateTrustAnchorsFromFile(luaconfsLocal->trustAnchorFileInfo.fname, dsAnchors)) {
+            if (updateTrustAnchorsFromFile(luaconfsLocal->trustAnchorFileInfo.fname, dsAnchors, log)) {
               g_luaconfs.modify([&dsAnchors](LuaConfigItems& lci) {
                 lci.dsAnchors = dsAnchors;
               });
             }
           }
           catch (const PDNSException& pe) {
-            g_log << Logger::Error << "Unable to update Trust Anchors: " << pe.reason << endl;
+            SLOG(g_log << Logger::Error << "Unable to update Trust Anchors: " << pe.reason << endl,
+                 log->error(Logr::Error, pe.reason, "Unable to update Trust Anchors"));
           }
         }
       });
@@ -2135,12 +2148,14 @@ static void houseKeeping(void*)
   }
   catch (const PDNSException& ae) {
     t_running = false;
-    g_log << Logger::Error << "Fatal error in housekeeping thread: " << ae.reason << endl;
+    SLOG(g_log << Logger::Error << "Fatal error in housekeeping thread: " << ae.reason << endl,
+         log->error(Logr::Error, ae.reason, "Fatal error in housekeeping thread"));
     throw;
   }
   catch (...) {
     t_running = false;
-    g_log << Logger::Error << "Uncaught exception in housekeeping thread" << endl;
+    SLOG(g_log << Logger::Error << "Uncaught exception in housekeeping thread" << endl,
+         log->info(Logr::Error, "Uncaught exception in housekeeping thread"));
     throw;
   }
 }
@@ -2164,9 +2179,11 @@ static void recursorThread()
         if (!primeHints()) {
           threadInfo.setExitCode(EXIT_FAILURE);
           RecursorControlChannel::stop = 1;
-          g_log << Logger::Critical << "Priming cache failed, stopping" << endl;
+          SLOG(g_log << Logger::Critical << "Priming cache failed, stopping" << endl,
+               log->info(Logr::Critical, "Priming cache failed, stopping"));
         }
-        g_log << Logger::Debug << "Done priming cache with root hints" << endl;
+        SLOG(g_log << Logger::Debug << "Done priming cache with root hints" << endl,
+             log->info(Logr::Debug, "Done priming cache with root hints"));
       }
     }
 
@@ -2186,11 +2203,13 @@ static void recursorThread()
         if (!::arg()["lua-dns-script"].empty()) {
           t_pdl = std::make_shared<RecursorLua4>();
           t_pdl->loadFile(::arg()["lua-dns-script"]);
-          g_log << Logger::Warning << "Loaded 'lua' script from '" << ::arg()["lua-dns-script"] << "'" << endl;
+          SLOG(g_log << Logger::Warning << "Loaded 'lua' script from '" << ::arg()["lua-dns-script"] << "'" << endl,
+               log->info(Logr::Warning, "Loading Lua script from file", "name", Logging::Loggable(::arg()["lua-dns-script"])));
         }
       }
       catch (std::exception& e) {
-        g_log << Logger::Error << "Failed to load 'lua' script from '" << ::arg()["lua-dns-script"] << "': " << e.what() << endl;
+        SLOG(g_log << Logger::Error << "Failed to load 'lua' script from '" << ::arg()["lua-dns-script"] << "': " << e.what() << endl,
+             log->error(Logr::Error, e.what(), "Failed to load Lua script from file", "name", Logging::Loggable(::arg()["lua-dns-script"])));
         _exit(99);
       }
     }
@@ -2299,7 +2318,7 @@ static void recursorThread()
       // Use primes, it avoid not being scheduled in cases where the counter has a regular pattern.
       // We want to call handler thread often, it gets scheduled about 2 times per second
       if (((threadInfo.isHandler() || threadInfo.isTaskThread()) && s_counter % 11 == 0) || s_counter % 499 == 0) {
-        MT->makeThread(houseKeeping, 0);
+        MT->makeThread(houseKeeping, nullptr);
       }
 
       if (!(s_counter % 55)) {

diff --git a/pdns/secpoll-recursor.cc b/pdns/secpoll-recursor.cc
index 69618030f82c79e7e1c558d65342d9a6c0166738..be3d105d70dff26193b0d5f2ba20cf23ad527857 100644 (file)
--- a/pdns/secpoll-recursor.cc
+++ b/pdns/secpoll-recursor.cc
@@ -17,7 +17,7 @@
 uint32_t g_security_status;
 string g_security_message;
 
-void doSecPoll(time_t* last_secpoll)
+void doSecPoll(time_t* last_secpoll, std::shared_ptr<Logr::Logger>& log)
 {
   if (::arg()["security-poll-suffix"].empty())
     return;
@@ -55,15 +55,18 @@ void doSecPoll(time_t* last_secpoll)
     state = sr.getValidationState();
   }
 
+  auto vlog = log->withValues("version", Logging::Loggable(pkgv), "query", Logging::Loggable(query));
   if (vStateIsBogus(state)) {
-    g_log << Logger::Error << "Failed to retrieve security status update for '" + pkgv + "' on '" << query << "', DNSSEC validation result was Bogus!" << endl;
+    SLOG(g_log << Logger::Error << "Failed to retrieve security status update for '" + pkgv + "' on '" << query << "', DNSSEC validation result was Bogus!" << endl,
+         vlog->info(Logr::Error, "Failed to retrieve security status update", "validationResult", Logging::Loggable(vStateToString(state))));
     if (g_security_status == 1) // If we were OK, go to unknown
       g_security_status = 0;
     return;
   }
 
   if (res == RCode::NXDomain && !isReleaseVersion(pkgv)) {
-    g_log << Logger::Warning << "Not validating response for security status update, this is a non-release version" << endl;
+    SLOG(g_log << Logger::Warning << "Not validating response for security status update, this is a non-release version" << endl,
+         vlog->info(Logr::Warning, "Not validating response for security status update, this is a non-release version"));
     return;
   }
 
@@ -75,20 +78,25 @@ void doSecPoll(time_t* last_secpoll)
   }
   catch (const PDNSException& pe) {
     g_security_status = security_status;
-    g_log << Logger::Warning << "Failed to retrieve security status update for '" << pkgv << "' on '" << query << "': " << pe.reason << endl;
+    SLOG(g_log << Logger::Warning << "Failed to retrieve security status update for '" << pkgv << "' on '" << query << "': " << pe.reason << endl,
+         vlog->error(Logr::Warning, pe.reason, "Failed to retrieve security status update"));
     return;
   }
 
   g_security_message = security_message;
 
+  auto rlog = vlog->withValues("message", Logging::Loggable(g_security_message), "status", Logging::Loggable(security_status));
   if (g_security_status != 1 && security_status == 1) {
-    g_log << Logger::Warning << "Polled security status of version " << pkgv << ", no known issues reported: " << g_security_message << endl;
+    SLOG(g_log << Logger::Warning << "Polled security status of version " << pkgv << ", no known issues reported: " << g_security_message << endl,
+         rlog->info(Logr::Notice, "Polled security status of version, no known issues reported"));
   }
   if (security_status == 2) {
-    g_log << Logger::Error << "PowerDNS Security Update Recommended: " << g_security_message << endl;
+    SLOG(g_log << Logger::Error << "PowerDNS Security Update Recommended: " << g_security_message << endl,
+         rlog->info(Logr::Error, "PowerDNS Security Update Recommended"));
   }
   if (security_status == 3) {
-    g_log << Logger::Error << "PowerDNS Security Update Mandatory: " << g_security_message << endl;
+    SLOG(g_log << Logger::Error << "PowerDNS Security Update Mandatory: " << g_security_message << endl,
+         rlog->info(Logr::Error, "PowerDNS Security Update Mandatory"));
   }
 
   g_security_status = security_status;

diff --git a/pdns/secpoll-recursor.hh b/pdns/secpoll-recursor.hh
index 3a06d20e1c1a24b27e6e51eb7f67efd1377d48e1..cfa77fa32077335518086b8a7ebae3c4df4d5264 100644 (file)
--- a/pdns/secpoll-recursor.hh
+++ b/pdns/secpoll-recursor.hh
@@ -22,8 +22,9 @@
 #pragma once
 #include <time.h>
 #include "namespaces.hh"
+#include "logr.hh"
 #include <stdint.h>
 
-void doSecPoll(time_t*);
+void doSecPoll(time_t*, std::shared_ptr<Logr::Logger>&);
 extern uint32_t g_security_status;
 extern std::string g_security_message;

diff --git a/pdns/syncres.cc b/pdns/syncres.cc
index f0d0140b93e194733acdecb00d20b771a0752ebf..1c6ee2aa0fac017dad1f821f28d9ae75a9ae0f03 100644 (file)
--- a/pdns/syncres.cc
+++ b/pdns/syncres.cc
@@ -2164,7 +2164,8 @@ void SyncRes::getBestNSFromCache(const DNSName &qname, const QType qtype, vector
       /* let's prevent an infinite loop */
       if (!d_updatingRootNS) {
         primeRootNSZones(g_dnssecmode, depth);
-        getRootNS(d_now, d_asyncResolve, depth);
+        auto log = g_slog->withName("housekeeping");
+        getRootNS(d_now, d_asyncResolve, depth, log);
       }
     }
   } while(subdomain.chopOff());
@@ -5669,7 +5670,7 @@ int directResolve(const DNSName& qname, const QType qtype, const QClass qclass,
   return res;
 }
 
-int SyncRes::getRootNS(struct timeval now, asyncresolve_t asyncCallback, unsigned int depth) {
+int SyncRes::getRootNS(struct timeval now, asyncresolve_t asyncCallback, unsigned int depth, std::shared_ptr<Logr::Logger>& log) {
   SyncRes sr(now);
   sr.setDoEDNS0(true);
   sr.setUpdatingRootNS();
@@ -5706,7 +5707,8 @@ int SyncRes::getRootNS(struct timeval now, asyncresolve_t asyncCallback, unsigne
   }
 
   if (res == 0) {
-    g_log<<Logger::Debug<<"Refreshed . records"<<endl;
+    SLOG(g_log<<Logger::Debug<<"Refreshed . records"<<endl,
+         log->info(Logr::Debug, "Refreshed . records"));
   }
   else {
     g_log<<Logger::Warning<<"Failed to update root NS records, RCODE="<<res<<endl;

diff --git a/pdns/syncres.hh b/pdns/syncres.hh
index b77457d6a7176ffc9bc777612042ee7ca30b4833..a47365db72b16675777785088a8064bf6695f411 100644 (file)
--- a/pdns/syncres.hh
+++ b/pdns/syncres.hh
@@ -52,6 +52,7 @@
 #include "stat_t.hh"
 #include "tcpiohandler.hh"
 #include "rec-eventtrace.hh"
+#include "logr.hh"
 
 #ifdef HAVE_CONFIG_H
 #include "config.h"
@@ -183,7 +184,7 @@ public:
   static uint64_t doDumpSavedParentNSSets(int fd);
   static uint64_t doDumpDoTProbeMap(int fd);
 
-  static int getRootNS(struct timeval now, asyncresolve_t asyncCallback, unsigned int depth);
+  static int getRootNS(struct timeval now, asyncresolve_t asyncCallback, unsigned int depth, std::shared_ptr<Logr::Logger>&);
   static void addDontQuery(const std::string& mask)
   {
     if (!s_dontQuery)

diff --git a/pdns/validate-recursor.cc b/pdns/validate-recursor.cc
index 4c2bb1086a4c8d736eb54848b37ddfcc3f65f996..545b815ff08259147a910501f24176b25fae50fe 100644 (file)
--- a/pdns/validate-recursor.cc
+++ b/pdns/validate-recursor.cc
@@ -12,14 +12,17 @@ bool g_dnssecLogBogus;
 
 bool checkDNSSECDisabled()
 {
-  return warnIfDNSSECDisabled("");
+  return g_dnssecmode == DNSSECMode::Off;
 }
 
 bool warnIfDNSSECDisabled(const string& msg)
 {
   if (g_dnssecmode == DNSSECMode::Off) {
-    if (!msg.empty())
-      g_log << Logger::Warning << msg << endl;
+    if (!msg.empty()) {
+      auto log = g_slog->withName("config");
+      SLOG(g_log << Logger::Warning << msg << endl,
+           log->info(Logr::Warning, msg));
+    }
     return true;
   }
   return false;
@@ -38,7 +41,7 @@ vState increaseXDNSSECStateCounter(const vState& state)
 }
 
 // Returns true if dsAnchors were modified
-bool updateTrustAnchorsFromFile(const std::string& fname, map<DNSName, dsmap_t>& dsAnchors)
+bool updateTrustAnchorsFromFile(const std::string& fname, map<DNSName, dsmap_t>& dsAnchors, std::shared_ptr<Logr::Logger>& log)
 {
   map<DNSName, dsmap_t> newDSAnchors;
   try {
@@ -65,10 +68,12 @@ bool updateTrustAnchorsFromFile(const std::string& fname, map<DNSName, dsmap_t>&
       }
     }
     if (dsAnchors == newDSAnchors) {
-      g_log << Logger::Debug << "Read Trust Anchors from file, no changes detected" << endl;
+      SLOG(g_log << Logger::Debug << "Read Trust Anchors from file, no changes detected" << endl,
+           log->info(Logr::Debug, "Read Trust Anchors from file, no changes detected"));
       return false;
     }
-    g_log << Logger::Info << "Read changed Trust Anchors from file, updating" << endl;
+    SLOG(g_log << Logger::Info << "Read changed Trust Anchors from file, updating" << endl,
+         log->info(Logr::Info, "Read changed Trust Anchors from file, updating"));
     dsAnchors = newDSAnchors;
     return true;
   }

diff --git a/pdns/validate-recursor.hh b/pdns/validate-recursor.hh
index 7e31c63c0b03a76450aa9bad207b6533ac29bbc4..a45304a47735149e33a48773e4db59dd88de167a 100644 (file)
--- a/pdns/validate-recursor.hh
+++ b/pdns/validate-recursor.hh
@@ -22,7 +22,7 @@
 #pragma once
 #include "namespaces.hh"
 #include "validate.hh"
-#include "logger.hh"
+#include "logging.hh"
 
 /* Off: 3.x behaviour, we do no DNSSEC, no EDNS
    ProcessNoValidate: we gather DNSSEC records on all queries, but we will never validate
@@ -46,4 +46,4 @@ bool checkDNSSECDisabled();
 bool warnIfDNSSECDisabled(const string& msg);
 vState increaseDNSSECStateCounter(const vState& state);
 vState increaseXDNSSECStateCounter(const vState& state);
-bool updateTrustAnchorsFromFile(const std::string& fname, map<DNSName, dsmap_t>& dsAnchors);
+bool updateTrustAnchorsFromFile(const std::string& fname, map<DNSName, dsmap_t>& dsAnchors, std::shared_ptr<Logr::Logger>&);