From: Otto Moerbeek <otto.moerbeek@open-xchange.com>
Date: Wed, 1 Jun 2022 14:34:10 +0000 (+0200)
Subject: Move RPZ, dnstap and protobuf subsystems  to structured logging,
X-Git-Tag: auth-4.8.0-alpha0~69^2~3
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=62b191dc9eec20c519dfe07c5d71675d2118678d;p=thirdparty%2Fpdns.git

Move RPZ, dnstap and protobuf subsystems  to structured logging,

Plus a few remaining cases for startup abnd config.
---

diff --git a/pdns/fstrm_logger.cc b/pdns/fstrm_logger.cc
index 6e608cbeea..c5339d645f 100644
--- a/pdns/fstrm_logger.cc
+++ b/pdns/fstrm_logger.cc
@@ -6,6 +6,7 @@
 
 #ifdef RECURSOR
 #include "logger.hh"
+#include "logging.hh"
 #else
 #include "dolog.hh"
 #endif
@@ -165,7 +166,8 @@ void FrameStreamLogger::queueData(const std::string& data)
   uint8_t *frame = (uint8_t*)malloc(data.length());
   if (!frame) {
 #ifdef RECURSOR
-    g_log<<Logger::Warning<<"FrameStreamLogger: cannot allocate memory for stream."<<std::endl;
+    SLOG(g_log<<Logger::Warning<<"FrameStreamLogger: cannot allocate memory for stream."<<std::endl,
+         g_slog->withName("dnstap")->info(Logr::Warning, "cannot allocate memory for stream"));
 #else
     warnlog("FrameStreamLogger: cannot allocate memory for stream.");
 #endif
@@ -182,7 +184,8 @@ void FrameStreamLogger::queueData(const std::string& data)
   } else if (res == fstrm_res_again) {
     free(frame);
 #ifdef RECURSOR
-    g_log<<Logger::Debug<<"FrameStreamLogger: queue full, dropping."<<std::endl;
+    SLOG(g_log<<Logger::Debug<<"FrameStreamLogger: queue full, dropping."<<std::endl,
+         g_slog->withName("dnstap")->info(Logr::Debug, "queue full, dropping"));
 #else
     vinfolog("FrameStreamLogger: queue full, dropping.");
 #endif
@@ -191,7 +194,8 @@ void FrameStreamLogger::queueData(const std::string& data)
     // Permanent failure.
     free(frame);
 #ifdef RECURSOR
-    g_log<<Logger::Warning<<"FrameStreamLogger: submitting to queue failed."<<std::endl;
+    SLOG(g_log<<Logger::Warning<<"FrameStreamLogger: submitting to queue failed."<<std::endl,
+         g_slog->withName("dnstap")->info(Logr::Warning, "submitting to queue failed"));
 #else
     warnlog("FrameStreamLogger: submitting to queue failed.");
 #endif
diff --git a/pdns/pdns_recursor.cc b/pdns/pdns_recursor.cc
index e888a88da9..e6658bbeac 100644
--- a/pdns/pdns_recursor.cc
+++ b/pdns/pdns_recursor.cc
@@ -2345,7 +2345,8 @@ void makeUDPServerSockets(deferredAdd_t& deferredAdds, Logr::log_t log)
       setSocketReceiveBuffer(fd, 250000);
     }
     catch (const std::exception& e) {
-      g_log << Logger::Error << e.what() << endl;
+      SLOG(g_log << Logger::Error << e.what() << endl,
+           log->error(Logr::Error, e.what(), "Exception while setting socker buffer size"));
     }
     sin.sin4.sin_port = htons(st.port);
 
