A compatibiliy macro to have both old and new logging.

Existing logging is routed to old-style to avoid breaking log scanner
tools. New logging can use the structured logging API.

diff --git a/pdns/pdns_recursor.cc b/pdns/pdns_recursor.cc
index 280f93674442b25d9aee32354543d45021f38473..e8781acebe6f46b65e893aafbb4b61ad44e0b760 100644 (file)
--- a/pdns/pdns_recursor.cc
+++ b/pdns/pdns_recursor.cc
@@ -5697,7 +5697,6 @@ static void loggerBackend(const Logging::Entry& entry) {
   g_log << u << buf.str() << endl;
 }
 
-
 int main(int argc, char **argv)
 {
   g_argc = argc;
@@ -5995,13 +5994,15 @@ int main(int argc, char **argv)
     auto startupLog = g_slog->withName("startup");
 
     if(!::arg().file(configname.c_str())) {
-      startupLog->error("No such file", "Unable to parse configuration file", "config_file", Logging::Loggable(configname));
+      SLOG(g_log<<Logger::Warning<<"Unable to parse configuration file '"<<configname<<"'"<<endl,
+           startupLog->error("No such file", "Unable to parse configuration file", "config_file", Logging::Loggable(configname)));
     }
 
     ::arg().parse(argc,argv);
 
     if( !::arg()["chroot"].empty() && !::arg()["api-config-dir"].empty() ) {
-      startupLog->info("Cannot use chroot and enable the API at the same time");
+      SLOG(g_log<<Logger::Error<<"Using chroot and enabling the API is not possible"<<endl,
+           startupLog->info("Cannot use chroot and enable the API at the same time"));
       exit(EXIT_FAILURE);
     }
 
@@ -6014,13 +6015,15 @@ int main(int argc, char **argv)
 
     if(::arg().asNum("threads")==1) {
       if (::arg().mustDo("pdns-distributes-queries")) {
-        startupLog->v(1)->info("Only one thread, no need to distribute queries ourselves");
+        SLOG(g_log<<Logger::Warning<<"Asked to run with pdns-distributes-queries set but no distributor threads, raising to 1"<<endl,
+             startupLog->v(1)->info("Only one thread, no need to distribute queries ourselves"));
         ::arg().set("pdns-distributes-queries")="no";
       }
     }
 
     if(::arg().mustDo("pdns-distributes-queries") && ::arg().asNum("distributor-threads") <= 0) {
-      startupLog->v(1)->info("Asked to run with pdns-distributes-queries set but no distributor threads, raising to 1");
+      SLOG(g_log<<Logger::Warning<<"Asked to run with pdns-distributes-queries set but no distributor threads, raising to 1"<<endl,
+           startupLog->v(1)->info("Asked to run with pdns-distributes-queries set but no distributor threads, raising to 1"));
       ::arg().set("distributor-threads")="1";
     }
 

diff --git a/pdns/recursordist/logging.cc b/pdns/recursordist/logging.cc
index 57ba371f24969f3daf0a67ada5b5958c64a51ac5..7fe236342199275c2908b27060eac02a51b86e2d 100644 (file)
--- a/pdns/recursordist/logging.cc
+++ b/pdns/recursordist/logging.cc
@@ -177,3 +177,4 @@ Logger::~Logger()
 };
 
 std::shared_ptr<Logging::Logger> g_slog{nullptr};
+bool g_slogOldStyle = false;

diff --git a/pdns/recursordist/logging.hh b/pdns/recursordist/logging.hh
index fe5ad1f4fa9f102d05a42fd88f3fbf6c7fd87a86..7d28856d4acf352da191c12758f5a81fb059761d 100644 (file)
--- a/pdns/recursordist/logging.hh
+++ b/pdns/recursordist/logging.hh
@@ -116,3 +116,22 @@ private:
 }
 
 extern std::shared_ptr<Logging::Logger> g_slog;
