]> git.ipfire.org Git - thirdparty/pdns.git/commitdiff
Remaining structured logging, "only" sending/receiving questions and answers, validat...
authorOtto Moerbeek <otto.moerbeek@open-xchange.com>
Wed, 15 Jun 2022 08:43:37 +0000 (10:43 +0200)
committerOtto Moerbeek <otto.moerbeek@open-xchange.com>
Mon, 20 Jun 2022 13:15:30 +0000 (15:15 +0200)
pdns/lua-base4.cc
pdns/nod.cc
pdns/rec-carbon.cc
pdns/rec-snmp.cc
pdns/recursordist/pubsuffixloader.cc
pdns/rpzloader.cc
pdns/syncres.cc
pdns/threadname.cc
pdns/unix_utility.cc

index 31c2da0cf730c6a79e4525199dc117ebcb653a37..f3d0751e47e57f3d445451551210d262f3ba1052 100644 (file)
@@ -3,6 +3,7 @@
 #include <unordered_map>
 #include <typeinfo>
 #include "logger.hh"
+#include "logging.hh"
 #include "iputils.hh"
 #include "dnsname.hh"
 #include "dnsparser.hh"
@@ -21,7 +22,8 @@ int BaseLua4::loadFile(const std::string &fname) {
   std::ifstream ifs(fname);
   if (!ifs) {
     ret = errno;
-    g_log<<Logger::Error<<"Unable to read configuration file from '"<<fname<<"': "<<stringerror()<<endl;
+    SLOG(g_log<<Logger::Error<<"Unable to read configuration file from '"<<fname<<"': "<<stringerror(ret)<<endl,
+         g_slog->withName("lua")->error(Logr::Error, ret, "Unable to read configuration file", "file", Logging::Loggable(fname)));
     return ret;
   }
   loadStream(ifs);
@@ -167,7 +169,10 @@ void BaseLua4::prepareContext() {
       else
         cas.insert(boost::get<ComboAddress>(in));
       }
-      catch(std::exception& e) { g_log <<Logger::Error<<e.what()<<endl; }
+      catch(std::exception& e) {
+        SLOG(g_log <<Logger::Error<<e.what()<<endl,
+             g_slog->withName("lua")->error(Logr::Error, e.what(), "Exception in newCAS", "exception", Logging::Loggable("std::exception")));
+      }
     });
   d_lw->registerFunction<bool(cas_t::*)(const ComboAddress&)>("check",[](const cas_t& cas, const ComboAddress&ca) { return cas.count(ca)>0; });
 