diff --git a/pdns/rec-lua-conf.cc b/pdns/rec-lua-conf.cc
index cc80775ca9..193add8023 100644
--- a/pdns/rec-lua-conf.cc
+++ b/pdns/rec-lua-conf.cc
@@ -252,7 +252,8 @@ static void rpzPrimary(LuaConfigItems& lci, luaConfigDelayedThreads& delayedThre
       if (have.count("refresh")) {
         refresh = boost::get<uint32_t>(have["refresh"]);
         if (refresh == 0) {
-          g_log << Logger::Warning << "rpzPrimary refresh value of 0 ignored" << endl;
+          SLOG(g_log << Logger::Warning << "rpzPrimary refresh value of 0 ignored" << endl,
+               lci.d_slog->info(Logr::Warning, "rpzPrimary refresh value of 0 ignored"));
         }
       }
 
@@ -291,8 +292,10 @@ static void rpzPrimary(LuaConfigItems& lci, luaConfigDelayedThreads& delayedThre
     zone->setName(polName);
     zoneIdx = lci.dfe.addZone(zone);
 
+    auto log =  lci.d_slog->withValues("seedfile", Logging::Loggable(seedFile), "zone",  Logging::Loggable(zoneName));
     if (!seedFile.empty()) {
-      g_log << Logger::Info << "Pre-loading RPZ zone " << zoneName << " from seed file '" << seedFile << "'" << endl;
+      SLOG(g_log << Logger::Info << "Pre-loading RPZ zone " << zoneName << " from seed file '" << seedFile << "'" << endl,
+           log->info(Logr::Info, "Pre-loading RPZ zone from seed file"));
       try {
         sr = loadRPZFromFile(seedFile, zone, defpol, defpolOverrideLocal, maxTTL);
 
@@ -305,21 +308,25 @@ static void rpzPrimary(LuaConfigItems& lci, luaConfigDelayedThreads& delayedThre
         }
       }
       catch (const PDNSException& e) {
-        g_log << Logger::Warning << "Unable to pre-load RPZ zone " << zoneName << " from seed file '" << seedFile << "': " << e.reason << endl;
+        SLOG(g_log << Logger::Warning << "Unable to pre-load RPZ zone " << zoneName << " from seed file '" << seedFile << "': " << e.reason << endl,
+             log->error(Logr::Warning, e.reason, "Exception while pre-loadin RPZ zone", "exception", Logging::Loggable("PDNSException")));
         zone->clear();
       }
       catch (const std::exception& e) {
-        g_log << Logger::Warning << "Unable to pre-load RPZ zone " << zoneName << " from seed file '" << seedFile << "': " << e.what() << endl;
+        SLOG(g_log << Logger::Warning << "Unable to pre-load RPZ zone " << zoneName << " from seed file '" << seedFile << "': " << e.what() << endl,
+             log->error(Logr::Warning, e.what(), "Exception while pre-loadin RPZ zone", "exception", Logging::Loggable("std::exception")));
         zone->clear();
       }
     }
   }
   catch (const std::exception& e) {
-    g_log << Logger::Error << "Problem configuring 'rpzPrimary': " << e.what() << endl;
+    SLOG(g_log << Logger::Error << "Problem configuring 'rpzPrimary': " << e.what() << endl,
+         lci.d_slog->error(Logr::Critical, e.what(), "Exception configuring 'rpzPrimary'", "exception", Logging::Loggable("std::exception")));
     exit(1); // FIXME proper exit code?
   }
   catch (const PDNSException& e) {
-    g_log << Logger::Error << "Problem configuring 'rpzPrimary': " << e.reason << endl;
+    SLOG(g_log << Logger::Error << "Problem configuring 'rpzPrimary': " << e.reason << endl,
+         lci.d_slog->error(Logr::Critical, e.reason, "Exception configuring 'rpzPrimary'", Logging::Loggable("PDNSException")));
     exit(1); // FIXME proper exit code?
   }
 
@@ -357,6 +364,7 @@ public:
 void loadRecursorLuaConfig(const std::string& fname, luaConfigDelayedThreads& delayedThreads, ProxyMapping& proxyMapping)
 {
   LuaConfigItems lci;
+  lci.d_slog = g_slog->withName("luaconfig");
 
   RecLuaConfigContext Lua;
 
@@ -386,6 +394,7 @@ void loadRecursorLuaConfig(const std::string& fname, luaConfigDelayedThreads& de
   Lua->writeVariable("Policy", pmap);
 
   Lua->writeFunction("rpzFile", [&lci](const string& filename, boost::optional<rpzOptions_t> options) {
+    auto log = lci.d_slog->withValues("file", Logging::Loggable(filename));
     try {
       boost::optional<DNSFilterEngine::Policy> defpol;
       bool defpolOverrideLocal = true;
@@ -396,19 +405,23 @@ void loadRecursorLuaConfig(const std::string& fname, luaConfigDelayedThreads& de
         auto& have = *options;
         parseRPZParameters(have, zone, polName, defpol, defpolOverrideLocal, maxTTL);
       }
-      g_log << Logger::Warning << "Loading RPZ from file '" << filename << "'" << endl;
+      SLOG(g_log << Logger::Warning << "Loading RPZ from file '" << filename << "'" << endl,
+           log->info(Logr::Info, "Loading RPZ from file"));
       zone->setName(polName);
       loadRPZFromFile(filename, zone, defpol, defpolOverrideLocal, maxTTL);
       lci.dfe.addZone(zone);
-      g_log << Logger::Warning << "Done loading RPZ from file '" << filename << "'" << endl;
+      SLOG(g_log << Logger::Warning << "Done loading RPZ from file '" << filename << "'" << endl,
+           log->info(Logr::Info,  "Done loading RPZ from file"));
     }
     catch (const std::exception& e) {
-      g_log << Logger::Error << "Unable to load RPZ zone from '" << filename << "': " << e.what() << endl;
+      SLOG(g_log << Logger::Error << "Unable to load RPZ zone from '" << filename << "': " << e.what() << endl,
+           log->error(Logr::Error, e.what(), "Exception while loadinf  RPZ zone from file"));
     }
   });
 
   Lua->writeFunction("rpzMaster", [&lci, &delayedThreads](const boost::variant<string, std::vector<std::pair<int, string>>>& primaries_, const string& zoneName, boost::optional<rpzOptions_t> options) {
-    g_log << Logger::Warning << "'rpzMaster' is deprecated and will be removed in a future release, use 'rpzPrimary' instead" << endl;
+    SLOG(g_log << Logger::Warning << "'rpzMaster' is deprecated and will be removed in a future release, use 'rpzPrimary' instead" << endl,
+         lci.d_slog->info(Logr::Warning, "'rpzMaster' is deprecated and will be removed in a future release, use 'rpzPrimary' instead"));
     rpzPrimary(lci, delayedThreads, primaries_, zoneName, options);
   });
   Lua->writeFunction("rpzPrimary", [&lci, &delayedThreads](const boost::variant<string, std::vector<std::pair<int, string>>>& primaries_, const string& zoneName, boost::optional<rpzOptions_t> options) {
@@ -583,11 +596,10 @@ 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, log);
+    updateTrustAnchorsFromFile(fnamearg, lci.dsAnchors, lci.d_slog);
   });
 
   Lua->writeFunction("setProtobufMasks", [&lci](const uint8_t maskV4, uint8_t maskV6) {
@@ -616,14 +628,17 @@ void loadRecursorLuaConfig(const std::string& fname, luaConfigDelayedThreads& de
         parseProtobufOptions(vars, lci.protobufExportConfig);
       }
       catch (std::exception& e) {
-        g_log << Logger::Error << "Error while adding protobuf logger: " << e.what() << endl;
+        SLOG(g_log << Logger::Error << "Error while adding protobuf logger: " << e.what() << endl,
+             lci.d_slog->error(Logr::Error, e.what(), "Exception  while adding protobuf logger", "exception", Logging::Loggable("std::exception")));
       }
       catch (PDNSException& e) {
-        g_log << Logger::Error << "Error while adding protobuf logger: " << e.reason << endl;
+        SLOG(g_log << Logger::Error << "Error while adding protobuf logger: " << e.reason << endl,
+             lci.d_slog->error(Logr::Error, e.reason, "Exception  while adding protobuf logger", "exception", Logging::Loggable("PDNSException")));
       }
     }
     else {
-      g_log << Logger::Error << "Only one protobufServer() directive can be configured, we already have " << lci.protobufExportConfig.servers.at(0).toString() << endl;
+      SLOG(g_log << Logger::Error << "Only one protobufServer() directive can be configured, we already have " << lci.protobufExportConfig.servers.at(0).toString() << endl,
+           lci.d_slog->info(Logr::Error, "Only one protobufServer() directive can be configured", "existing", Logging::Loggable(lci.protobufExportConfig.servers.at(0).toString())));
     }
   });
 
@@ -648,14 +663,17 @@ void loadRecursorLuaConfig(const std::string& fname, luaConfigDelayedThreads& de
         parseProtobufOptions(vars, lci.outgoingProtobufExportConfig);
       }
       catch (std::exception& e) {
-        g_log << Logger::Error << "Error while starting outgoing protobuf logger: " << e.what() << endl;
+        SLOG(g_log << Logger::Error << "Error while starting outgoing protobuf logger: " << e.what() << endl,
+             lci.d_slog->error(Logr::Error, "Exception while starting outgoing protobuf logger", "exception", Logging::Loggable("std::exception")));
       }
       catch (PDNSException& e) {
-        g_log << Logger::Error << "Error while starting outgoing protobuf logger: " << e.reason << endl;
+        SLOG(g_log << Logger::Error << "Error while starting outgoing protobuf logger: " << e.reason << endl,
+             lci.d_slog->error(Logr::Error, "Exception while starting outgoing protobuf logger", "exception", Logging::Loggable("PDNSException")));
       }
     }
     else {
-      g_log << Logger::Error << "Only one outgoingProtobufServer() directive can be configured, we already have " << lci.outgoingProtobufExportConfig.servers.at(0).toString() << endl;
+      SLOG(g_log << Logger::Error << "Only one outgoingProtobufServer() directive can be configured, we already have " << lci.outgoingProtobufExportConfig.servers.at(0).toString() << endl,
+           lci.d_slog->info(Logr::Error, "Only one outgoingProtobufServer() directive can be configured", "existing", Logging::Loggable(lci.outgoingProtobufExportConfig.servers.at(0).toString())));
     }
   });
 