+
+// The list of subsystem names that use structured logging
+extern bool g_slogOldStyle;
+
+// A helper macro to switch between odl-style logging and new-style (structured logging)
+// A typical use:
+//
+// SLOG(g_log<<Logger::Warning<<"Unable to parse configuration file '"<<configname<<"'"<<endl,
+//      startupLog->error("No such file", "Unable to parse configuration file", "config_file", Logging::Loggable(configname));
+//
+#define SLOG(oldStyle, slogCall)  \
+  do {                            \
+    if (!g_slogOldStyle) {        \
+      slogCall;                   \
+    }                             \
+    else {                        \
+      oldStyle;                   \
+    }                             \
+  } while (0);

diff --git a/pdns/rpzloader.cc b/pdns/rpzloader.cc
index 25b13701f3e28494a8050718929793e5d8eaff9c..5fa63ed22caef7a9f03d986c91171cdf0bec4e60 100644 (file)
--- a/pdns/rpzloader.cc
+++ b/pdns/rpzloader.cc
@@ -192,10 +192,12 @@ static shared_ptr<SOARecordContent> loadRPZFromServer(const shared_ptr<Logr::Log
 {
 
   auto logger = plogger->withValues("primary", Logging::Loggable(primary));
-  logger->info(Logr::Info, "Loading RPZ from nameserver");
+  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()) {
-    logger->info(Logr::Info, "Using TSIG key for authentication", "tsig_key_name", Logging::Loggable(tt.name), "tsig_key_algorithm", Logging::Loggable(tt.algo));
+    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)));
   }
 
   ComboAddress local(localAddress);
@@ -230,11 +232,13 @@ static shared_ptr<SOARecordContent> loadRPZFromServer(const shared_ptr<Logr::Log
       throw PDNSException("Total AXFR time exceeded!");
     }
     if(last != time(0)) {
-      logger->info(Logr::Info, "RPZ load in progress", "nrecords", Logging::Loggable(nrecords));
+      SLOG(g_log<<Logger::Info<<"Loaded & indexed "<<nrecords<<" policy records so far for RPZ zone '"<<zoneName<<"'"<<endl,
+           logger->info(Logr::Info, "RPZ load in progress", "nrecords", Logging::Loggable(nrecords)));
       last=time(0);
     }
   }
-  logger->info(Logr::Info, "RPZ load completed", "nrecords", Logging::Loggable(nrecords), "soa", Logging::Loggable(sr->getZoneRepresentation()));
+  SLOG(g_log<<Logger::Info<<"Done: "<<nrecords<<" policy records active, SOA: "<<sr->getZoneRepresentation()<<endl,
+       logger->info(Logr::Info, "RPZ load completed", "nrecords", Logging::Loggable(nrecords), "soa", Logging::Loggable(sr->getZoneRepresentation())));
   return sr;
 }
 