@@ -229,7 +234,10 @@ void BaseLua4::prepareContext() {
   d_lw->registerFunction<void(DNSRecord::*)(const std::string&)>("changeContent", [](DNSRecord& dr, const std::string& newContent) { dr.d_content = shared_ptr<DNSRecordContent>(DNSRecordContent::mastermake(dr.d_type, 1, newContent)); });
 
   // pdnsload
-  d_lw->writeFunction("pdnslog", [](const std::string& msg, boost::optional<int> loglevel) { g_log << (Logger::Urgency)loglevel.get_value_or(Logger::Warning) << msg<<endl; });
+  d_lw->writeFunction("pdnslog", [](const std::string& msg, boost::optional<int> loglevel) {
+    SLOG(g_log << (Logger::Urgency)loglevel.get_value_or(Logger::Warning) << msg<<endl,
+         g_slog->withName("lua")->info(static_cast<Logr::Priority>(loglevel.get_value_or(Logr::Warning)), msg));
+  });
   d_lw->writeFunction("pdnsrandom", [](boost::optional<uint32_t> maximum) { return dns_random(maximum.get_value_or(0xffffffff)); });
 
   // certain constants
index 07d39282385c9c8544e814caa1c61ebfa4f65982..6dc93a233af86133799977dfdb559ac6ab89847e 100644 (file)
@@ -30,6 +30,7 @@
 #include "threadname.hh"
 #include <stdlib.h>
 #include "logger.hh"
+#include "logging.hh"
 #include "misc.hh"
 
 using namespace nod;
@@ -58,6 +59,7 @@ bool PersistentSBF::init(bool ignore_pid) {
   if (d_init)
     return false;
 
+  auto log = g_slog->withName("nod");
   std::lock_guard<std::mutex> lock(d_cachedir_mutex);
   if (d_cachedir.length()) {
     filesystem::path p(d_cachedir);
@@ -86,7 +88,8 @@ bool PersistentSBF::init(bool ignore_pid) {
           std::ifstream infile;
           try {
             infile.open(filename, std::ios::in | std::ios::binary);
-            g_log << Logger::Warning << "Found SBF file " << filename << endl;
+            SLOG(g_log << Logger::Warning << "Found SBF file " << filename << endl,
+                 log->info(Logr::Warning, "Found SBF File", "file", Logging::Loggable(filename)));
             // read the file into the sbf
             d_sbf.lock()->restore(infile);
             infile.close();
@@ -98,13 +101,15 @@ bool PersistentSBF::init(bool ignore_pid) {
           catch (const std::runtime_error& e) {
             infile.close();
             filesystem::remove(newest_file);
-            g_log<<Logger::Warning<<"NODDB init: Cannot parse file: " << filename << ": " << e.what() << "; removed" << endl;
+            SLOG(g_log<<Logger::Warning<<"NODDB init: Cannot parse file: " << filename << ": " << e.what() << "; removed" << endl,
+                 log->error(Logr::Warning, e.what(), "NODDB init: Cannot parse file, removed", "file",  Logging::Loggable(filename)));
           }
         }
       }
     }
     catch (const filesystem::filesystem_error& e) {
-      g_log<<Logger::Warning<<"NODDB init failed:: " << e.what() << endl;
+      SLOG(g_log<<Logger::Warning<<"NODDB init failed:: " << e.what() << endl,
+           log->error(Logr::Warning, e.what(), "NODDB init failed", "exception", Logging::Loggable("filesystem::filesystem_error")));
       return false;
     }
   }
@@ -130,6 +135,7 @@ void PersistentSBF::setCacheDir(const std::string& cachedir)
 // file IO to complete
 bool PersistentSBF::snapshotCurrent(std::thread::id tid)
 {
+  auto log = g_slog->withName("nod");
   if (d_cachedir.length()) {
     filesystem::path p(d_cachedir);
     filesystem::path f(d_cachedir);
@@ -165,18 +171,21 @@ bool PersistentSBF::snapshotCurrent(std::thread::id tid)
           filesystem::rename(ftmp, f);
         }
         catch (const std::runtime_error& e) {
-          g_log<<Logger::Warning<<"NODDB snapshot: Cannot rename file: " << e.what() << endl;
+          SLOG(g_log<<Logger::Warning<<"NODDB snapshot: Cannot rename file: " << e.what() << endl,
+               log->error(Logr::Warning, e.what(), "NODDB snapshot: Cannot rename file", "exception", Logging::Loggable("std::runtime_error")));
           filesystem::remove(ftmp);
           throw;
         }
         return true;
       }
       catch (const std::runtime_error& e) {
-        g_log<<Logger::Warning<<"NODDB snapshot: Cannot write file: " << e.what() << endl;
+        SLOG(g_log<<Logger::Warning<<"NODDB snapshot: Cannot write file: " << e.what() << endl,
+              log->error(Logr::Warning, e.what(), "NODDB snapshot: Cannot write file", "exception", Logging::Loggable("std::runtime_error")));
       }
     }
     else {
-      g_log<<Logger::Warning<<"NODDB snapshot: Cannot write file: " << f.string() << endl;
+      SLOG(g_log<<Logger::Warning<<"NODDB snapshot: Cannot write file: " << f.string() << endl,
+           log->info(Logr::Warning, "NODDB snapshot: Cannot write file", "file", Logging::Loggable(f.string())));
     }
   }
   return false;
index a8e67a6bae64e3f33a7c173dcc2c550bcfa89a78..8e28309b2b7bf33c8a4b2724bf63c8c6b40c9346 100644 (file)
@@ -6,6 +6,7 @@
 #include "rec_channel.hh"
 #include "iputils.hh"
 #include "logger.hh"