@@ -683,14 +701,17 @@ void loadRecursorLuaConfig(const std::string& fname, luaConfigDelayedThreads& de
         parseFrameStreamOptions(vars, lci.frameStreamExportConfig);
       }
       catch (std::exception& e) {
-        g_log << Logger::Error << "Error reading config for dnstap framestream logger: " << e.what() << endl;
+        SLOG(g_log << Logger::Error << "Error reading config for dnstap framestream logger: " << e.what() << endl,
+              lci.d_slog->error(Logr::Error, "Exception reading config for dnstap framestream logger", "exception", Logging::Loggable("std::exception")));
       }
       catch (PDNSException& e) {
-        g_log << Logger::Error << "Error reading config for dnstap framestream logger: " << e.reason << endl;
+        SLOG(g_log << Logger::Error << "Error reading config for dnstap framestream logger: " << e.reason << endl,
+             lci.d_slog->error(Logr::Error, "Exception reading config for dnstap framestream logger", "exception", Logging::Loggable("PDNSException")));
       }
     }
     else {
-      g_log << Logger::Error << "Only one dnstapFrameStreamServer() directive can be configured, we already have " << lci.frameStreamExportConfig.servers.at(0) << endl;
+      SLOG(g_log << Logger::Error << "Only one dnstapFrameStreamServer() directive can be configured, we already have " << lci.frameStreamExportConfig.servers.at(0) << endl,
+           lci.d_slog->info(Logr::Error,  "Only one dnstapFrameStreamServer() directive can be configured",  "existing", Logging::Loggable(lci.frameStreamExportConfig.servers.at(0))));
     }
   });
 #endif /* HAVE_FSTRM */
@@ -782,11 +803,13 @@ void startLuaConfigDelayedThreads(const luaConfigDelayedThreads& delayedThreads,
       t.detach();
     }
     catch (const std::exception& e) {
-      g_log << Logger::Error << "Problem starting RPZIXFRTracker thread: " << e.what() << endl;
+      SLOG(g_log << Logger::Error << "Problem starting RPZIXFRTracker thread: " << e.what() << endl,
+           g_slog->withName("rpz")->error(Logr::Error, e.what(), "Exception startng RPZIXFRTracker thread", "exception", Logging::Loggable("std::exception")));
       exit(1);
     }
     catch (const PDNSException& e) {
-      g_log << Logger::Error << "Problem starting RPZIXFRTracker thread: " << e.reason << endl;
+      SLOG(g_log << Logger::Error << "Problem starting RPZIXFRTracker thread: " << e.reason << endl,
+           g_slog->withName("rpz")->error(Logr::Error, e.reason, "Exception startng RPZIXFRTracker thread", "exception", Logging::Loggable("PDNSException")));
       exit(1);
     }
   }
diff --git a/pdns/rec-lua-conf.hh b/pdns/rec-lua-conf.hh
index 33faf1d101..d0b19057b9 100644
--- a/pdns/rec-lua-conf.hh
+++ b/pdns/rec-lua-conf.hh
@@ -27,6 +27,7 @@
 #include "filterpo.hh"
 #include "validate.hh"
 #include "rec-zonetocache.hh"
+#include "logging.hh"
 
 struct ProtobufExportConfig
 {
@@ -94,6 +95,7 @@ public:
   ProtobufExportConfig protobufExportConfig;
   ProtobufExportConfig outgoingProtobufExportConfig;
   FrameStreamExportConfig frameStreamExportConfig;
+  std::shared_ptr<Logr::Logger> d_slog;
   /* we need to increment this every time the configuration
      is reloaded, so we know if we need to reload the protobuf
      remote loggers */
diff --git a/pdns/recursordist/rec-main.cc b/pdns/recursordist/rec-main.cc
index d1af68e46c..08682566ff 100644
--- a/pdns/recursordist/rec-main.cc
+++ b/pdns/recursordist/rec-main.cc
@@ -374,7 +374,7 @@ static FDMultiplexer* getMultiplexer(Logr::log_t log)
   _exit(1);
 }
 