@@ -321,7 +325,8 @@ static bool dumpZoneToDisk(const shared_ptr<Logr::Logger>& plogger, const DNSNam
   std::string temp = dumpZoneFileName + "XXXXXX";
   int fd = mkstemp(&temp.at(0));
   if (fd < 0) {
-    logger->error(Logr::Warning, errno, "Unable to create temporary file");
+    SLOG(g_log<<Logger::Warning<<"Unable to open a file to dump the content of the RPZ zone "<<zoneName<<endl,
+         logger->error(Logr::Warning, errno, "Unable to create temporary file"));
     return false;
   }
 
@@ -329,7 +334,8 @@ static bool dumpZoneToDisk(const shared_ptr<Logr::Logger>& plogger, const DNSNam
   if (!fp) {
     int err = errno;
     close(fd);
-    logger->error(Logr::Warning, err, "Unable to open file pointer");
+    SLOG(g_log<<Logger::Warning<<"Unable to open a file pointer to dump the content of the RPZ zone "<<zoneName<<endl,
+         logger->error(Logr::Warning, err, "Unable to open file pointer"));
     return false;
   }
   fd = -1;
@@ -338,27 +344,32 @@ static bool dumpZoneToDisk(const shared_ptr<Logr::Logger>& plogger, const DNSNam
     newZone->dump(fp.get());
   }
   catch(const std::exception& e) {
-    logger->error(Logr::Warning, e.what(), "Error while dumping the content of the RPZ");
+    SLOG(g_log<<Logger::Warning<<"Error while dumping the content of the RPZ zone "<<zoneName<<": "<<e.what()<<endl,
+         logger->error(Logr::Warning, e.what(), "Error while dumping the content of the RPZ"));
     return false;
   }
 
   if (fflush(fp.get()) != 0) {
-    logger->error(Logr::Warning, errno, "Error while flushing the content of the RPZ");
+    SLOG(g_log<<Logger::Warning<<"Error while flushing the content of the RPZ zone "<<zoneName<<" to the dump file: "<<stringerror()<<endl,
+         logger->error(Logr::Warning, errno, "Error while flushing the content of the RPZ"));
     return false;
   }
 
   if (fsync(fileno(fp.get())) != 0) {
-    logger->error(Logr::Warning, errno, "Error while syncing the content of the RPZ");
+    SLOG(g_log<<Logger::Warning<<"Error while syncing the content of the RPZ zone "<<zoneName<<" to the dump file: "<<stringerror()<<endl,
+         logger->error(Logr::Warning, errno, "Error while syncing the content of the RPZ"));
     return false;
   }
 
   if (fclose(fp.release()) != 0) {
-    logger->error(Logr::Warning, errno, "Error while writing the content of the RPZ");
+    SLOG(g_log<<Logger::Warning<<"Error while writing the content of the RPZ zone "<<zoneName<<" to the dump file: "<<stringerror()<<endl,
+         logger->error(Logr::Warning, errno, "Error while writing the content of the RPZ"));
     return false;
   }
 
   if (rename(temp.c_str(), dumpZoneFileName.c_str()) != 0) {
-    logger->error(Logr::Warning, errno, "Error while moving the content of the RPZ", "destination_file", Logging::Loggable(dumpZoneFileName));
+    SLOG(g_log<<Logger::Warning<<"Error while moving the content of the RPZ zone "<<zoneName<<" to the dump file: "<<stringerror()<<endl,
+         logger->error(Logr::Warning, errno, "Error while moving the content of the RPZ", "destination_file", Logging::Loggable(dumpZoneFileName)));
     return false;
   }
 
@@ -376,7 +387,8 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, const boost::opt
   /* 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);
   if (!oldZone) {
-    logger->error(Logr::Error, "Unable to retrieve RPZ zone from configuration", "index", Logging::Loggable(zoneIdx));
+    SLOG(g_log<<Logger::Error<<"Unable to retrieve RPZ zone with index "<<zoneIdx<<" from the configuration, exiting"<<endl,
+         logger->error(Logr::Error, "Unable to retrieve RPZ zone from configuration", "index", Logging::Loggable(zoneIdx)));
     return;
   }
 
@@ -413,11 +425,13 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, const boost::opt
         break;
       }
       catch(const std::exception& e) {
-        logger->info(Logr::Warning, "Unable to load RPZ zone, will retry", "from", Logging::Loggable(primary), "exception", Logging::Loggable(e.what()), "refresh", Logging::Loggable(refresh));
+        SLOG(g_log<<Logger::Warning<<"Unable to load RPZ zone '"<<zoneName<<"' from '"<<primary<<"': '"<<e.what()<<"'. (Will try again in "<<refresh<<" seconds...)"<<endl,
+             logger->info(Logr::Warning, "Unable to load RPZ zone, will retry", "from", Logging::Loggable(primary), "exception", Logging::Loggable(e.what()), "refresh", Logging::Loggable(refresh)));
         incRPZFailedTransfers(polName);
       }
       catch(const PDNSException& e) {
-        logger->info(Logr::Warning, "Unable to load RPZ zone, will retry", "from", Logging::Loggable(primary), "exception", Logging::Loggable(e.reason), "refresh", Logging::Loggable(refresh));
+        SLOG(g_log<<Logger::Warning<<"Unable to load RPZ zone '"<<zoneName<<"' from '"<<primary<<"': '"<<e.reason<<"'. (Will try again in "<<refresh<<" seconds...)"<<endl,
+             logger->info(Logr::Warning, "Unable to load RPZ zone, will retry", "from", Logging::Loggable(primary), "exception", Logging::Loggable(e.reason), "refresh", Logging::Loggable(refresh)));
         incRPZFailedTransfers(polName);
       }
     }