+#include "logging.hh"
 #include "arguments.hh"
 #include "lock.hh"
 
@@ -13,6 +14,7 @@ GlobalStateHolder<CarbonConfig> g_carbonConfig;
 
 void doCarbonDump(void*)
 {
+  auto log = g_slog->withName("carbon");
   try {
     static thread_local auto configHolder = g_carbonConfig.getLocal();
 
@@ -66,21 +68,27 @@ void doCarbonDump(void*)
 
       auto ret = asendtcp(msg, handler); // this will actually do the right thing waiting on the connect
       if (ret == LWResult::Result::Timeout) {
-        g_log << Logger::Warning << "Timeout connecting/writing carbon data to " << remote.toStringWithPort() << endl;
+        SLOG(g_log << Logger::Warning << "Timeout connecting/writing carbon data to " << remote.toStringWithPort() << endl,
+             log->info(Logr::Warning, "Timeout connecting/writing carbon data", "address", Logging::Loggable(remote)));
       }
       else if (ret != LWResult::Result::Success) {
-        g_log << Logger::Warning << "Error writing carbon data to " << remote.toStringWithPort() << ": " << stringerror() << endl;
+        int err = errno;
+        SLOG(g_log << Logger::Warning << "Error writing carbon data to " << remote.toStringWithPort() << ": " << stringerror(err) << endl,
+             log->error(Logr::Warning, err, "Error writing carbon data", "address", Logging::Loggable(remote)));
       }
       handler->close();
     }
   }
   catch (const PDNSException& e) {
-    g_log << Logger::Error << "Error in carbon thread: " << e.reason << endl;
+    SLOG(g_log << Logger::Error << "Error in carbon thread: " << e.reason << endl,
+         log->error(Logr::Error, e.reason, "Error in carbon thread", "exception", Logging::Loggable("PDNSException")));
   }
   catch (const std::exception& e) {
-    g_log << Logger::Error << "Error in carbon thread: " << e.what() << endl;
+    SLOG(g_log << Logger::Error << "Error in carbon thread: " << e.what() << endl,
+         log->error(Logr::Error, e.what(), "Error in carbon thread", "exception", Logging::Loggable("std::exception")));
   }
   catch (...) {
-    g_log << Logger::Error << "Unknown error in carbon thread" << endl;
+    SLOG(g_log << Logger::Error << "Unknown error in carbon thread" << endl,
+         log->info(Logr::Error, "Error in carbon thread"));
   }
 }
index 0f76cadd838cb602237a6438b8211907e18c321e..d3eb3e4c4cee32c038b6773a1207e77bcaff1a79 100644 (file)
@@ -5,6 +5,7 @@
 #include "rec_channel.hh"
 
 #include "logger.hh"
+#include "logging.hh"
 
 #ifdef HAVE_NET_SNMP
 
@@ -200,12 +201,14 @@ static int handleDisabledCounter64Stats(netsnmp_mib_handler* handler,
 static void registerCounter64Stat(const std::string& name, const oid statOID[], size_t statOIDLength)
 {
   if (statOIDLength != OID_LENGTH(questionsOID)) {
-    g_log << Logger::Error << "Invalid OID for SNMP Counter64 statistic " << name << endl;
+    SLOG(g_log << Logger::Error << "Invalid OID for SNMP Counter64 statistic " << name << endl,
+         g_slog->withName("snmp")->info(Logr::Error, "Invalid OID for SNMP Counter64 statistic", "name", Logging::Loggable(name)));
     return;
   }
 
   if (s_statsMap.find(statOID[statOIDLength - 1]) != s_statsMap.end()) {
-    g_log << Logger::Error << "OID for SNMP Counter64 statistic " << name << " has already been registered" << endl;
+    SLOG(g_log << Logger::Error << "OID for SNMP Counter64 statistic " << name << " has already been registered" << endl,
+         g_slog->withName("snmp")->info(Logr::Error, "OID for SNMP Counter64 statistic has already been registered", "name", Logging::Loggable(name)));
     return;
   }
 
index e9a25bfc16ec9a1b51d72837c1d6ac98dcc94f88..ea8b9908d00f7c89b7bc14d8a959e28121e0c28b 100644 (file)
@@ -25,6 +25,7 @@
 
 #include "dnsname.hh"
 #include "logger.hh"
+#include "logging.hh"
 #include "misc.hh"
 #include "pubsuffix.hh"
 
@@ -66,11 +67,13 @@ void initPublicSuffixList(const std::string& file)
         }
       }
 