-static std::shared_ptr<std::vector<std::unique_ptr<RemoteLogger>>> startProtobufServers(const ProtobufExportConfig& config)
+static std::shared_ptr<std::vector<std::unique_ptr<RemoteLogger>>> startProtobufServers(const ProtobufExportConfig& config, Logr::log_t log)
 {
   auto result = std::make_shared<std::vector<std::unique_ptr<RemoteLogger>>>();
 
@@ -386,10 +386,12 @@ static std::shared_ptr<std::vector<std::unique_ptr<RemoteLogger>>> startProtobuf
       result->emplace_back(std::move(logger));
     }
     catch (const std::exception& e) {
-      g_log << Logger::Error << "Error while starting protobuf logger to '" << server << ": " << e.what() << endl;
+      SLOG(g_log << Logger::Error << "Error while starting protobuf logger to '" << server << ": " << e.what() << endl,
+           log->error(Logr::Error, e.what(), "Exception while starting protobuf logger", "exception", Logging::Loggable("std::exception"), "server", Logging::Loggable(server)));
     }
     catch (const PDNSException& e) {
-      g_log << Logger::Error << "Error while starting protobuf logger to '" << server << ": " << e.reason << endl;
+      SLOG(g_log << Logger::Error << "Error while starting protobuf logger to '" << server << ": " << e.reason << endl,
+           log->error(Logr::Error, e.reason, "Exception while starting protobuf logger", "exception", Logging::Loggable("PDNSException"), "server", Logging::Loggable(server)));
     }
   }
 
@@ -420,7 +422,8 @@ bool checkProtobufExport(LocalStateHolder<LuaConfigItems>& luaconfsLocal)
     }
     t_protobufServers.reset();
 
-    t_protobufServers = startProtobufServers(luaconfsLocal->protobufExportConfig);
+    auto log = g_slog->withName("protobuf");
+    t_protobufServers = startProtobufServers(luaconfsLocal->protobufExportConfig, log);
     t_protobufServersGeneration = luaconfsLocal->generation;
   }
 
@@ -451,7 +454,8 @@ bool checkOutgoingProtobufExport(LocalStateHolder<LuaConfigItems>& luaconfsLocal
     }
     t_outgoingProtobufServers.reset();
 
-    t_outgoingProtobufServers = startProtobufServers(luaconfsLocal->outgoingProtobufExportConfig);
+    auto log = g_slog->withName("protobuf");
+    t_outgoingProtobufServers = startProtobufServers(luaconfsLocal->outgoingProtobufExportConfig, log);
     t_outgoingProtobufServersGeneration = luaconfsLocal->generation;
   }
 
@@ -575,7 +579,7 @@ void protobufLogResponse(const struct dnsheader* dh, LocalStateHolder<LuaConfigI
 
 #ifdef HAVE_FSTRM
 
-static std::shared_ptr<std::vector<std::unique_ptr<FrameStreamLogger>>> startFrameStreamServers(const FrameStreamExportConfig& config)
+static std::shared_ptr<std::vector<std::unique_ptr<FrameStreamLogger>>> startFrameStreamServers(const FrameStreamExportConfig& config, Logr::log_t log)
 {
   auto result = std::make_shared<std::vector<std::unique_ptr<FrameStreamLogger>>>();
 
@@ -601,10 +605,12 @@ static std::shared_ptr<std::vector<std::unique_ptr<FrameStreamLogger>>> startFra
       result->emplace_back(fsl);
     }
     catch (const std::exception& e) {
-      g_log << Logger::Error << "Error while starting dnstap framestream logger to '" << server << ": " << e.what() << endl;
+      SLOG(g_log << Logger::Error << "Error while starting dnstap framestream logger to '" << server << ": " << e.what() << endl,
+           log->error(Logr::Error, e.what(), "Exception while starting dnstap framestream logger", "exception", Logging::Loggable("std::exception"), "server", Logging::Loggable(server)));
     }
     catch (const PDNSException& e) {
-      g_log << Logger::Error << "Error while starting dnstap framestream logger to '" << server << ": " << e.reason << endl;
+      SLOG(g_log << Logger::Error << "Error while starting dnstap framestream logger to '" << server << ": " << e.reason << endl,
+           log->error(Logr::Error, e.reason, "Exception while starting dnstap framestream logger", "exception", Logging::Loggable("PDNSException"), "server", Logging::Loggable(server)));
     }
   }
 
@@ -631,7 +637,8 @@ bool checkFrameStreamExport(LocalStateHolder<LuaConfigItems>& luaconfsLocal)
       t_frameStreamServers.reset();
     }
 
-    t_frameStreamServers = startFrameStreamServers(luaconfsLocal->frameStreamExportConfig);
+    auto log = g_slog->withName("dnstap");
+    t_frameStreamServers = startFrameStreamServers(luaconfsLocal->frameStreamExportConfig, log);
     t_frameStreamServersGeneration = luaconfsLocal->generation;
   }
 
@@ -1210,7 +1217,8 @@ template <class T>
 T broadcastAccFunction(const std::function<T*()>& func)
 {
   if (!RecThreadInfo::self().isHandler()) {
-    g_log << Logger::Error << "broadcastAccFunction has been called by a worker (" << RecThreadInfo::id() << ")" << endl;
+    SLOG(g_log << Logger::Error << "broadcastAccFunction has been called by a worker (" << RecThreadInfo::id() << ")" << endl,
+         g_slog->withName("runtime")->info(Logr::Critical, "broadcastAccFunction has been called by a worker")); // tid will be added
     _exit(1);
   }
 
@@ -1432,8 +1440,8 @@ static int serviceMain(int argc, char* argv[], Logr::log_t log)
   SyncRes::s_max_busy_dot_probes = ::arg().asNum("max-busy-dot-probes");
 
   if (SyncRes::s_tcp_fast_open_connect) {
-    checkFastOpenSysctl(true);
-    checkTFOconnect();
+    checkFastOpenSysctl(true, log);
+    checkTFOconnect(log);
   }
 
   if (SyncRes::s_serverID.empty()) {
@@ -1895,12 +1903,16 @@ static void handlePipeRequest(int fd, FDMultiplexer::funcparam_t& var)
     resp = tmsg->func();
   }
   catch (std::exception& e) {
-    if (g_logCommonErrors)
-      g_log << Logger::Error << "PIPE function we executed created exception: " << e.what() << endl; // but what if they wanted an answer.. we send 0
+    if (g_logCommonErrors) {
+      SLOG(g_log << Logger::Error << "PIPE function we executed created exception: " << e.what() << endl, // but what if they wanted an answer.. we send 0
+           g_slog->withName("runtime")->error(Logr::Error, e.what(), "PIPE function we executed created exception", "exception", Logging::Loggable("std::exception")));
+    }
   }
   catch (PDNSException& e) {
-    if (g_logCommonErrors)
-      g_log << Logger::Error << "PIPE function we executed created PDNS exception: " << e.reason << endl; // but what if they wanted an answer.. we send 0
+    if (g_logCommonErrors) {
+      SLOG(g_log << Logger::Error << "PIPE function we executed created PDNS exception: " << e.reason << endl, // but what if they wanted an answer.. we send 0
+           g_slog->withName("runtime")->error(Logr::Error, e.reason, "PIPE function we executed created exception", "exception", Logging::Loggable("PDNSException")));
+    }
   }
   if (tmsg->wantAnswer) {
     if (write(RecThreadInfo::self().pipes.writeFromThread, &resp, sizeof(resp)) != sizeof(resp)) {
@@ -2296,16 +2308,19 @@ static void recursorThread()
 
     if (threadInfo.isHandler()) {
       if (::arg().mustDo("webserver")) {
-        g_log << Logger::Warning << "Enabling web server" << endl;
+        SLOG(g_log << Logger::Warning << "Enabling web server" << endl,
+             log->info(Logr::Info, "Enabling web server"))
         try {
           rws = make_unique<RecursorWebServer>(t_fdm.get());
         }
         catch (const PDNSException& e) {
-          g_log << Logger::Error << "Unable to start the internal web server: " << e.reason << endl;
+          SLOG(g_log << Logger::Error << "Unable to start the internal web server: " << e.reason << endl,
+               log->error(Logr::Critical, e.reason, "Exception while starting internal web server"));
           _exit(99);
         }
       }
-      g_log << Logger::Info << "Enabled '" << t_fdm->getName() << "' multiplexer" << endl;
+      SLOG(g_log << Logger::Info << "Enabled '" << t_fdm->getName() << "' multiplexer" << endl,
+           log->info(Logr::Info, "Enabled multiplexer", "name", Logging::Loggable(t_fdm->getName())));
     }
     else {
       t_fdm->addReadFD(threadInfo.pipes.readQueriesToThread, handlePipeRequest);
@@ -2424,13 +2439,16 @@ static void recursorThread()
     }
   }
   catch (PDNSException& ae) {
-    g_log << Logger::Error << "Exception: " << ae.reason << endl;
+    SLOG(g_log << Logger::Error << "Exception: " << ae.reason << endl,
+         log->error(Logr::Error, ae.reason, "Exception in RecursorThread", "exception", Logging::Loggable("PDNSException")))
   }
   catch (std::exception& e) {
-    g_log << Logger::Error << "STL Exception: " << e.what() << endl;
+    SLOG(g_log << Logger::Error << "STL Exception: " << e.what() << endl,
+         log->error(Logr::Error, e.what(), "Exception in RecursorThread", "exception", Logging::Loggable("std::exception")))
   }
   catch (...) {
-    g_log << Logger::Error << "any other exception in main: " << endl;
+    SLOG(g_log << Logger::Error << "any other exception in main: " << endl,
+         log->info(Logr::Error, "Exception in RecursorThread"));
   }
 }
 
diff --git a/pdns/recursordist/rec-main.hh b/pdns/recursordist/rec-main.hh
index 94a9a903f3..6ba4a92b2f 100644
--- a/pdns/recursordist/rec-main.hh
+++ b/pdns/recursordist/rec-main.hh
@@ -523,8 +523,8 @@ void requestWipeCaches(const DNSName& canon);
 void startDoResolve(void* p);
 bool expectProxyProtocol(const ComboAddress& from);
 void finishTCPReply(std::unique_ptr<DNSComboWriter>& dc, bool hadError, bool updateInFlight);
-void checkFastOpenSysctl(bool active);
-void checkTFOconnect();
+void checkFastOpenSysctl(bool active, Logr::log_t);
+void checkTFOconnect(Logr::log_t);
 void makeTCPServerSockets(deferredAdd_t& deferredAdds, std::set<int>& tcpSockets, Logr::log_t);
 void handleNewTCPQuestion(int fd, FDMultiplexer::funcparam_t&);
 
diff --git a/pdns/recursordist/rec-tcp.cc b/pdns/recursordist/rec-tcp.cc
index 52d5c0c909..9aac57eca6 100644
--- a/pdns/recursordist/rec-tcp.cc
+++ b/pdns/recursordist/rec-tcp.cc
@@ -839,28 +839,32 @@ static void TCPIOHandlerIO(int fd, FDMultiplexer::funcparam_t& var)
   TCPIOHandlerStateChange(pid->lowState, newstate, pid);
 }
 
-void checkFastOpenSysctl(bool active)
+void checkFastOpenSysctl(bool active, Logr::log_t log)
 {
 #ifdef __linux__
   string line;
   if (readFileIfThere("/proc/sys/net/ipv4/tcp_fastopen", &line)) {
     int flag = std::stoi(line);
     if (active && !(flag & 1)) {
-      g_log << Logger::Error << "tcp-fast-open-connect enabled but net.ipv4.tcp_fastopen does not allow it" << endl;
+      SLOG(g_log << Logger::Error << "tcp-fast-open-connect enabled but net.ipv4.tcp_fastopen does not allow it" << endl,
+           log->info(Logr::Error, "tcp-fast-open-connect enabled but net.ipv4.tcp_fastopen does not allow it"));
     }
     if (!active && !(flag & 2)) {
-      g_log << Logger::Error << "tcp-fast-open enabled but net.ipv4.tcp_fastopen does not allow it" << endl;
+      SLOG(g_log << Logger::Error << "tcp-fast-open enabled but net.ipv4.tcp_fastopen does not allow it" << endl,
+           log->info(Logr::Error, "tcp-fast-open enabled but net.ipv4.tcp_fastopen does not allow it"));
     }
   }
   else {
-    g_log << Logger::Notice << "Cannot determine if kernel settings allow fast-open" << endl;
+    SLOG(g_log << Logger::Notice << "Cannot determine if kernel settings allow fast-open" << endl,
+         log->info(Logr::Notice, "Cannot determine if kernel settings allow fast-open"));
   }
 #else
-  g_log << Logger::Notice << "Cannot determine if kernel settings allow fast-open" << endl;
+  SLOG(g_log << Logger::Notice << "Cannot determine if kernel settings allow fast-open" << endl,
+       log->info(Logr::Notice, "Cannot determine if kernel settings allow fast-open"));
 #endif
 }
 