-      g_log << Logger::Info << "Loaded the Public Suffix List from '" << file << "'" << endl;
+      SLOG(g_log << Logger::Info << "Loaded the Public Suffix List from '" << file << "'" << endl,
+           g_slog->withName("runtime")->info(Logr::Info, "Loaded the Public Suffix List", "file", Logging::Loggable(file)));
       loaded = true;
     }
     catch (const std::exception& e) {
-      g_log << Logger::Warning << "Error while loading the Public Suffix List from '" << file << "', falling back to the built-in list: " << e.what() << endl;
+      SLOG(g_log << Logger::Warning << "Error while loading the Public Suffix List from '" << file << "', falling back to the built-in list: " << e.what() << endl,
+           g_slog->withName("runtime")->error(Logr::Error, e.what(), "Loaded the Public Suffix List", "file", Logging::Loggable(file)));
     }
   }
 
index 52a0386db92cd6c9d16749506f487b1f57e9cd1f..a92ee3f8b953ca12da54e79449e8265da4cbf1f1 100644 (file)
@@ -468,7 +468,7 @@ void RPZIXFRTracker(const std::vector<ComboAddress>& primaries, const boost::opt
       auto soa = getRR<SOARecordContent>(dr);
       auto serial = soa ? soa->d_st.serial : 0;
       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)));