-void checkTFOconnect()
+void checkTFOconnect( Logr::log_t log)
 {
   try {
     Socket s(AF_INET, SOCK_STREAM);
@@ -868,7 +872,8 @@ void checkTFOconnect()
     s.setFastOpenConnect();
   }
   catch (const NetworkError& e) {
-    g_log << Logger::Error << "tcp-fast-open-connect enabled but returned error: " << e.what() << endl;
+    SLOG(g_log << Logger::Error << "tcp-fast-open-connect enabled but returned error: " << e.what() << endl,
+         log->error(Logr::Error, e.what(), "tcp-fast-open-connect enabled but returned error"));
   }
 }
 
@@ -1026,7 +1031,9 @@ void makeTCPServerSockets(deferredAdd_t& deferredAdds, std::set<int>& tcpSockets
 
     int tmp = 1;
     if (setsockopt(fd, SOL_SOCKET, SO_REUSEADDR, &tmp, sizeof tmp) < 0) {
-      g_log << Logger::Error << "Setsockopt failed for TCP listening socket" << endl;
+      int err = errno;
+      SLOG(g_log << Logger::Error << "Setsockopt failed for TCP listening socket" << endl,
+           log->error(Logr::Critical, err, "Setsockopt failed for TCP listening socket"));
       exit(1);
     }
     if (sin.sin6.sin6_family == AF_INET6 && setsockopt(fd, IPPROTO_IPV6, IPV6_V6ONLY, &tmp, sizeof(tmp)) < 0) {
@@ -1066,7 +1073,7 @@ void makeTCPServerSockets(deferredAdd_t& deferredAdds, std::set<int>& tcpSockets
     }
 
     if (SyncRes::s_tcp_fast_open > 0) {
-      checkFastOpenSysctl(false);
+      checkFastOpenSysctl(false, log);
 #ifdef TCP_FASTOPEN
       if (setsockopt(fd, IPPROTO_TCP, TCP_FASTOPEN, &SyncRes::s_tcp_fast_open, sizeof SyncRes::s_tcp_fast_open) < 0) {
         int err = errno;
diff --git a/pdns/remote_logger.cc b/pdns/remote_logger.cc
index 96e596888c..8ffb3b4285 100644
--- a/pdns/remote_logger.cc
+++ b/pdns/remote_logger.cc
@@ -7,6 +7,7 @@
 #endif
 #ifdef PDNS_CONFIG_ARGS
 #include "logger.hh"
+#include "logging.hh"
 #define WE_ARE_RECURSOR
 #else
 #include "dolog.hh"
@@ -119,7 +120,8 @@ bool RemoteLogger::reconnect()
   }
   catch (const std::exception& e) {
 #ifdef WE_ARE_RECURSOR
-    g_log<<Logger::Warning<<"Error connecting to remote logger "<<d_remote.toStringWithPort()<<": "<<e.what()<<std::endl;
+    SLOG(g_log<<Logger::Warning<<"Error connecting to remote logger "<<d_remote.toStringWithPort()<<": "<<e.what()<<std::endl,
+         g_slog->withName("protobuf")->error(Logr::Error, e.what(), "Exception while connection to remote logger", "address", Logging::Loggable(d_remote)));
 #else
     warnlog("Error connecting to remote logger %s: %s", d_remote.toStringWithPort(), e.what());
 #endif
@@ -222,10 +224,12 @@ void RemoteLogger::maintenanceThread()
   }
   catch (const std::exception& e)
   {
-    cerr << "Remote Logger's maintenance thead died on: " << e.what() << endl;
+    SLOG(g_log << "Remote Logger's maintenance thead died on: " << e.what() << endl,
+         g_slog->withName("protobuf")->error(Logr::Error, e.what(), "Remote Logger's maintenance thead died"));
   }
   catch (...) {
-    cerr << "Remote Logger's maintenance thead died on unknown exception" << endl;
+    SLOG(g_log << "Remote Logger's maintenance thead died on unknown exception" << endl,
+          g_slog->withName("protobuf")->info(Logr::Error, "Remote Logger's maintenance thead died"));
   }
 }
 
diff --git a/pdns/rpzloader.cc b/pdns/rpzloader.cc
index b047182c6b..217cec0641 100644
--- a/pdns/rpzloader.cc
+++ b/pdns/rpzloader.cc
@@ -64,7 +64,7 @@ Netmask makeNetmaskFromRPZ(const DNSName& name)
   return Netmask(v6);
 }
 
-static void RPZRecordToPolicy(const DNSRecord& dr, std::shared_ptr<DNSFilterEngine::Zone> zone, bool addOrRemove, const boost::optional<DNSFilterEngine::Policy>& defpol, bool defpolOverrideLocal, uint32_t maxTTL)
+static void RPZRecordToPolicy(const DNSRecord& dr, std::shared_ptr<DNSFilterEngine::Zone> zone, bool addOrRemove, const boost::optional<DNSFilterEngine::Policy>& defpol, bool defpolOverrideLocal, uint32_t maxTTL, Logr::log_t log)
 {
   static const DNSName drop("rpz-drop."), truncate("rpz-tcp-only."), noaction("rpz-passthru.");
   static const DNSName rpzClientIP("rpz-client-ip"), rpzIP("rpz-ip"),
@@ -117,7 +117,8 @@ static void RPZRecordToPolicy(const DNSRecord& dr, std::shared_ptr<DNSFilterEngi
     else if(!crcTarget.empty() && !crcTarget.isRoot() && crcTarget.getRawLabel(crcTarget.countLabels() - 1).compare(0, rpzPrefix.length(), rpzPrefix) == 0) {
       /* this is very likely an higher format number or a configuration error,
          let's just ignore it. */
-      g_log<<Logger::Info<<"Discarding unsupported RPZ entry "<<crcTarget<<" for "<<dr.d_name<<endl;
+      SLOG(g_log<<Logger::Info<<"Discarding unsupported RPZ entry "<<crcTarget<<" for "<<dr.d_name<<endl,
+           log->info(Logr::Info, "Discarding unsupported RPZ entry", "target", Logging::Loggable(crcTarget), "name", Logging::Loggable(dr.d_name)));
       return;
     }
     else {
@@ -194,7 +195,6 @@ static shared_ptr<SOARecordContent> loadRPZFromServer(Logr::log_t plogger, const
   auto logger = plogger->withValues("primary", Logging::Loggable(primary));
   SLOG(g_log<<Logger::Warning<<"Loading RPZ zone '"<<zoneName<<"' from "<<primary.toStringWithPort()<<endl,
        logger->info(Logr::Info, "Loading RPZ from nameserver"));
-  logger = logger->v(1);
   if(!tt.name.empty()) {
     SLOG(g_log<<Logger::Warning<<"With TSIG key '"<<tt.name<<"' of algorithm '"<<tt.algo<<"'"<<endl,
          logger->info(Logr::Info, "Using TSIG key for authentication", "tsig_key_name", Logging::Loggable(tt.name), "tsig_key_algorithm", Logging::Loggable(tt.algo)));
@@ -224,7 +224,7 @@ static shared_ptr<SOARecordContent> loadRPZFromServer(Logr::log_t plogger, const
 	continue;
       }
 
-      RPZRecordToPolicy(dr, zone, true, defpol, defpolOverrideLocal, maxTTL);
+      RPZRecordToPolicy(dr, zone, true, defpol, defpolOverrideLocal, maxTTL, logger);
       nrecords++;
     } 
     axfrNow = time(nullptr);
@@ -289,6 +289,7 @@ std::shared_ptr<SOARecordContent> loadRPZFromFile(const std::string& fname, std:
   zpt.setMaxIncludes(::arg().asNum("max-include-depth"));
   DNSResourceRecord drr;
   DNSName domain;
+  auto log = g_slog->withName("rpz")->withValues("file", Logging::Loggable(fname), "zone", Logging::Loggable(zone->getName()));
   while(zpt.get(drr)) {
     try {
       if(drr.qtype.getCode() == QType::CNAME && drr.content.empty())
@@ -304,7 +305,7 @@ std::shared_ptr<SOARecordContent> loadRPZFromFile(const std::string& fname, std:
       }
       else {
 	dr.d_name=dr.d_name.makeRelative(domain);
-	RPZRecordToPolicy(dr, zone, true, defpol, defpolOverrideLocal, maxTTL);
+	RPZRecordToPolicy(dr, zone, true, defpol, defpolOverrideLocal, maxTTL, log);
       }
     }
     catch(const PDNSException& pe) {
@@ -319,10 +320,9 @@ std::shared_ptr<SOARecordContent> loadRPZFromFile(const std::string& fname, std:
   return sr;
 }
 
-static bool dumpZoneToDisk(Logr::log_t plogger, const DNSName& zoneName, const std::shared_ptr<DNSFilterEngine::Zone>& newZone, const std::string& dumpZoneFileName)
+static bool dumpZoneToDisk(Logr::log_t logger, const DNSName& zoneName, const std::shared_ptr<DNSFilterEngine::Zone>& newZone, const std::string& dumpZoneFileName)
 {
-  auto logger = plogger->v(1);
-  logger->info("Dumping zone to disk", "destination_file", Logging::Loggable(dumpZoneFileName));
+  logger->info(Logr::Debug, "Dumping zone to disk", "destination_file", Logging::Loggable(dumpZoneFileName));
   std::string temp = dumpZoneFileName + "XXXXXX";
   int fd = mkstemp(&temp.at(0));
   if (fd < 0) {
@@ -382,7 +382,7 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, const boost::opt
   bool isPreloaded = sr != nullptr;
   auto luaconfsLocal = g_luaconfs.getLocal();
 
-  auto logger = g_slog->withName("rpz")->v(1);
+  auto logger = g_slog->withName("rpz");
 
   /* we can _never_ modify this zone directly, we need to do a full copy then replace the existing zone */
   std::shared_ptr<DNSFilterEngine::Zone> oldZone = luaconfsLocal->dfe.getZone(zoneIdx);
@@ -458,7 +458,8 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, const boost::opt
       /* the configuration has been reloaded, meaning that a new thread
          has been started to handle that zone and we are now obsolete.
       */
-      g_log<<Logger::Info<<"A more recent configuration has been found, stopping the existing RPZ update thread for "<<zoneName<<endl;
+      SLOG(g_log<<Logger::Info<<"A more recent configuration has been found, stopping the existing RPZ update thread for "<<zoneName<<endl,
+           logger->info(Logr::Info, "A more recent configuration has been found, stopping the existing RPZ update thread"));
       return;
     }
 
@@ -466,7 +467,8 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, const boost::opt
     for (const auto& primary : primaries) {
       auto soa = getRR<SOARecordContent>(dr);
       auto serial = soa ? soa->d_st.serial : 0;
-      g_log<<Logger::Info<<"Getting IXFR deltas for "<<zoneName<<" from "<<primary.toStringWithPort()<<", our serial: "<<serial<<endl;
+      SLOG(g_log<<Logger::Info<<"Getting IXFR deltas for "<<zoneName<<" from "<<primary.toStringWithPort()<<", our serial: "<<serial<<endl,
+           logger->info(Logr::Info, "Getting IXFR deltas", "address", Logging::Loggable(primary)));
 
       ComboAddress local(localAddress);
       if (local == ComboAddress()) {
@@ -479,7 +481,8 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, const boost::opt
         /* no need to try another primary */
         break;
       } catch(const std::runtime_error& e ){
-        g_log<<Logger::Warning<<e.what()<<endl;
+        SLOG(g_log<<Logger::Warning<<e.what()<<endl,
+             logger->error(Logr::Warning, e.what(), "Exception during retrieval of delta"));
         incRPZFailedTransfers(polName);
         continue;
       }
@@ -490,15 +493,18 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, const boost::opt
     }
 
     try {
-      g_log<<Logger::Info<<"Processing "<<deltas.size()<<" delta"<<addS(deltas)<<" for RPZ "<<zoneName<<endl;
+      SLOG(g_log<<Logger::Info<<"Processing "<<deltas.size()<<" delta"<<addS(deltas)<<" for RPZ "<<zoneName<<endl,
+           logger->info(Logr::Info, "Processing deltas", "size", Logging::Loggable(deltas.size())));
 
       if (luaconfsLocal->generation != configGeneration) {
-        g_log<<Logger::Info<<"A more recent configuration has been found, stopping the existing RPZ update thread for "<<zoneName<<endl;
+        SLOG(g_log<<Logger::Info<<"A more recent configuration has been found, stopping the existing RPZ update thread for "<<zoneName<<endl,
+             logger->info(Logr::Info, "A more recent configuration has been found, stopping the existing RPZ update thread"))
         return;
       }
       oldZone = luaconfsLocal->dfe.getZone(zoneIdx);
       if (!oldZone || oldZone->getDomain() != zoneName) {
-        g_log<<Logger::Info<<"This policy is no more, stopping the existing RPZ update thread for "<<zoneName << endl;
+        SLOG(g_log<<Logger::Info<<"This policy is no more, stopping the existing RPZ update thread for "<<zoneName << endl,
+             logger->info(Logr::Info, "This policy is no more, stopping the existing RPZ update thread"));
         return;
       }
       /* we need to make a _full copy_ of the zone we are going to work on */
@@ -512,7 +518,8 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, const boost::opt
         const auto& remove = delta.first;
         const auto& add = delta.second;
         if(remove.empty()) {
-          g_log<<Logger::Warning<<"IXFR update is a whole new zone"<<endl;
+          SLOG(g_log<<Logger::Warning<<"IXFR update is a whole new zone"<<endl,
+               logger->info(Logr::Warning, "IXFR update is a whole new zone"));
           newZone->clear();
           fullUpdate = true;
         }
@@ -535,8 +542,9 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, const boost::opt
           }
           else {
             totremove++;
-            g_log<<(g_logRPZChanges ? Logger::Info : Logger::Debug)<<"Had removal of "<<rr.d_name<<" from RPZ zone "<<zoneName<<endl;
-            RPZRecordToPolicy(rr, newZone, false, defpol, defpolOverrideLocal, maxTTL);
+            SLOG(g_log<<(g_logRPZChanges ? Logger::Info : Logger::Debug)<<"Had removal of "<<rr.d_name<<" from RPZ zone "<<zoneName<<endl,
+                 logger->info(g_logRPZChanges ? Logr::Info : Logr::Debug, "Remove from RPZ zone", "name", Logging::Loggable(rr.d_name)));
+            RPZRecordToPolicy(rr, newZone, false, defpol, defpolOverrideLocal, maxTTL, logger);
           }
         }
 
@@ -552,8 +560,9 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, const boost::opt
           }
           else {
             totadd++;
-            g_log<<(g_logRPZChanges ? Logger::Info : Logger::Debug)<<"Had addition of "<<rr.d_name<<" to RPZ zone "<<zoneName<<endl;
-            RPZRecordToPolicy(rr, newZone, true, defpol, defpolOverrideLocal, maxTTL);
+            SLOG(g_log<<(g_logRPZChanges ? Logger::Info : Logger::Debug)<<"Had addition of "<<rr.d_name<<" to RPZ zone "<<zoneName<<endl,
+                 logger->info(g_logRPZChanges ? Logr::Info : Logr::Debug, "Addition to RPZ zone", "name", Logging::Loggable(rr.d_name)));
+            RPZRecordToPolicy(rr, newZone, true, defpol, defpolOverrideLocal, maxTTL, logger);
           }
         }
       }
@@ -562,7 +571,8 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, const boost::opt
       if (currentSR) {
         sr = currentSR;
       }
-      g_log<<Logger::Info<<"Had "<<totremove<<" RPZ removal"<<addS(totremove)<<", "<<totadd<<" addition"<<addS(totadd)<<" for "<<zoneName<<" New serial: "<<sr->d_st.serial<<endl;
+      SLOG(g_log<<Logger::Info<<"Had "<<totremove<<" RPZ removal"<<addS(totremove)<<", "<<totadd<<" addition"<<addS(totadd)<<" for "<<zoneName<<" New serial: "<<sr->d_st.serial<<endl,
+           logger->info(Logr::Info, "RPZ mutations", "removals",  Logging::Loggable(totremove), "additions", Logging::Loggable(totadd), "newserial", Logging::Loggable(sr->d_st.serial)));
       newZone->setSerial(sr->d_st.serial);
       newZone->setRefresh(sr->d_st.refresh);
       setRPZZoneNewState(polName, sr->d_st.serial, newZone->size(), false, fullUpdate);
@@ -572,7 +582,8 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, const boost::opt
          since they might have been updated by another RPZ IXFR tracker thread.
       */
       if (luaconfsLocal->generation != configGeneration) {
-        g_log<<Logger::Info<<"A more recent configuration has been found, stopping the existing RPZ update thread for "<<zoneName<<endl;
+        SLOG(g_log<<Logger::Info<<"A more recent configuration has been found, stopping the existing RPZ update thread for "<<zoneName<<endl,
+             logger->info(Logr::Info, "A more recent configuration has been found, stopping the existing RPZ update thread"));
         return;
       }
       g_luaconfs.modify([zoneIdx, &newZone](LuaConfigItems& lci) {
@@ -585,7 +596,8 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, const boost::opt
       refresh = std::max(refreshFromConf ? refreshFromConf : newZone->getRefresh(), 1U);
     }
     catch (const std::exception& e) {
-      g_log << Logger::Error << "Error while applying the update received over XFR for "<<zoneName<<", skipping the update: "<< e.what() <<endl;
+      SLOG(g_log << Logger::Error << "Error while applying the update received over XFR for "<<zoneName<<", skipping the update: "<< e.what() <<endl,
+           logger->error(Logr::Error, e.what(), "Exception while applying the update received over XFR, skipping"));
     }
   }
 }