+           logger->info(Logr::Info, "Getting IXFR deltas", "address", Logging::Loggable(primary), "ourserial", Logging::Loggable(serial)));
 
       ComboAddress local(localAddress);
       if (local == ComboAddress()) {
index 07fdafe868cbe6cbf12494d912aa0eea3b6028a7..c137dcd56094582ee95b59b8e1017ddb890bb6d7 100644 (file)
@@ -5012,8 +5012,13 @@ static void updateDoTStatus(ComboAddress address, DoTStatus::Status status, time
 
 bool SyncRes::tryDoT(const DNSName& qname, const QType qtype, const DNSName& nsName, ComboAddress address, time_t now)
 {
-  auto logHelper = [](const string& msg) {
-    g_log<<Logger::Debug<<"Failed to probe DoT records, got an exception: "<<msg<<endl;
+  auto log = g_slog->withName("taskq")->withValues("method", Logging::Loggable("tryDoT"), "name", Logging::Loggable(qname), "qtype", Logging::Loggable(QType(qtype).toString()), "ip", Logging::Loggable(address));
+
+  auto logHelper1 = [&log](const string& ename) {
+    log->info(Logr::Debug, "Failed to probe DoT records, got an exception", "exception", Logging::Loggable(ename));
+  };
+  auto logHelper2 = [&log](const string& msg, const string& ename) {
+    log->error(Logr::Debug, msg, "Failed to probe DoT records, got an exception", "exception", Logging::Loggable(ename));
   };
   LWResult lwr;
   bool truncated;
@@ -5027,19 +5032,19 @@ bool SyncRes::tryDoT(const DNSName& qname, const QType qtype, const DNSName& nsN
     ok = ok && lwr.d_rcode == RCode::NoError && lwr.d_records.size() > 0;
   }
   catch(const PDNSException& e) {
-    logHelper(e.reason);
+    logHelper2(e.reason, "PDNSException");
   }
   catch(const ImmediateServFailException& e) {
-    logHelper(e.reason);
+    logHelper2(e.reason, "ImmediateServFailException");
   }
   catch(const PolicyHitException& e) {
-    logHelper("PolicyHitException");
+    logHelper1("PolicyHitException");
   }
   catch(const std::exception& e) {
-    logHelper(e.what());
+    logHelper2(e.what(), "std::exception");
   }
   catch(...) {
-    logHelper("other");
+    logHelper1("other");
   }
   updateDoTStatus(address, ok ? DoTStatus::Good : DoTStatus::Bad, now + (ok ? dotSuccessWait : dotFailWait), true);
   return ok;
index 4318117d0a2da5d7009efc7c5c348844f778da7a..39e904ce9111d7edea29035c9bd5415e12508c20 100644 (file)
@@ -35,6 +35,7 @@
 #include "dolog.hh"
 #else
 #include "logger.hh"
+#include "logging.hh"
 #endif
 
 #include "threadname.hh"
@@ -72,7 +73,8 @@ void setThreadName(const std::string& threadName) {
 #ifdef DNSDIST
     warnlog("Could not set thread name %s for thread: %s", threadName, strerror(retval));
 #else
-    g_log<<Logger::Warning<<"Could not set thread name "<<threadName<<" for thread: "<<strerror(retval)<<endl;
+    SLOG(g_log<<Logger::Warning<<"Could not set thread name "<<threadName<<" for thread: "<<strerror(retval)<<endl,
+         g_slog->withName("runtime")->error(Logr::Warning, retval, "Could not set thread name", "name", Logging::Loggable(threadName)));
 #endif
   }
 }
index 8d209275d2e3f3ee3322db5e990914c25d102d17..763885916f694576b2c56e62a6a95d2ebf29a6f3 100644 (file)
 #include <cstring>
 #include <fcntl.h>
 #include <unistd.h>
-#include <stdlib.h> 
+#include <stdlib.h>
 #include "pdnsexception.hh"
 #include "logger.hh"
+#include "logging.hh"
 #include "misc.hh"
 #include <pwd.h>
 #include <grp.h>
@@ -83,23 +84,35 @@ void Utility::setBindAny(int af, sock_t sock)
 
   (void) one; // avoids 'unused var' warning on systems that have none of the defines checked below
 #ifdef IP_FREEBIND
-  if (setsockopt(sock, IPPROTO_IP, IP_FREEBIND, &one, sizeof(one)) < 0)
-      g_log<<Logger::Warning<<"Warning: IP_FREEBIND setsockopt failed: "<<stringerror()<<endl;
+  if (setsockopt(sock, IPPROTO_IP, IP_FREEBIND, &one, sizeof(one)) < 0) {
+    int err = errno;
+    SLOG(g_log<<Logger::Warning<<"Warning: IP_FREEBIND setsockopt failed: "<<stringerror(err)<<endl,
+         g_slog->withName("runtime")->error(Logr::Warning, err, "Warning: IP_FREEBIND setsockopt failed"));
+  }
 #endif
 
 #ifdef IP_BINDANY
   if (af == AF_INET)
-    if (setsockopt(sock, IPPROTO_IP, IP_BINDANY, &one, sizeof(one)) < 0)
-      g_log<<Logger::Warning<<"Warning: IP_BINDANY setsockopt failed: "<<stringerror()<<endl;
+    if (setsockopt(sock, IPPROTO_IP, IP_BINDANY, &one, sizeof(one)) < 0) {
+      int err = errno;
+      SLOG(g_log<<Logger::Warning<<"Warning: IP_BINDANY setsockopt failed: "<<stringerror(err)<<endl,
+           g_slog->withName("runtime")->error(Logr::Warning, err, "Warning: IP_BINDANY setsockopt failed"));
+    }
 #endif
 #ifdef IPV6_BINDANY
-  if (af == AF_INET6)
-    if (setsockopt(sock, IPPROTO_IPV6, IPV6_BINDANY, &one, sizeof(one)) < 0)
-      g_log<<Logger::Warning<<"Warning: IPV6_BINDANY setsockopt failed: "<<stringerror()<<endl;
+  if (af == AF_INET6) {
+    if (setsockopt(sock, IPPROTO_IPV6, IPV6_BINDANY, &one, sizeof(one)) < 0) {
+      SLOG(g_log<<Logger::Warning<<"Warning: IPV6_BINDANY setsockopt failed: "<<stringerror(err)<<endl,
+           g_slog->withName("runtime")->error(Logr::Warning, err, ""Warning: IPV6_BINDANY setsockopt failed"));
+    }
+  }
 #endif
 #ifdef SO_BINDANY
-  if (setsockopt(sock, SOL_SOCKET, SO_BINDANY, &one, sizeof(one)) < 0)
-      g_log<<Logger::Warning<<"Warning: SO_BINDANY setsockopt failed: "<<stringerror()<<endl;
+  if (setsockopt(sock, SOL_SOCKET, SO_BINDANY, &one, sizeof(one)) < 0) {
+    int err = errno;
+    SLOG(g_log<<Logger::Warning<<"Warning: SO_BINDANY setsockopt failed: "<<stringerror(err)<<endl,
+         g_slog->withName("runtime")->error(Logr::Warning, err, "Warning: SO_BINDANY setsockopt failed"));
+  }
 #endif
 }
 
@@ -128,22 +141,30 @@ void Utility::dropGroupPrivs( uid_t uid, gid_t gid )
 {
   if(gid && gid != getegid()) {
     if(setgid(gid)<0) {
-      g_log<<Logger::Critical<<"Unable to set effective group id to "<<gid<<": "<<stringerror()<<endl;
+      int err = errno;
+      SLOG(g_log<<Logger::Critical<<"Unable to set effective group id to "<<gid<<": "<<stringerror(err)<<endl,
+           g_slog->withName("runtime")->error(Logr::Critical, err, "Unable to set effective group id", "gid", Logging::Loggable(gid)));
       exit(1);
     }
-    else
-      g_log<<Logger::Info<<"Set effective group id to "<<gid<<endl;
-
+    else {
+      SLOG(g_log<<Logger::Info<<"Set effective group id to "<<gid<<endl,
+           g_slog->withName("runtime")->info(Logr::Info, "Set effective group id", "gid", Logging::Loggable(gid)));
+    }
     struct passwd *pw=getpwuid(uid);
     if(!pw) {
-      g_log<<Logger::Warning<<"Unable to determine user name for uid "<<uid<<endl;
+      SLOG(g_log<<Logger::Warning<<"Unable to determine user name for uid "<<uid<<endl,
+           g_slog->withName("runtime")->info(Logr::Warning, "Unable to determine user name", "uid", Logging::Loggable(uid)));
       if (setgroups(0, nullptr)<0) {
-        g_log<<Logger::Critical<<"Unable to drop supplementary gids: "<<stringerror()<<endl;
+        int err = errno;
+        SLOG(g_log<<Logger::Critical<<"Unable to drop supplementary gids: "<<stringerror(err)<<endl,
+             g_slog->withName("runtime")->error(Logr::Critical, err, "Unable to drop supplementary gids"));
         exit(1);
       }
     } else {
       if (initgroups(pw->pw_name, gid)<0) {
-        g_log<<Logger::Critical<<"Unable to set supplementary groups: "<<stringerror()<<endl;
+        int err = errno;
+        SLOG(g_log<<Logger::Critical<<"Unable to set supplementary groups: "<<stringerror(err)<<endl,
+             g_slog->withName("runtime")->error(Logr::Critical, err, "Unable to drop supplementary groups"));
         exit(1);
       }
     }
@@ -156,11 +177,15 @@ void Utility::dropUserPrivs( uid_t uid )
 {
   if(uid && uid != geteuid()) {
     if(setuid(uid)<0) {
-      g_log<<Logger::Critical<<"Unable to set effective user id to "<<uid<<": "<<stringerror()<<endl;
+      int err = errno;
+      SLOG(g_log<<Logger::Critical<<"Unable to set effective user id to "<<uid<<": "<<stringerror(err)<<endl,
+           g_slog->withName("runtime")->error(Logr::Error, err, "Unable to set effective user id", "uid", Logging::Loggable(uid)));
       exit(1);
     }
-    else
-      g_log<<Logger::Info<<"Set effective user id to "<<uid<<endl;
+    else {
+      SLOG(g_log<<Logger::Info<<"Set effective user id to "<<uid<<endl,
+           g_slog->withName("runtime")->info("Set effective user", "uid", Logging::Loggable(uid)));
+    }
   }
 }