]> git.ipfire.org Git - thirdparty/pdns.git/commitdiff
dnsdist: More structured logging conversions
authorRemi Gacogne <remi.gacogne@powerdns.com>
Tue, 9 Dec 2025 16:17:07 +0000 (17:17 +0100)
committerRemi Gacogne <remi.gacogne@powerdns.com>
Mon, 19 Jan 2026 09:55:39 +0000 (10:55 +0100)
Signed-off-by: Remi Gacogne <remi.gacogne@powerdns.com>
17 files changed:
pdns/dnsdistdist/Makefile.am
pdns/dnsdistdist/dnsdist-actions-factory.cc
pdns/dnsdistdist/dnsdist-async.cc
pdns/dnsdistdist/dnsdist-backend.cc
pdns/dnsdistdist/dnsdist-dnsquestion.cc
pdns/dnsdistdist/dnsdist-doh-common.hh
pdns/dnsdistdist/dnsdist-lua-web.cc
pdns/dnsdistdist/dnsdist-web.cc
pdns/dnsdistdist/dnsdist-xsk.cc
pdns/dnsdistdist/dnsdist.cc
pdns/dnsdistdist/dnsdist.hh
pdns/dnsdistdist/doh3.cc
pdns/dnsdistdist/doh3.hh
pdns/dnsdistdist/doq-common.cc
pdns/dnsdistdist/doq.cc
pdns/dnsdistdist/doq.hh
pdns/dnsdistdist/test-dnsdistnghttp2-in_cc.cc

index eb615dc02ef9f03a85f06212a60f730fa0daffa8..b58b4fb9d3cdcd7c8adb8e9064965a03c973b2a1 100644 (file)
@@ -641,6 +641,7 @@ fuzz_target_dnsdistcache_SOURCES = \
        ext/json11/json11.cpp \
        ext/json11/json11.hpp \
        fuzz_dnsdistcache.cc \
+       gettime.cc gettime.hh \
        iputils.cc iputils.hh \
        logging.cc logging.hh \
        misc.cc misc.hh \
index 78075473705f56361568c701533f8aaad2c10232..290b29021ccbfb0fc2fb97d7f0bb8a46dc668153 100644 (file)
@@ -549,10 +549,12 @@ public:
       return result;
     }
     catch (const std::exception& e) {
-      warnlog("LuaAction failed inside Lua, returning ServFail: %s", e.what());
+      SLOG(warnlog("LuaAction failed inside Lua, returning ServFail: %s", e.what()),
+           dnsquestion->getLogger()->error(Logr::Warning, e.what(), "LuaAction failed inside Lua, returning ServFail"));
     }
     catch (...) {
-      warnlog("LuaAction failed inside Lua, returning ServFail: [unknown exception]");
+      SLOG(warnlog("LuaAction failed inside Lua, returning ServFail: [unknown exception]"),
+           dnsquestion->getLogger()->error(Logr::Warning, "[unknown exception]", "LuaAction failed inside Lua, returning ServFail"));
     }
     return DNSAction::Action::ServFail;
   }
@@ -594,10 +596,12 @@ public:
       return result;
     }
     catch (const std::exception& e) {
-      warnlog("LuaResponseAction failed inside Lua, returning ServFail: %s", e.what());
+      SLOG(warnlog("LuaResponseAction failed inside Lua, returning ServFail: %s", e.what()),
+           response->getLogger()->error(Logr::Warning, e.what(), "LuaResponseAction failed inside Lua, returning ServFail"));
     }
     catch (...) {
-      warnlog("LuaResponseAction failed inside Lua, returning ServFail: [unknown exception]");
+      SLOG(warnlog("LuaResponseAction failed inside Lua, returning ServFail: [unknown exception]"),
+           response->getLogger()->error(Logr::Warning, "[unknown exception]", "LuaResponseAction failed inside Lua, returning ServFail"));
     }
     return DNSResponseAction::Action::ServFail;
   }
@@ -642,10 +646,12 @@ public:
       return result;
     }
     catch (const std::exception& e) {
-      warnlog("LuaFFIAction failed inside Lua, returning ServFail: %s", e.what());
+      SLOG(warnlog("LuaFFIAction failed inside Lua, returning ServFail: %s", e.what()),
+           dnsquestion->getLogger()->error(Logr::Warning, e.what(), "LuaFFIAction failed inside Lua, returning ServFail"));
     }
     catch (...) {
-      warnlog("LuaFFIAction failed inside Lua, returning ServFail: [unknown exception]");
+      SLOG(warnlog("LuaFFIAction failed inside Lua, returning ServFail: [unknown exception]"),
+           dnsquestion->getLogger()->error(Logr::Warning, "[unknown exception]", "LuaFFIAction failed inside Lua, returning ServFail"));
     }
     return DNSAction::Action::ServFail;
   }
@@ -699,10 +705,12 @@ public:
       return static_cast<DNSAction::Action>(ret);
     }
     catch (const std::exception& e) {
-      warnlog("LuaFFIPerThreadAction failed inside Lua, returning ServFail: %s", e.what());
+      SLOG(warnlog("LuaFFIPerthreadAction failed inside Lua, returning ServFail: %s", e.what()),
+           dnsquestion->getLogger()->error(Logr::Warning, e.what(), "LuaFFIPerthreadAction failed inside Lua, returning ServFail"));
     }
     catch (...) {
-      warnlog("LuaFFIPerthreadAction failed inside Lua, returning ServFail: [unknown exception]");
+      SLOG(warnlog("LuaFFIPerthreadAction failed inside Lua, returning ServFail: [unknown exception]"),
+           dnsquestion->getLogger()->error(Logr::Warning, "[unknown exception]", "LuaFFIPerthreadAction failed inside Lua, returning ServFail"));
     }
     return DNSAction::Action::ServFail;
   }
@@ -761,10 +769,12 @@ public:
       return result;
     }
     catch (const std::exception& e) {
-      warnlog("LuaFFIResponseAction failed inside Lua, returning ServFail: %s", e.what());
+      SLOG(warnlog("LuaFFIResponseAction failed inside Lua, returning ServFail: %s", e.what()),
+           response->getLogger()->error(Logr::Warning, e.what(), "LuaFFIResponseAction failed inside Lua, returning ServFail"));
     }
     catch (...) {
-      warnlog("LuaFFIResponseAction failed inside Lua, returning ServFail: [unknown exception]");
+      SLOG(warnlog("LuaFFIResponseAction failed inside Lua, returning ServFail: [unknown exception]"),
+           response->getLogger()->error(Logr::Warning, "[unknown exception]", "LuaFFIResponseAction failed inside Lua, returning ServFail"));
     }
     return DNSResponseAction::Action::ServFail;
   }
@@ -818,10 +828,12 @@ public:
       return static_cast<DNSResponseAction::Action>(ret);
     }
     catch (const std::exception& e) {
-      warnlog("LuaFFIPerThreadResponseAction failed inside Lua, returning ServFail: %s", e.what());
+      SLOG(warnlog("LuaFFIPerThreadResponseAction failed inside Lua, returning ServFail: %s", e.what()),
+           response->getLogger()->error(Logr::Warning, e.what(), "LuaFFIPerThreadResponseAction failed inside Lua, returning ServFail"));
     }
     catch (...) {
-      warnlog("LuaFFIPerthreadResponseAction failed inside Lua, returning ServFail: [unknown exception]");
+      SLOG(warnlog("LuaFFIPerThreadResponseAction failed inside Lua, returning ServFail: [unknown exception]"),
+           response->getLogger()->error(Logr::Warning, "[unknown exception]", "LuaFFIPerThreadResponseAction failed inside Lua, returning ServFail"));
     }
     return DNSResponseAction::Action::ServFail;
   }
@@ -1109,10 +1121,12 @@ public:
     if (!filepointer) {
       if (!d_verboseOnly || dnsdist::configuration::getCurrentRuntimeConfiguration().d_verbose) {
         if (d_includeTimestamp) {
-          infolog("[%u.%u] Packet from %s for %s %s with id %d", static_cast<unsigned long long>(dnsquestion->getQueryRealTime().tv_sec), static_cast<unsigned long>(dnsquestion->getQueryRealTime().tv_nsec), dnsquestion->ids.origRemote.toStringWithPort(), dnsquestion->ids.qname.toString(), QType(dnsquestion->ids.qtype).toString(), dnsquestion->getHeader()->id);
+          SLOG(infolog("[%u.%u] Packet from %s for %s %s with id %d", static_cast<unsigned long long>(dnsquestion->getQueryRealTime().tv_sec), static_cast<unsigned long>(dnsquestion->getQueryRealTime().tv_nsec), dnsquestion->ids.origRemote.toStringWithPort(), dnsquestion->ids.qname.toString(), QType(dnsquestion->ids.qtype).toString(), dnsquestion->getHeader()->id),
+               dnsquestion->getLogger()->info(Logr::Info, "Logging packet", "query-real-time-sec", Logging::Loggable(dnsquestion->getQueryRealTime().tv_sec), "query-real-time-nsec", Logging::Loggable(dnsquestion->getQueryRealTime().tv_nsec)));
         }
         else {
-          infolog("Packet from %s for %s %s with id %d", dnsquestion->ids.origRemote.toStringWithPort(), dnsquestion->ids.qname.toString(), QType(dnsquestion->ids.qtype).toString(), dnsquestion->getHeader()->id);
+          SLOG(infolog("Packet from %s for %s %s with id %d", dnsquestion->ids.origRemote.toStringWithPort(), dnsquestion->ids.qname.toString(), QType(dnsquestion->ids.qtype).toString(), dnsquestion->getHeader()->id),
+               dnsquestion->getLogger()->info(Logr::Info, "Logging packet"));
         }
       }
     }
@@ -1161,7 +1175,9 @@ public:
   void reload() override
   {
     if (!reopenLogFile()) {
-      warnlog("Unable to open file '%s' for logging: %s", d_fname, stringerror());
+      int savederrno = errno;
+      SLOG(warnlog("Unable to open file '%s' for logging: %s", d_fname, stringerror(savederrno)),
+           dnsdist::logging::getTopLogger()->error(Logr::Warning, savederrno, "Unable to open file for logging", "file-name", Logging::Loggable(d_fname)));
     }
   }
 
@@ -1222,10 +1238,12 @@ public:
     if (!filepointer) {
       if (!d_verboseOnly || dnsdist::configuration::getCurrentRuntimeConfiguration().d_verbose) {
         if (d_includeTimestamp) {
-          infolog("[%u.%u] Answer to %s for %s %s (%s) with id %u", static_cast<unsigned long long>(response->getQueryRealTime().tv_sec), static_cast<unsigned long>(response->getQueryRealTime().tv_nsec), response->ids.origRemote.toStringWithPort(), response->ids.qname.toString(), QType(response->ids.qtype).toString(), RCode::to_s(response->getHeader()->rcode), response->getHeader()->id);
+          SLOG(infolog("[%u.%u] Answer to %s for %s %s (%s) with id %u", static_cast<unsigned long long>(response->getQueryRealTime().tv_sec), static_cast<unsigned long>(response->getQueryRealTime().tv_nsec), response->ids.origRemote.toStringWithPort(), response->ids.qname.toString(), QType(response->ids.qtype).toString(), RCode::to_s(response->getHeader()->rcode), response->getHeader()->id),
+               response->getLogger()->info(Logr::Info, "Logging response packet", "query-real-time-sec", Logging::Loggable(response->getQueryRealTime().tv_sec), "query-real-time-nsec", Logging::Loggable(response->getQueryRealTime().tv_nsec)));
         }
         else {
-          infolog("Answer to %s for %s %s (%s) with id %u", response->ids.origRemote.toStringWithPort(), response->ids.qname.toString(), QType(response->ids.qtype).toString(), RCode::to_s(response->getHeader()->rcode), response->getHeader()->id);
+          SLOG(infolog("Answer to %s for %s %s (%s) with id %u", response->ids.origRemote.toStringWithPort(), response->ids.qname.toString(), QType(response->ids.qtype).toString(), RCode::to_s(response->getHeader()->rcode), response->getHeader()->id),
+               response->getLogger()->info("Logging response packet"));
         }
       }
     }
@@ -1251,7 +1269,9 @@ public:
   void reload() override
   {
     if (!reopenLogFile()) {
-      warnlog("Unable to open file '%s' for logging: %s", d_fname, stringerror());
+      int savederrno = errno;
+      SLOG(warnlog("Unable to open file '%s' for logging: %s", d_fname, stringerror(savederrno)),
+           dnsdist::logging::getTopLogger()->error(Logr::Warning, savederrno, "Unable to open file for logging", "file-name", Logging::Loggable(d_fname)));
     }
   }
 
@@ -1503,15 +1523,18 @@ static void remoteLoggerQueueData(RemoteLoggerInterface& remoteLogger, const std
   case RemoteLoggerInterface::Result::Queued:
     break;
   case RemoteLoggerInterface::Result::PipeFull: {
-    vinfolog("%s: %s", remoteLogger.name(), RemoteLoggerInterface::toErrorString(ret));
+    VERBOSESLOG(infolog("%s: %s", remoteLogger.name(), RemoteLoggerInterface::toErrorString(ret)),
+                dnsdist::logging::getTopLogger()->error(Logr::Info, RemoteLoggerInterface::toErrorString(ret), "Remote logger pipe full event", "remote-logger-name", Logging::Loggable(remoteLogger.name())));
     break;
   }
   case RemoteLoggerInterface::Result::TooLarge: {
-    warnlog("%s: %s", remoteLogger.name(), RemoteLoggerInterface::toErrorString(ret));
+    SLOG(warnlog("%s: %s", remoteLogger.name(), RemoteLoggerInterface::toErrorString(ret)),
+         dnsdist::logging::getTopLogger()->error(Logr::Warning, RemoteLoggerInterface::toErrorString(ret), "Remote logger too large event", "remote-logger-name", Logging::Loggable(remoteLogger.name())));
     break;
   }
   case RemoteLoggerInterface::Result::OtherError:
-    warnlog("%s: %s", remoteLogger.name(), RemoteLoggerInterface::toErrorString(ret));
+    SLOG(warnlog("%s: %s", remoteLogger.name(), RemoteLoggerInterface::toErrorString(ret)),
+         dnsdist::logging::getTopLogger()->error(Logr::Warning, RemoteLoggerInterface::toErrorString(ret), "Remote logger error event", "remote-logger-name", Logging::Loggable(remoteLogger.name())));
   }
 }
 
@@ -1694,7 +1717,8 @@ public:
   {
     auto tracer = dnsquestion->ids.getTracer();
     if (tracer == nullptr) {
-      vinfolog("SetTraceAction called, but OpenTelemetry tracing is globally disabled. Did you forget to call setOpenTelemetryTracing?");
+      VERBOSESLOG(infolog("SetTraceAction called, but OpenTelemetry tracing is globally disabled. Did you forget to call setOpenTelemetryTracing?"),
+                  dnsquestion->getLogger()->info(Logr::Info, "SetTraceAction called, but OpenTelemetry tracing is globally disabled. Did you forget to call setOpenTelemetryTracing?"));
       return Action::None;
     }
 
@@ -1724,7 +1748,8 @@ public:
     }
     if (dnsquestion->ednsOptions == nullptr) {
       // Parsing failed, log a warning and return
-      vinfolog("parsing EDNS options failed while looking for OpenTelemetry Trace ID");
+      VERBOSESLOG(infolog("parsing EDNS options failed while looking for OpenTelemetry Trace ID"),
+                  dnsquestion->getLogger()->info(Logr::Info, "Parsing EDNS options failed while looking for OpenTelemetry Trace ID"));
       return Action::None;
     }
 
@@ -1750,7 +1775,8 @@ public:
       }
 
       if (!last) {
-        vinfolog("SetTraceAction: EDNS options is not the last RR in the packet, not removing TRACEPARENT");
+        VERBOSESLOG(infolog("SetTraceAction: EDNS options is not the last RR in the packet, not removing TRACEPARENT"),
+                    dnsquestion->getLogger()->info(Logr::Info, "SetTraceAction: EDNS options is not the last RR in the packet, not removing TRACEPARENT"));
         return Action::None;
       }
 
index 194077cdf7b9b8d1c39614bac153a957cb78761d..65241b5f99da4174b65faa8365f7873869a5b18e 100644 (file)
@@ -135,7 +135,8 @@ void AsynchronousHolder::mainThread(std::shared_ptr<Data> data)
       auto [queryID, query] = std::move(expiredEvents.front());
       expiredEvents.pop_front();
       if (!data->d_failOpen) {
-        vinfolog("Asynchronous query %d has expired at %d.%d, notifying the sender", queryID, now.tv_sec, now.tv_usec);
+        VERBOSESLOG(infolog("Asynchronous query %d has expired at %d.%d, notifying the sender", queryID, now.tv_sec, now.tv_usec),
+                    dnsdist::logging::getTopLogger()->info(Logr::Info, "Asynchronous query has expired, notifying the sender", "query-id", Logging::Loggable(queryID)));
         auto sender = query->getTCPQuerySender();
         if (sender) {
           TCPResponse tresponse(std::move(query->query));
@@ -143,7 +144,8 @@ void AsynchronousHolder::mainThread(std::shared_ptr<Data> data)
         }
       }
       else {
-        vinfolog("Asynchronous query %d has expired at %d.%d, resuming", queryID, now.tv_sec, now.tv_usec);
+        VERBOSESLOG(infolog("Asynchronous query %d has expired at %d.%d, resuming", queryID, now.tv_sec, now.tv_usec),
+                    dnsdist::logging::getTopLogger()->info(Logr::Info, "Asynchronous query has expired, resuming", "query-id", Logging::Loggable(queryID)));
         resumeQuery(std::move(query));
       }
     }
@@ -181,9 +183,10 @@ std::unique_ptr<CrossProtocolQuery> AsynchronousHolder::get(uint16_t asyncID, ui
   auto content = d_data->d_content.lock();
   auto contentIt = content->find(std::tie(queryID, asyncID));
   if (contentIt == content->end()) {
-    struct timeval now{};
+    timeval now{};
     gettimeofday(&now, nullptr);
-    vinfolog("Asynchronous object %d not found at %d.%d", queryID, now.tv_sec, now.tv_usec);
+    VERBOSESLOG(infolog("Asynchronous object %d not found at %d.%d", queryID, now.tv_sec, now.tv_usec),
+                dnsdist::logging::getTopLogger()->info(Logr::Info, "Asynchronous object not found", "async-id", Logging::Loggable(asyncID), "query-id", Logging::Loggable(queryID)));
     return nullptr;
   }
 
@@ -238,7 +241,8 @@ static bool resumeResponse(std::unique_ptr<CrossProtocolQuery>&& response)
     }
   }
   catch (const std::exception& e) {
-    vinfolog("Got exception while resuming cross-protocol response: %s", e.what());
+    VERBOSESLOG(infolog("Got exception while resuming cross-protocol response: %s", e.what()),
+                dnsdist::logging::getTopLogger()->error(Logr::Info, e.what(), "Got exception while resuming cross-protocol response"));
     return false;
   }
 
@@ -268,7 +272,8 @@ void handleQueuedAsynchronousEvents()
       queue->pop_front();
     }
     if (query && !resumeQuery(std::move(query))) {
-      vinfolog("Unable to resume asynchronous query event");
+      VERBOSESLOG(infolog("Unable to resume asynchronous query event"),
+                  dnsdist::logging::getTopLogger()->info(Logr::Info, "Unable to resume asynchronous query event"));
     }
   }
 }
@@ -326,13 +331,15 @@ bool resumeQuery(std::unique_ptr<CrossProtocolQuery>&& query)
       return true;
     }
     catch (const std::exception& e) {
-      vinfolog("Got exception while resuming cross-protocol self-answered query: %s", e.what());
+      VERBOSESLOG(infolog("Got exception while resuming cross-protocol self-answered query: %s", e.what()),
+                  dnsdist::logging::getTopLogger()->error(Logr::Info, e.what(), "Got exception while resuming cross-protocol self-answered query"));
       return false;
     }
   }
   if (result == ProcessQueryResult::Asynchronous) {
     /* nope */
-    errlog("processQueryAfterRules returned 'asynchronous' while trying to resume an already asynchronous query");
+    SLOG(errlog("processQueryAfterRules returned 'asynchronous' while trying to resume an already asynchronous query"),
+         dnsdist::logging::getTopLogger()->info(Logr::Info, "processQueryAfterRules returned 'asynchronous' while trying to resume an already asynchronous query"));
     return false;
   }
 
@@ -352,7 +359,8 @@ bool suspendQuery(DNSQuestion& dnsQuestion, uint16_t asyncID, uint16_t queryID,
   ttd.tv_usec += static_cast<decltype(ttd.tv_usec)>((timeoutMs % 1000) * 1000);
   normalizeTV(ttd);
 
-  vinfolog("Suspending asynchronous query %d at %d.%d until %d.%d", queryID, now.tv_sec, now.tv_usec, ttd.tv_sec, ttd.tv_usec);
+  VERBOSESLOG(infolog("Suspending asynchronous query %d at %d.%d until %d.%d", queryID, now.tv_sec, now.tv_usec, ttd.tv_sec, ttd.tv_usec),
+              dnsQuestion.getLogger()->info(Logr::Info, "Suspending asynchronous query", "until-sec", Logging::Loggable(ttd.tv_sec), "until-usec", Logging::Loggable(ttd.tv_usec)));
   auto query = getInternalQueryFromDQ(dnsQuestion, false);
 
   g_asyncHolder->push(asyncID, queryID, ttd, std::move(query));
@@ -372,7 +380,8 @@ bool suspendResponse(DNSResponse& dnsResponse, uint16_t asyncID, uint16_t queryI
   ttd.tv_usec += static_cast<decltype(ttd.tv_usec)>((timeoutMs % 1000) * 1000);
   normalizeTV(ttd);
 
-  vinfolog("Suspending asynchronous response %d at %d.%d until %d.%d", queryID, now.tv_sec, now.tv_usec, ttd.tv_sec, ttd.tv_usec);
+  VERBOSESLOG(infolog("Suspending asynchronous response %d at %d.%d until %d.%d", queryID, now.tv_sec, now.tv_usec, ttd.tv_sec, ttd.tv_usec),
+              dnsResponse.getLogger()->info(Logr::Info, "Suspending asynchronous response", "until-sec", Logging::Loggable(ttd.tv_sec), "until-usec", Logging::Loggable(ttd.tv_usec)));
   auto query = getInternalQueryFromDQ(dnsResponse, true);
   query->d_isResponse = true;
   query->downstream = dnsResponse.d_downstream;
index a755f5be417652cfc048f0723c0348a88950c459..48ce881ec8d2ee796be5aab747f65dce19ef0a67 100644 (file)
@@ -128,7 +128,9 @@ bool DownstreamState::reconnect(bool initialAttempt)
     if (!d_config.sourceItfName.empty()) {
       int res = setsockopt(fd, SOL_SOCKET, SO_BINDTODEVICE, d_config.sourceItfName.c_str(), d_config.sourceItfName.length());
       if (res != 0) {
-        infolog("Error setting up the interface on backend socket '%s': %s", d_config.remote.toStringWithPort(), stringerror());
+        int saved = errno;
+        SLOG(infolog("Error setting up the interface on backend socket '%s': %s", d_config.remote.toStringWithPort(), stringerror(saved)),
+             getLogger()->error(Logr::Info, saved, "Error setting up the interface on backend socket", "source-interface", Logging::Loggable(d_config.sourceItfName)));
       }
     }
 #endif
@@ -158,10 +160,13 @@ bool DownstreamState::reconnect(bool initialAttempt)
     catch (const std::runtime_error& error) {
       if (initialAttempt || dnsdist::configuration::getCurrentRuntimeConfiguration().d_verbose) {
         if (!IsAnyAddress(d_config.sourceAddr) || !d_config.sourceItfName.empty()) {
-            infolog("Error connecting to new server with address %s (source address: %s, source interface: %s): %s", d_config.remote.toStringWithPort(), IsAnyAddress(d_config.sourceAddr) ? "not set" : d_config.sourceAddr.toString(), d_config.sourceItfName.empty() ? "not set" : d_config.sourceItfName, error.what());
+          SLOG(infolog("Error connecting to new server with address %s (source address: %s, source interface: %s): %s", d_config.remote.toStringWithPort(), IsAnyAddress(d_config.sourceAddr) ? "not set" : d_config.sourceAddr.toString(), d_config.sourceItfName.empty() ? "not set" : d_config.sourceItfName, error.what()),
+               getLogger()->error(Logr::Info, error.what(), "Error connecting to server", "source-address", Logging::Loggable(d_config.sourceAddr), "source-interface", Logging::Loggable(d_config.sourceItfName)));
+
           }
         else {
-          infolog("Error connecting to new server with address %s: %s", d_config.remote.toStringWithPort(), error.what());
+          SLOG(infolog("Error connecting to new server with address %s: %s", d_config.remote.toStringWithPort(), error.what()),
+               getLogger()->error(Logr::Info, error.what(), "Error connecting to server"));
         }
       }
       connected = false;
@@ -254,7 +259,9 @@ void DownstreamState::stop()
 void DownstreamState::hash()
 {
   const auto hashPerturbation = dnsdist::configuration::getImmutableConfiguration().d_hashPerturbation;
-  vinfolog("Computing hashes for id=%s and weight=%d, hash_perturbation=%d", *d_config.id, d_config.d_weight, hashPerturbation);
+  VERBOSESLOG(infolog("Computing hashes for id=%s and weight=%d, hash_perturbation=%d", *d_config.id, d_config.d_weight, hashPerturbation),
+              dnsdist::logging::getTopLogger()->info(Logr::Info, "Computing hashes for backend", "id", Logging::Loggable(*d_config.id), "weight", Logging::Loggable(d_config.d_weight), "hash-perturbation", Logging::Loggable(hashPerturbation)));
+
   auto weight = d_config.d_weight;
   auto idStr = boost::str(boost::format("%s") % *d_config.id);
   auto lockedHashes = hashes.write_lock();
@@ -283,7 +290,8 @@ void DownstreamState::setId(const boost::uuids::uuid& newId)
 void DownstreamState::setWeight(int newWeight)
 {
   if (newWeight < 1) {
-    errlog("Error setting server's weight: downstream weight value must be greater than 0.");
+    SLOG(errlog("Error setting server's weight: downstream weight value must be greater than 0."),
+         getLogger()->info(Logr::Error, "Error setting server's weight: downstream weight value must be greater than 0", "weight", Logging::Loggable(newWeight)));
     return ;
   }
 
@@ -449,9 +457,10 @@ void DownstreamState::handleUDPTimeout(IDState& ids)
   ++reuseds;
   --outstanding;
   ++dnsdist::metrics::g_stats.downstreamTimeouts; // this is an 'actively' discovered timeout
-  vinfolog("Had a downstream timeout from %s (%s) for query for %s|%s from %s",
-           d_config.remote.toStringWithPort(), getName(),
-           ids.internal.qname.toLogString(), QType(ids.internal.qtype).toString(), ids.internal.origRemote.toStringWithPort());
+  SLOG(infolog("Had a downstream timeout from %s (%s) for query for %s|%s from %s",
+               d_config.remote.toStringWithPort(), getName(),
+               ids.internal.qname.toLogString(), QType(ids.internal.qtype).toString(), ids.internal.origRemote.toStringWithPort()),
+       getLogger()->info(Logr::Info, "Had a downstream timeout", "qname", Logging::Loggable(ids.internal.qname), "qtype", Logging::Loggable(QType(ids.internal.qtype)), "query-id", Logging::Loggable(ids.internal.origID), "address", Logging::Loggable(ids.internal.origRemote)));
 
   const auto& chains = dnsdist::configuration::getCurrentRuntimeConfiguration().d_ruleChains;
   const auto& timeoutRespRules = dnsdist::rules::getResponseRuleChain(chains, dnsdist::rules::ResponseRuleChain::TimeoutResponseRules);
@@ -684,7 +693,8 @@ bool DownstreamState::healthCheckRequired(std::optional<time_t> currentTime)
   if (d_config.d_healthCheckMode == DownstreamState::HealthCheckMode::Lazy) {
     auto stats = d_lazyHealthCheckStats.lock();
     if (stats->d_status == LazyHealthCheckStats::LazyStatus::PotentialFailure) {
-      vinfolog("Sending health-check query for %s which is still in the Potential Failure state", getNameWithAddr());
+      VERBOSESLOG(infolog("Sending health-check query for %s which is still in the Potential Failure state", getNameWithAddr()),
+                  getLogger()->info(Logr::Info, "Sending health-check query for a backend which is still in the Potential Failure state"));
       return true;
     }
     if (stats->d_status == LazyHealthCheckStats::LazyStatus::Failed) {
@@ -693,7 +703,8 @@ bool DownstreamState::healthCheckRequired(std::optional<time_t> currentTime)
         /* we update the next check time here because the check might time out,
            and we do not want to send a second check during that time unless
            the timer is actually very short */
-        vinfolog("Sending health-check query for %s which is still in the Failed state", getNameWithAddr());
+        VERBOSESLOG(infolog("Sending health-check query for %s which is still in the Failed state", getNameWithAddr()),
+                    getLogger()->info(Logr::Info, "Sending health-check query for backend which is still in the Failed state"));
         updateNextLazyHealthCheck(*stats, true, now);
         return true;
       }
@@ -717,7 +728,8 @@ bool DownstreamState::healthCheckRequired(std::optional<time_t> currentTime)
       auto current = (100.0 * failures) / totalCount;
       if (current >= maxFailureRate) {
         lastResults.clear();
-        vinfolog("Backend %s reached the lazy health-check threshold (%f%% out of %f%%, looking at sample of %d items with %d failures), moving to Potential Failure state", getNameWithAddr(), current, maxFailureRate, totalCount, failures);
+        VERBOSESLOG(infolog("Backend %s reached the lazy health-check threshold (%f%% out of %f%%, looking at sample of %d items with %d failures), moving to Potential Failure state", getNameWithAddr(), current, maxFailureRate, totalCount, failures),
+                    getLogger()->info(Logr::Info, "Backend reached the lazy health-check threshold, moving to Potential failure state", "current-failure-rate", Logging::Loggable(current), "max-failure-rate", Logging::Loggable(maxFailureRate), "samples", Logging::Loggable(totalCount), "failures-count", Logging::Loggable(failures)));
         stats->d_status = LazyHealthCheckStats::LazyStatus::PotentialFailure;
         consecutiveSuccessfulChecks = 0;
         /* we update the next check time here because the check might time out,
@@ -758,7 +770,8 @@ void DownstreamState::updateNextLazyHealthCheck(LazyHealthCheckStats& stats, boo
       /* we are still in the "up" state, we need to send the next query quickly to
          determine if the backend is really down */
       stats.d_nextCheck = now + d_config.checkInterval;
-      vinfolog("Backend %s is in potential failure state, next check in %d seconds", getNameWithAddr(), d_config.checkInterval.load());
+      VERBOSESLOG(infolog("Backend %s is in potential failure state, next check in %d seconds", getNameWithAddr(), d_config.checkInterval.load()),
+                  getLogger()->info(Logr::Info, "Backend is in potential failure state", "next-check", Logging::Loggable(d_config.checkInterval.load())));
     }
     else if (consecutiveSuccessfulChecks > 0) {
       /* we are in 'Failed' state, but just had one (or more) successful check,
@@ -766,7 +779,8 @@ void DownstreamState::updateNextLazyHealthCheck(LazyHealthCheckStats& stats, boo
          be available again. */
       stats.d_nextCheck = now + d_config.d_lazyHealthCheckFailedInterval;
       if (!checkScheduled) {
-        vinfolog("Backend %s is in failed state but had %d consecutive successful checks, next check in %d seconds", getNameWithAddr(), std::to_string(consecutiveSuccessfulChecks), d_config.d_lazyHealthCheckFailedInterval);
+        VERBOSESLOG(infolog("Backend %s is in failed state but had %d consecutive successful checks, next check in %d seconds", getNameWithAddr(), std::to_string(consecutiveSuccessfulChecks), d_config.d_lazyHealthCheckFailedInterval),
+                    getLogger()->info(Logr::Info, "Backend is in failed state but had a successful check", "consecutive-successful-checks", Logging::Loggable(std::to_string(consecutiveSuccessfulChecks)), "next-check", Logging::Loggable(d_config.d_lazyHealthCheckFailedInterval)));
       }
     }
     else {
@@ -790,12 +804,14 @@ void DownstreamState::updateNextLazyHealthCheck(LazyHealthCheckStats& stats, boo
       }
 
       stats.d_nextCheck = now + backOff;
-      vinfolog("Backend %s is in failed state and has failed %d consecutive checks, next check in %d seconds", getNameWithAddr(), failedTests, backOff);
+      VERBOSESLOG(infolog("Backend %s is in failed state and has failed %d consecutive checks, next check in %d seconds", getNameWithAddr(), failedTests, backOff),
+                  getLogger()->info(Logr::Info, "Backend is in failed state and has failed its last check", "consecutive-failed-checks", Logging::Loggable(failedTests), "next-check", Logging::Loggable(backOff)));
     }
   }
   else {
     stats.d_nextCheck = now + d_config.d_lazyHealthCheckFailedInterval;
-    vinfolog("Backend %s is in %s state, next check in %d seconds", getNameWithAddr(), (stats.d_status == DownstreamState::LazyHealthCheckStats::LazyStatus::PotentialFailure ? "potential failure" : "failed"), d_config.d_lazyHealthCheckFailedInterval);
+    VERBOSESLOG(infolog("Backend %s is in %s state, next check in %d seconds", getNameWithAddr(), (stats.d_status == DownstreamState::LazyHealthCheckStats::LazyStatus::PotentialFailure ? "potential failure" : "failed"), d_config.d_lazyHealthCheckFailedInterval),
+                getLogger()->info(Logr::Info, "Scheduling the next lazy check for this backend", "state", Logging::Loggable(stats.d_status == DownstreamState::LazyHealthCheckStats::LazyStatus::PotentialFailure ? "potential failure" : "failed"), "next-check", Logging::Loggable(d_config.d_lazyHealthCheckFailedInterval)));
   }
 }
 
@@ -809,7 +825,8 @@ void DownstreamState::submitHealthCheckResult(bool initial, bool newResult)
     /* if this is the initial health-check, at startup, we do not care
        about the minimum number of failed/successful health-checks */
     if (!IsAnyAddress(d_config.remote)) {
-      infolog("Marking downstream %s as '%s'", getNameWithAddr(), newResult ? "up" : "down");
+      SLOG(infolog("Marking downstream %s as '%s'", getNameWithAddr(), newResult ? "up" : "down"),
+           getLogger()->info(Logr::Info, "Setting initial status for backend", "status", Logging::Loggable(newResult ? "up" : "down")));
     }
     setUpStatus(newResult);
     if (newResult == false) {
@@ -850,7 +867,8 @@ void DownstreamState::submitHealthCheckResult(bool initial, bool newResult)
     if (newState) {
       if (d_config.d_healthCheckMode == DownstreamState::HealthCheckMode::Lazy) {
         auto stats = d_lazyHealthCheckStats.lock();
-        vinfolog("Backend %s had %d successful checks, moving to Healthy", getNameWithAddr(), std::to_string(consecutiveSuccessfulChecks));
+        VERBOSESLOG(infolog("Backend %s had %d successful checks, moving to Healthy", getNameWithAddr(), std::to_string(consecutiveSuccessfulChecks)),
+                    getLogger()->info(Logr::Info, "Backend had a successful check, moving to Healthy", "consecutive-successful-checks", Logging::Loggable(std::to_string(consecutiveSuccessfulChecks))));
         stats->d_status = LazyHealthCheckStats::LazyStatus::Healthy;
         stats->d_lastResults.clear();
       }
@@ -873,7 +891,8 @@ void DownstreamState::submitHealthCheckResult(bool initial, bool newResult)
       }
       else if (d_config.d_healthCheckMode == DownstreamState::HealthCheckMode::Lazy) {
         auto stats = d_lazyHealthCheckStats.lock();
-        vinfolog("Backend %s failed its health-check, moving from Potential failure to Failed", getNameWithAddr());
+        VERBOSESLOG(infolog("Backend %s failed its health-check, moving from Potential failure to Failed", getNameWithAddr()),
+                    getLogger()->info(Logr::Info, "Backend failed its health-check, moving from Potential failure to Failed"));
         stats->d_status = LazyHealthCheckStats::LazyStatus::Failed;
         currentCheckFailures = 1;
         updateNextLazyHealthCheck(*stats, false);
@@ -884,7 +903,8 @@ void DownstreamState::submitHealthCheckResult(bool initial, bool newResult)
   if (newState != upStatus.load(std::memory_order_relaxed)) {
     /* we are actually moving to a new state */
     if (!IsAnyAddress(d_config.remote)) {
-      infolog("Marking downstream %s as '%s'", getNameWithAddr(), newState ? "up" : "down");
+      SLOG(infolog("Marking downstream %s as '%s'", getNameWithAddr(), newState ? "up" : "down"),
+           getLogger()->info(Logr::Info, "Updating status for backend", "status", Logging::Loggable(newState ? "up" : "down")));
     }
 
     if (newState && !isTCPOnly() && (!connected || d_config.reconnectOnUp)) {
@@ -927,7 +947,8 @@ void DownstreamState::registerXsk(std::vector<std::shared_ptr<XskSocket>>& xsks)
     }
 
     if (addresses.size() > 1) {
-      warnlog("More than one address configured on interface %s, picking the first one (%s) for XSK. Set the 'source' parameter on 'newServer' if you want to use a different address.", ifName, addresses.at(0).toString());
+      SLOG(warnlog("More than one address configured on interface %s, picking the first one (%s) for XSK. Set the 'source' parameter on 'newServer' if you want to use a different address.", ifName, addresses.at(0).toString()),
+           getLogger()->info(Logr::Warning, "More than one address configured on this interface, picking the first one for XSK. Set the 'source' parameter on 'newServer' if you want to use a different address.", "interface", Logging::Loggable(ifName), "address", Logging::Loggable(addresses.at(0).toString())));
     }
     d_config.sourceAddr = addresses.at(0);
   }
@@ -986,7 +1007,9 @@ bool DownstreamState::parseSourceParameter(const std::string& source, Downstream
     return true;
   }
 
-  warnlog("Dismissing source %s because '%s' is not a valid interface name", source, config.sourceItfName);
+  SLOG(warnlog("Dismissing source %s because '%s' is not a valid interface name", source, config.sourceItfName),
+       dnsdist::logging::getTopLogger()->info(Logr::Warning, "Dismissing source because the interface name is not valid", "backend-name", Logging::Loggable(config.name), "backend-address", Logging::Loggable(config.remote), "source", Logging::Loggable(source), "source-interface", Logging::Loggable(config.sourceItfName)));
+
   return false;
 }
 
@@ -1018,6 +1041,11 @@ unsigned int DownstreamState::getQPSLimit() const
   return d_qpsLimiter ? d_qpsLimiter->getRate() : 0U;
 }
 
+[[nodiscard]] std::shared_ptr<const Logr::Logger> DownstreamState::getLogger() const
+{
+  return dnsdist::logging::getTopLogger()->withName("backend")->withValues("backend-name", Logging::Loggable(getName()), "backend-address", Logging::Loggable(d_config.remote), "backend-proto", Logging::Loggable(getProtocol()));
+}
+
 size_t ServerPool::countServers(bool upOnly) const
 {
   size_t count = 0;
index 5b6d2a050ad6076606f3017e9c4f0d8db6525c3f..d91b3fe6b7b1e181198d88d86615ed9233e385a8 100644 (file)
@@ -66,7 +66,25 @@ std::shared_ptr<const Logr::Logger> DNSQuestion::getThisLogger() const
     return d_logger;
   }
   auto logger = dnsdist::logging::getTopLogger();
-  logger = logger->withValues("qname", Logging::Loggable(ids.qname), "qtype", Logging::Loggable(QType(ids.qtype)), "qclass", Logging::Loggable(QClass(ids.qclass)), "source", Logging::Loggable(ids.origRemote), "destination", Logging::Loggable(ids.origDest), "proto", Logging::Loggable(ids.protocol));
+  logger = logger->withValues("qname", Logging::Loggable(ids.qname), "qtype", Logging::Loggable(QType(ids.qtype)), "qclass", Logging::Loggable(QClass(ids.qclass)), "source", Logging::Loggable(ids.origRemote), "destination", Logging::Loggable(ids.origDest), "proto", Logging::Loggable(ids.protocol), "id", Logging::Loggable(ids.origID), "flags", Logging::Loggable(ids.origFlags));
+  return logger;
+}
+
+std::shared_ptr<const Logr::Logger> DNSResponse::getThisLogger() const
+{
+  if (d_logger) {
+    return d_logger;
+  }
+  auto logger = DNSQuestion::getThisLogger();
+  if (data.size() >= sizeof(dnsheader)) {
+    const auto header = getHeader();
+    logger = logger->withValues("rcode", Logging::Loggable(RCode::to_s(header->rcode)));
+  }
+  if (d_downstream) {
+    logger = logger->withValues("backend-protocol", Logging::Loggable(d_downstream->getProtocol()), "backend-name", Logging::Loggable(d_downstream->getName()), "backend-address", Logging::Loggable(d_downstream->d_config.remote));
+  }
+  const double udiff = ids.queryRealTime.udiff();
+  logger = logger->withValues("latency-us", Logging::Loggable(udiff), "response-size", Logging::Loggable(data.size()));
   return logger;
 }
 
index 48d29a46b99b66cbdc95195ed320fc0bc7d5f32c..a3f2bb70671d4389f66fc1b01c9a5ad816007162 100644 (file)
@@ -27,6 +27,7 @@
 #include <string_view>
 
 #include "config.h"
+#include "dolog.hh"
 #include "iputils.hh"
 #include "libssl.hh"
 #include "noinitvector.hh"
@@ -99,6 +100,7 @@ struct DOHFrontend
   std::shared_ptr<DOHServerConfig> d_dsc{nullptr};
   std::shared_ptr<std::vector<std::shared_ptr<DOHResponseMapEntry>>> d_responsesMap;
   std::shared_ptr<TLSFrontend> d_tlsContext;
+  std::shared_ptr<const Logr::Logger> d_logger;
   std::string d_serverTokens{"dnsdist"};
   std::unordered_map<std::string, std::string> d_customResponseHeaders;
   std::string d_library;
@@ -152,6 +154,11 @@ struct DOHFrontend
     return !d_tlsContext->d_tlsConfig.d_certKeyPairs.empty();
   }
 
+  const Logr::Logger& getLogger() const
+  {
+    return *d_logger;
+  }
+
 #ifndef HAVE_DNS_OVER_HTTPS
   virtual void setup()
   {
index 7dbd51504237e323f73876ad38c6e4e0267558dc..d3f476cefbc871288ae896895685f59157835f77 100644 (file)
@@ -27,7 +27,7 @@
 
 namespace dnsdist::webserver
 {
-void registerWebHandler(const std::string& endpoint, std::function<void(const YaHTTP::Request&, YaHTTP::Response&)> handler, bool isLua);
+void registerWebHandler(const std::string& endpoint, std::function<void(const YaHTTP::Request&, YaHTTP::Response&)> handler);
 }
 
 void setupLuaWeb([[maybe_unused]] LuaContext& luaCtx)
@@ -35,7 +35,7 @@ void setupLuaWeb([[maybe_unused]] LuaContext& luaCtx)
 #ifndef DISABLE_LUA_WEB_HANDLERS
   luaCtx.writeFunction("registerWebHandler", [](const std::string& path, std::function<void(const YaHTTP::Request*, YaHTTP::Response*)> handler) {
     /* LuaWrapper does a copy for objects passed by reference, so we pass a pointer */
-    dnsdist::webserver::registerWebHandler(path, [handler](const YaHTTP::Request& req, YaHTTP::Response& resp) { handler(&req, &resp); }, true);
+    dnsdist::webserver::registerWebHandler(path, [handler](const YaHTTP::Request& req, YaHTTP::Response& resp) { handler(&req, &resp); });
   });
 
   luaCtx.registerMember<std::string(YaHTTP::Request::*)>("path", [](const YaHTTP::Request& req) -> std::string { return req.url.path; }, [](YaHTTP::Request& req, const std::string& path) { (void)req; (void) path; });
index 836d3d3f230aa22794613df88b3720638d40b2a2..9eb6fc1c6ec9141e48c612b20d0537066d7d4b21 100644 (file)
@@ -25,6 +25,7 @@
 #include <sys/time.h>
 #include <sys/resource.h>
 #include <thread>
+#include <variant>
 
 #include "ext/json11/json11.hpp"
 #include <yahttp/yahttp.hpp>
@@ -173,15 +174,16 @@ std::string getConfig()
 class WebClientConnection
 {
 public:
-  WebClientConnection(const ComboAddress& client, int socketDesc) :
+  WebClientConnection(const ComboAddress& client, int socketDesc, const Logr::Logger& logger) :
     d_client(client), d_socket(socketDesc)
   {
     if (!s_connManager.registerConnection()) {
       throw std::runtime_error("Too many concurrent web client connections");
     }
+    d_logger = logger.withValues("address", Logging::Loggable(client));
   }
   WebClientConnection(WebClientConnection&& rhs) noexcept :
-    d_client(rhs.d_client), d_socket(std::move(rhs.d_socket))
+    d_logger(std::move(rhs.d_logger)), d_client(rhs.d_client), d_socket(std::move(rhs.d_socket))
   {
   }
   WebClientConnection(const WebClientConnection&) = delete;
@@ -190,6 +192,7 @@ public:
   {
     d_client = rhs.d_client;
     d_socket = std::move(rhs.d_socket);
+    d_logger = std::move(rhs.d_logger);
     return *this;
   }
 
@@ -210,7 +213,13 @@ public:
     return d_client;
   }
 
+  [[nodiscard]] const Logr::Logger& getLogger() const
+  {
+    return *d_logger;
+  }
+
 private:
+  std::shared_ptr<Logr::Logger> d_logger;
   ComboAddress d_client;
   Socket d_socket;
 };
@@ -225,23 +234,29 @@ bool addMetricDefinition([[maybe_unused]] const dnsdist::prometheus::PrometheusM
 }
 
 #ifndef DISABLE_WEB_CONFIG
-static bool apiWriteConfigFile(const string& filebasename, const string& content)
+static bool apiWriteConfigFile(const string& filebasename, const string& content, const Logr::Logger& logger)
 {
   const auto& runtimeConfig = dnsdist::configuration::getCurrentRuntimeConfiguration();
   if (!runtimeConfig.d_apiReadWrite) {
-    warnlog("Not writing content to %s since the API is read-only", filebasename);
+    SLOG(warnlog("Not writing content to %s since the API is read-only", filebasename),
+         logger.info(Logr::Warning, "Not writing content to file since the API is read-only", "file", Logging::Loggable(filebasename)));
     return false;
   }
 
   if (runtimeConfig.d_apiConfigDirectory.empty()) {
-    vinfolog("Not writing content to %s since the API configuration directory is not set", filebasename);
+    VERBOSESLOG(infolog("Not writing content to %s since the API configuration directory is not set", filebasename),
+                logger.info(Logr::Info, "Not writing content to file since the API configuration directory is not set", "file", Logging::Loggable(filebasename)));
+
     return false;
   }
 
   string filename = runtimeConfig.d_apiConfigDirectory + "/" + filebasename + ".conf";
   ofstream ofconf(filename.c_str());
   if (!ofconf) {
-    errlog("Could not open configuration fragment file '%s' for writing: %s", filename, stringerror());
+    int saved = errno;
+    SLOG(errlog("Could not open configuration fragment file '%s' for writing: %s", filename, stringerror(saved)),
+         logger.error(Logr::Error, saved, "Could not open configuration fragment file for writing", "file", Logging::Loggable(filebasename)));
+
     return false;
   }
   ofconf << "-- Generated by the REST API, DO NOT EDIT" << endl;
@@ -250,7 +265,7 @@ static bool apiWriteConfigFile(const string& filebasename, const string& content
   return true;
 }
 
-static void apiSaveACL(const NetmaskGroup& nmg)
+static void apiSaveACL(const NetmaskGroup& nmg, const Logr::Logger& logger)
 {
   auto aclEntries = nmg.toStringVector();
 
@@ -263,7 +278,7 @@ static void apiSaveACL(const NetmaskGroup& nmg)
   }
 
   string content = "setACL({" + acl + "})";
-  apiWriteConfigFile("acl", content);
+  apiWriteConfigFile("acl", content, logger);
 }
 #endif /* DISABLE_WEB_CONFIG */
 
@@ -486,7 +501,7 @@ static void addHistogramToPrometheusOutput(std::ostringstream& output, const T&
   output << metricName << "_count" << label << " " << container.latencyCount << "\n";
 }
 
-static void handlePrometheus(const YaHTTP::Request& req, YaHTTP::Response& resp)
+static void handlePrometheus(const YaHTTP::Request& req, YaHTTP::Response& resp, const Logr::Logger& logger)
 {
   handleCORS(req, resp);
   resp.status = 200;
@@ -510,13 +525,15 @@ static void handlePrometheus(const YaHTTP::Request& req, YaHTTP::Response& resp)
 
       MetricDefinition metricDetails;
       if (!s_metricDefinitions.getMetricDetails(metricName, metricDetails)) {
-        vinfolog("Do not have metric details for %s", metricName);
+        VERBOSESLOG(infolog("Do not have metric details for %s", metricName),
+                    logger.info(Logr::Info, "Missing details for this metric", "metric-name", Logging::Loggable(metricName)));
         continue;
       }
 
       const std::string prometheusTypeName = s_metricDefinitions.getPrometheusStringMetricType(metricDetails.prometheusType);
       if (prometheusTypeName.empty()) {
-        vinfolog("Unknown Prometheus type for %s", metricName);
+        VERBOSESLOG(infolog("Unknown Prometheus type for %s", metricName),
+                    logger.info(Logr::Info, "Unknown Prometheus type", "metric-name", Logging::Loggable(metricName)));
         continue;
       }
 
@@ -991,8 +1008,9 @@ static void addStatsToJSONObject(Json::object& obj)
 }
 
 #ifndef DISABLE_BUILTIN_HTML
-static void handleJSONStats(const YaHTTP::Request& req, YaHTTP::Response& resp)
+static void handleJSONStats(const YaHTTP::Request& req, YaHTTP::Response& resp, const Logr::Logger& logger)
 {
+  (void)logger;
   handleCORS(req, resp);
   resp.status = 200;
 
@@ -1176,8 +1194,9 @@ static void addServerToJSON(Json::array& servers, int identifier, const std::sha
   servers.emplace_back(std::move(server));
 }
 
-static void handleStats(const YaHTTP::Request& req, YaHTTP::Response& resp)
+static void handleStats(const YaHTTP::Request& req, YaHTTP::Response& resp, const Logr::Logger& logger)
 {
+  (void)logger;
   handleCORS(req, resp);
   resp.status = 200;
 
@@ -1379,8 +1398,9 @@ static void handleStats(const YaHTTP::Request& req, YaHTTP::Response& resp)
   resp.body = Json(responseObject).dump();
 }
 
-static void handlePoolStats(const YaHTTP::Request& req, YaHTTP::Response& resp)
+static void handlePoolStats(const YaHTTP::Request& req, YaHTTP::Response& resp, const Logr::Logger& logger)
 {
+  (void)logger;
   handleCORS(req, resp);
   const auto poolName = req.getvars.find("name");
   if (poolName == req.getvars.end()) {
@@ -1429,8 +1449,9 @@ static void handlePoolStats(const YaHTTP::Request& req, YaHTTP::Response& resp)
   resp.body = my_json.dump();
 }
 
-static void handleStatsOnly(const YaHTTP::Request& req, YaHTTP::Response& resp)
+static void handleStatsOnly(const YaHTTP::Request& req, YaHTTP::Response& resp, const Logr::Logger& logger)
 {
+  (void)logger;
   handleCORS(req, resp);
   resp.status = 200;
 
@@ -1468,8 +1489,9 @@ static void handleStatsOnly(const YaHTTP::Request& req, YaHTTP::Response& resp)
 }
 
 #ifndef DISABLE_WEB_CONFIG
-static void handleConfigDump(const YaHTTP::Request& req, YaHTTP::Response& resp)
+static void handleConfigDump(const YaHTTP::Request& req, YaHTTP::Response& resp, const Logr::Logger& logger)
 {
+  (void)logger;
   handleCORS(req, resp);
   resp.status = 200;
 
@@ -1518,7 +1540,7 @@ static void handleConfigDump(const YaHTTP::Request& req, YaHTTP::Response& resp)
   resp.headers["Content-Type"] = "application/json";
 }
 
-static void handleAllowFrom(const YaHTTP::Request& req, YaHTTP::Response& resp)
+static void handleAllowFrom(const YaHTTP::Request& req, YaHTTP::Response& resp, const Logr::Logger& logger)
 {
   handleCORS(req, resp);
 
@@ -1545,11 +1567,13 @@ static void handleAllowFrom(const YaHTTP::Request& req, YaHTTP::Response& resp)
         }
 
         if (resp.status == 200) {
-          infolog("Updating the ACL via the API to %s", nmg.toString());
+          SLOG(infolog("Updating the ACL via the API to %s", nmg.toString()),
+               logger.info(Logr::Info, "Updating the ACL via the API", "acl", Logging::Loggable(nmg)));
+
           dnsdist::configuration::updateRuntimeConfiguration([&nmg](dnsdist::configuration::RuntimeConfiguration& config) {
             config.d_ACL = nmg;
           });
-          apiSaveACL(nmg);
+          apiSaveACL(nmg, logger);
         }
       }
       else {
@@ -1574,8 +1598,9 @@ static void handleAllowFrom(const YaHTTP::Request& req, YaHTTP::Response& resp)
 #endif /* DISABLE_WEB_CONFIG */
 
 #ifndef DISABLE_WEB_CACHE_MANAGEMENT
-static void handleCacheManagement(const YaHTTP::Request& req, YaHTTP::Response& resp)
+static void handleCacheManagement(const YaHTTP::Request& req, YaHTTP::Response& resp, const Logr::Logger& logger)
 {
+  (void)logger;
   handleCORS(req, resp);
 
   resp.headers["Content-Type"] = "application/json";
@@ -1688,7 +1713,7 @@ static void addRingEntryToList(const struct timespec& now, Json::array& list, co
   list.emplace_back(std::move(tmp));
 }
 
-static void handleRings(const YaHTTP::Request& req, YaHTTP::Response& resp)
+static void handleRings(const YaHTTP::Request& req, YaHTTP::Response& resp, const Logr::Logger& logger)
 {
   handleCORS(req, resp);
 
@@ -1701,7 +1726,8 @@ static void handleRings(const YaHTTP::Request& req, YaHTTP::Response& resp)
       maxNumberOfQueries = pdns::checked_stoi<size_t>(maxQueries->second);
     }
     catch (const std::exception& exp) {
-      vinfolog("Error parsing the 'maxQueries' value from rings HTTP GET query: %s", exp.what());
+      VERBOSESLOG(infolog("Error parsing the 'maxQueries' value from rings HTTP GET query: %s", exp.what()),
+                  logger.error(Logr::Info, exp.what(), "Error parsing the 'maxQueries' value from rings HTTP GET query"));
     }
   }
 
@@ -1711,7 +1737,8 @@ static void handleRings(const YaHTTP::Request& req, YaHTTP::Response& resp)
       maxNumberOfResponses = pdns::checked_stoi<size_t>(maxResponses->second);
     }
     catch (const std::exception& exp) {
-      vinfolog("Error parsing the 'maxResponses' value from rings HTTP GET query: %s", exp.what());
+      VERBOSESLOG(infolog("Error parsing the 'maxResponses' value from rings HTTP GET query: %s", exp.what()),
+                  logger.error(Logr::Info, exp.what(), "Error parsing the 'maxResponses' value from rings HTTP GET query"));
     }
   }
 
@@ -1754,21 +1781,24 @@ static void handleRings(const YaHTTP::Request& req, YaHTTP::Response& resp)
   resp.headers["Content-Type"] = "application/json";
 }
 
-using WebHandler = std::function<void(const YaHTTP::Request&, YaHTTP::Response&)>;
-struct WebHandlerContext
-{
-  WebHandler d_handler;
-  bool d_isLua{false};
-};
+using BuiltinWebHandler = std::function<void(const YaHTTP::Request&, YaHTTP::Response&, const Logr::Logger& logger)>;
+using LuaWebHandler = std::function<void(const YaHTTP::Request&, YaHTTP::Response&)>;
+using WebHandler = std::variant<BuiltinWebHandler, LuaWebHandler>;
+
+static SharedLockGuarded<std::unordered_map<std::string, WebHandler>> s_webHandlers;
 
-static SharedLockGuarded<std::unordered_map<std::string, WebHandlerContext>> s_webHandlers;
+void registerWebHandler(const std::string& endpoint, LuaWebHandler handler);
 
-void registerWebHandler(const std::string& endpoint, WebHandler handler, bool isLua = false);
+void registerWebHandler(const std::string& endpoint, LuaWebHandler handler)
+{
+  auto handlers = s_webHandlers.write_lock();
+  (*handlers)[endpoint] = WebHandler{std::move(handler)};
+}
 
-void registerWebHandler(const std::string& endpoint, WebHandler handler, bool isLua)
+static void registerWebHandler(const std::string& endpoint, BuiltinWebHandler handler)
 {
   auto handlers = s_webHandlers.write_lock();
-  (*handlers)[endpoint] = WebHandlerContext{std::move(handler), isLua};
+  (*handlers)[endpoint] = WebHandler{std::move(handler)};
 }
 
 void clearWebHandlers()
@@ -1779,16 +1809,18 @@ void clearWebHandlers()
 #ifndef DISABLE_BUILTIN_HTML
 #include "htmlfiles.h"
 
-static void redirectToIndex([[maybe_unused]] const YaHTTP::Request& req, YaHTTP::Response& resp)
+static void redirectToIndex([[maybe_unused]] const YaHTTP::Request& req, YaHTTP::Response& resp, const Logr::Logger& logger)
 {
+  (void)logger;
   const string charset = "; charset=utf-8";
   resp.body.assign(s_urlmap.at("index.html"));
   resp.headers["Content-Type"] = "text/html" + charset;
   resp.status = 200;
 }
 
-static void handleBuiltInFiles(const YaHTTP::Request& req, YaHTTP::Response& resp)
+static void handleBuiltInFiles(const YaHTTP::Request& req, YaHTTP::Response& resp, const Logr::Logger& logger)
 {
+  (void)logger;
   if (req.url.path.empty()) {
     resp.status = 404;
     return;
@@ -1853,7 +1885,8 @@ static void connectionThread(WebClientConnection&& conn)
 {
   setThreadName("dnsdist/webConn");
 
-  vinfolog("Webserver handling connection from %s", conn.getClient().toStringWithPort());
+  VERBOSESLOG(infolog("Webserver handling connection from %s", conn.getClient().toStringWithPort()),
+              conn.getLogger().info(Logr::Info, "Webserver handling connection"));
 
   try {
     YaHTTP::AsyncRequestLoader yarl;
@@ -1901,7 +1934,8 @@ static void connectionThread(WebClientConnection&& conn)
     else if (!handleAuthorization(req)) {
       auto header = req.headers.find("authorization");
       if (header != req.headers.end()) {
-        vinfolog("HTTP Request \"%s\" from %s: Web Authentication failed", req.url.path, conn.getClient().toStringWithPort());
+        VERBOSESLOG(infolog("HTTP Request \"%s\" from %s: Web Authentication failed", req.url.path, conn.getClient().toStringWithPort()),
+                    conn.getLogger().info(Logr::Info, "Web authentication failed for HTTP Request", "url", Logging::Loggable( req.url.path)));
       }
       resp.status = 401;
       resp.body = "<h1>Unauthorized</h1>";
@@ -1911,22 +1945,22 @@ static void connectionThread(WebClientConnection&& conn)
       resp.status = 405;
     }
     else {
-      std::optional<WebHandlerContext> handlerCtx{std::nullopt};
+      std::optional<WebHandler> handler{std::nullopt};
       {
         auto handlers = s_webHandlers.read_lock();
         const auto webHandlersIt = handlers->find(req.url.path);
         if (webHandlersIt != handlers->end()) {
-          handlerCtx = webHandlersIt->second;
+          handler = webHandlersIt->second;
         }
       }
 
-      if (handlerCtx) {
-        if (handlerCtx->d_isLua) {
+      if (handler) {
+        if (const auto* luaHandler = std::get_if<LuaWebHandler>(&*handler)) {
           auto lua = g_lua.lock();
-          handlerCtx->d_handler(req, resp);
+          (*luaHandler)(req, resp);
         }
-        else {
-          handlerCtx->d_handler(req, resp);
+        else if (const auto* builtinHandler = std::get_if<BuiltinWebHandler>(&*handler)) {
+          (*builtinHandler)(req, resp, conn.getLogger());
         }
       }
       else {
@@ -1940,13 +1974,16 @@ static void connectionThread(WebClientConnection&& conn)
     writen2(conn.getSocket().getHandle(), done.c_str(), done.size());
   }
   catch (const YaHTTP::ParseError& e) {
-    vinfolog("Webserver thread died with parse error exception while processing a request from %s: %s", conn.getClient().toStringWithPort(), e.what());
+    VERBOSESLOG(infolog("Webserver thread died with parse error exception while processing a request from %s: %s", conn.getClient().toStringWithPort(), e.what()),
+                conn.getLogger().error(Logr::Info, e.what(), "Webserver thread died with parse error exception while processing a request"));
   }
   catch (const std::exception& e) {
-    vinfolog("Webserver thread died with exception while processing a request from %s: %s", conn.getClient().toStringWithPort(), e.what());
+    VERBOSESLOG(infolog("Webserver thread died with exception while processing a request from %s: %s", conn.getClient().toStringWithPort(), e.what()),
+                conn.getLogger().error(Logr::Info, e.what(), "Webserver thread died with exception while processing a request"));
   }
   catch (...) {
-    vinfolog("Webserver thread died with exception while processing a request from %s", conn.getClient().toStringWithPort());
+    VERBOSESLOG(infolog("Webserver thread died with exception while processing a request from %s", conn.getClient().toStringWithPort()),
+                conn.getLogger().info(Logr::Info, "Webserver thread died with exception while processing a request"));
   }
 }
 
@@ -1958,13 +1995,15 @@ void setMaxConcurrentConnections(size_t max)
 void WebserverThread(ComboAddress listeningAddress, Socket sock)
 {
   setThreadName("dnsdist/webserv");
-  // coverity[auto_causes_copy]
-  infolog("Webserver launched on %s", listeningAddress.toStringWithPort());
+  auto serverLogger = dnsdist::logging::getTopLogger()->withName("webserver")->withValues("listening-address", Logging::Loggable(listeningAddress));
+  SLOG(infolog("Webserver launched on %s", listeningAddress.toStringWithPort()),
+       serverLogger->info(Logr::Info, "Webserver launched"));
 
   {
     const auto& config = dnsdist::configuration::getCurrentRuntimeConfiguration();
     if (!config.d_webPassword && config.d_dashboardRequiresAuthentication) {
-      warnlog("Webserver launched on %s without a password set!", listeningAddress.toStringWithPort());
+      SLOG(warnlog("Webserver launched on %s without a password set!", listeningAddress.toStringWithPort()),
+           serverLogger->info(Logr::Info, "Webserver launched without a password set!"));
     }
   }
 
@@ -1975,19 +2014,22 @@ void WebserverThread(ComboAddress listeningAddress, Socket sock)
       dnsdist::configuration::refreshLocalRuntimeConfiguration();
 
       if (!isClientAllowedByACL(remote)) {
-        vinfolog("Connection to webserver from client %s is not allowed, closing", remote.toStringWithPort());
+        VERBOSESLOG(infolog("Connection to webserver from client %s is not allowed, closing", remote.toStringWithPort()),
+                    serverLogger->info(Logr::Info, "Connection to webserver is not allowed by ACL, closing", "address", Logging::Loggable(remote)));
         close(fileDesc);
         continue;
       }
 
-      WebClientConnection conn(remote, fileDesc);
-      vinfolog("Got a connection to the webserver from %s", remote.toStringWithPort());
+      WebClientConnection conn(remote, fileDesc, *serverLogger);
+      VERBOSESLOG(infolog("Got a connection to the webserver from %s", remote.toStringWithPort()),
+                  conn.getLogger().info(Logr::Info, "Got a connection to the webserver"));
 
       std::thread connThr(connectionThread, std::move(conn));
       connThr.detach();
     }
     catch (const std::exception& e) {
-      vinfolog("Had an error accepting new webserver connection: %s", e.what());
+      VERBOSESLOG(infolog("Had an error accepting new webserver connection: %s", e.what()),
+                  serverLogger->error(Logr::Info, e.what(), "Had an error accepting new webserver connection"));
     }
   }
 }
index 325b1353ecd2f71a73ad0984d1d16f6051235eba..cbe41dd7066b69d935ad8e033e483b96a4267fae 100644 (file)
@@ -39,6 +39,8 @@ void XskResponderThread(std::shared_ptr<DownstreamState> dss, std::shared_ptr<Xs
 {
   try {
     setThreadName("dnsdist/XskResp");
+    auto logger = dnsdist::logging::getTopLogger()->withName("xsk-response-worker")->withValues("backend-name", Logging::Loggable(dss->getName()), "backend-address", Logging::Loggable(dss->d_config.remote));
+
     auto pollfds = getPollFdsForWorker(*xskInfo);
     while (!dss->isStopped()) {
       poll(pollfds.data(), pollfds.size(), -1);
@@ -72,19 +74,22 @@ void XskResponderThread(std::shared_ptr<DownstreamState> dss, std::shared_ptr<Xs
           }
           if (!processResponderPacket(dss, response, std::move(*ids))) {
             xskInfo->markAsFree(packet);
-            vinfolog("XSK packet dropped because processResponderPacket failed");
+            VERBOSESLOG(infolog("XSK packet dropped because processResponderPacket failed"),
+                        logger->info(Logr::Info, "XSK packet dropped because processResponderPacket failed"));
             return;
           }
           if (response.size() > packet.getCapacity()) {
             /* fallback to sending the packet via normal socket */
             sendUDPResponse(ids->cs->udpFD, response, ids->delayMsec, ids->hopLocal, ids->hopRemote);
-            infolog("XSK packet falling back because packet is too large");
+            VERBOSESLOG(infolog("XSK packet falling back because packet is too large"),
+                        logger->info(Logr::Info, "XSK packet falling back because packet is too large"));
             xskInfo->markAsFree(packet);
             return;
           }
           packet.setHeader(ids->xskPacketHeader);
           if (!packet.setPayload(response)) {
-            infolog("Unable to set XSK payload !");
+            VERBOSESLOG(infolog("Unable to set XSK payload!"),
+                        logger->info(Logr::Info, "Unable to set XSK payload!"));
           }
           if (ids->delayMsec > 0) {
             packet.addDelay(ids->delayMsec);
@@ -99,13 +104,16 @@ void XskResponderThread(std::shared_ptr<DownstreamState> dss, std::shared_ptr<Xs
     }
   }
   catch (const std::exception& e) {
-    errlog("XSK responder thread died because of exception: %s", e.what());
+    SLOG(errlog("XSK responder thread died because of exception: %s", e.what()),
+         dnsdist::logging::getTopLogger()->error(Logr::Error, e.what(), "XSK responder thread died because of exception"));
   }
   catch (const PDNSException& e) {
-    errlog("XSK responder thread died because of PowerDNS exception: %s", e.reason);
+    SLOG(errlog("XSK responder thread died because of PowerDNS exception: %s", e.reason),
+         dnsdist::logging::getTopLogger()->error(Logr::Error, e.reason, "XSK responder thread died because of exception"));
   }
   catch (...) {
-    errlog("XSK responder thread died because of an exception: %s", "unknown");
+    SLOG(errlog("XSK responder thread died because of an unknown exception"),
+         dnsdist::logging::getTopLogger()->info(Logr::Error, "XSK responder thread died because of an unknown exception"));
   }
 }
 
@@ -114,7 +122,8 @@ bool XskIsQueryAcceptable(const XskPacket& packet, ClientState& clientState, boo
   const auto& from = packet.getFromAddr();
   expectProxyProtocol = expectProxyProtocolFrom(from);
   if (!dnsdist::configuration::getCurrentRuntimeConfiguration().d_ACL.match(from) && !expectProxyProtocol) {
-    vinfolog("Query from %s dropped because of ACL", from.toStringWithPort());
+    VERBOSESLOG(infolog("Query from %s dropped because of ACL", from.toStringWithPort()),
+                dnsdist::logging::getTopLogger()->info(Logr::Info, "Query dropped because of ACL", "address", Logging::Loggable(from)));
     ++dnsdist::metrics::g_stats.aclDrops;
     return false;
   }
@@ -127,6 +136,8 @@ bool XskIsQueryAcceptable(const XskPacket& packet, ClientState& clientState, boo
 void XskRouter(std::shared_ptr<XskSocket> xsk)
 {
   setThreadName("dnsdist/XskRouter");
+  auto logger = dnsdist::logging::getTopLogger()->withName("xsk-router");
+
   uint32_t failed = 0;
   // packets to be submitted for sending
   vector<XskPacket> fillInTx;
@@ -188,7 +199,8 @@ void XskRouter(std::shared_ptr<XskSocket> xsk)
       xsk->send(fillInTx);
     }
     catch (...) {
-      vinfolog("Exception in XSK router loop");
+      VERBOSESLOG(infolog("Exception in XSK router loop"),
+                  logger->info(Logr::Info, "Exception in XSK router loop"));
     }
   }
 }
index 9f6c37e1c1fa183b43df379e6db35d346846b135..61542d92d9024d924f98760cf6816e42a041d0db 100644 (file)
@@ -715,21 +715,21 @@ static void handleResponseForUDPClient(InternalQueryState& ids, PacketBuffer& re
     if (!muted) {
       if (!ids.isXSK()) {
         VERBOSESLOG(infolog("Got answer from %s, relayed to %s (UDP), took %d us", backend->d_config.remote.toStringWithPort(), ids.origRemote.toStringWithPort(), udiff),
-                    dnsResponse.getLogger()->withName("udp-response")->info(Logr::Info, "Got answer from backend, relayed to client", "backend", Logging::Loggable(backend->d_config.remote), "latency-us", Logging::Loggable(udiff)));
+                    dnsResponse.getLogger()->withName("udp-response")->info(Logr::Info, "Got answer from backend, relayed to client"));
       }
       else {
         VERBOSESLOG(infolog("Got answer from %s, relayed to %s (UDP via XSK), took %d us", backend->d_config.remote.toStringWithPort(), ids.origRemote.toStringWithPort(), udiff),
-                    dnsResponse.getLogger()->withName("udp-xsk-response")->info(Logr::Info, "Got answer from backend, relayed to client", "backend", Logging::Loggable(backend->d_config.remote), "latency-us", Logging::Loggable(udiff)));
+                    dnsResponse.getLogger()->withName("udp-xsk-response")->info(Logr::Info, "Got answer from backend, relayed to client"));
       }
     }
     else {
       if (!ids.isXSK()) {
         VERBOSESLOG(infolog("Got answer from %s, NOT relayed to %s (UDP) since that frontend is muted, took %d us", backend->d_config.remote.toStringWithPort(), ids.origRemote.toStringWithPort(), udiff),
-                    dnsResponse.getLogger()->withName("udp-response")->info(Logr::Info, "Got answer from backend, NOT relayed to client since that frontend is muted", "backend", Logging::Loggable(backend->d_config.remote), "latency-us", Logging::Loggable(udiff)));
+                    dnsResponse.getLogger()->withName("udp-response")->info(Logr::Info, "Got answer from backend, NOT relayed to client since that frontend is muted"));
       }
       else {
         VERBOSESLOG(infolog("Got answer from %s, relayed to %s (UDP via XSK), took %d us", backend->d_config.remote.toStringWithPort(), ids.origRemote.toStringWithPort(), udiff),
-                    dnsResponse.getLogger()->withName("udp-xsk-response")->info(Logr::Info, "Got answer from backend, NOT relayed to client since that frontend is muted", "backend", Logging::Loggable(backend->d_config.remote), "latency-us", Logging::Loggable(udiff)));
+                    dnsResponse.getLogger()->withName("udp-xsk-response")->info(Logr::Info, "Got answer from backend, NOT relayed to client since that frontend is muted"));
       }
     }
 
@@ -1816,7 +1816,6 @@ std::unique_ptr<CrossProtocolQuery> getUDPCrossProtocolQueryFromDQ(DNSQuestion&
 
 ProcessQueryResult processQuery(DNSQuestion& dnsQuestion, std::shared_ptr<DownstreamState>& selectedBackend)
 {
-  dnsQuestion.getLogger()->info("test");
   auto closer = dnsQuestion.ids.getCloser(__func__); // NOLINT(cppcoreguidelines-pro-bounds-array-to-pointer-decay)
   const uint16_t queryId = ntohs(dnsQuestion.getHeader()->id);
   try {
@@ -2458,7 +2457,8 @@ static void maintThread()
       }
       catch (const std::exception& e) {
         if (secondsToWaitLog <= 0) {
-          warnlog("Error during execution of maintenance function(s): %s", e.what());
+          SLOG(warnlog("Error during execution of maintenance function(s): %s", e.what()),
+               dnsdist::logging::getTopLogger()->error(Logr::Warning, e.what(), "Error during execution of maintenance function(s)"));
           secondsToWaitLog = 61;
         }
         secondsToWaitLog -= interval;
@@ -3770,7 +3770,8 @@ int main(int argc, char** argv)
         }
         acls += aclEntry;
       }
-      infolog("ACL allowing queries from: %s", acls);
+      SLOG(infolog("ACL allowing queries from: %s", acls),
+           setupLogger->info(Logr::Info, "Allowing queries from", "acl", Logging::Loggable(acls)));
     }
     {
       std::string acls;
@@ -3781,14 +3782,16 @@ int main(int argc, char** argv)
         }
         acls += entry;
       }
-      infolog("Console ACL allowing connections from: %s", acls.c_str());
+      SLOG(infolog("Console ACL allowing connections from: %s", acls),
+           setupLogger->info(Logr::Info, "Allowing console connections from", "acl", Logging::Loggable(acls)));
     }
 
     auto listeningSockets = initListeningSockets();
 
 #if defined(HAVE_LIBSODIUM) || defined(HAVE_LIBCRYPTO)
     if (dnsdist::configuration::getCurrentRuntimeConfiguration().d_consoleEnabled && dnsdist::configuration::getCurrentRuntimeConfiguration().d_consoleKey.empty()) {
-      warnlog("Warning, the console has been enabled via 'controlSocket()' but no key has been set with 'setKey()' so all connections will fail until a key has been set");
+      SLOG(warnlog("Warning, the console has been enabled via 'controlSocket()' but no key has been set with 'setKey()' so all connections will fail until a key has been set"),
+           setupLogger->info(Logr::Warning, "The console has been enabled via 'controlSocket()' but no key has been set with 'setKey()' so allconnections will fail until a key has been set"));
     }
 #endif
 
@@ -3814,7 +3817,8 @@ int main(int argc, char** argv)
     /* the limit is completely arbitrary: hopefully high enough not to trigger too many false positives
        but low enough to be useful */
     if (maxTCPClientThreads >= 50U) {
-      warnlog("setMaxTCPClientThreads(%d) might create a large number of TCP connections to backends, and is probably not needed, please consider lowering it", maxTCPClientThreads);
+      SLOG(warnlog("setMaxTCPClientThreads(%d) might create a large number of TCP connections to backends, and is probably not needed, please consider lowering it", maxTCPClientThreads),
+           setupLogger->info(Logr::Warning, "The current setMaxTCPClientThreads() value might create a large number of TCP connections to backends, and is probably not needed, please consider lowering it", "value", Logging::Loggable(maxTCPClientThreads)));
     }
     g_tcpclientthreads = std::make_unique<TCPClientCollection>(maxTCPClientThreads, std::vector<ClientState*>());
 #endif
@@ -3873,7 +3877,8 @@ int main(int argc, char** argv)
           if (!queueHealthCheck(mplexer, dss, true)) {
             dss->submitHealthCheckResult(true, false);
             dss->setUpStatus(false);
-            warnlog("Marking downstream %s as 'down'", dss->getNameWithAddr());
+            SLOG(warnlog("Marking downstream %s as 'down'", dss->getNameWithAddr()),
+                 setupLogger->info(Logr::Warning, "Marking downstream backend server as 'down'", "backend-name", Logging::Loggable(dss->getName()), "address", Logging::Loggable(dss->d_config.remote)));
           }
         }
       }
index 058ed174e70f1b3dac95b6021b8a1e23b3c6e703..44ab85460463cebd2f7bced6c613496c80297d69 100644 (file)
@@ -173,7 +173,7 @@ struct DNSQuestion
   std::shared_ptr<const Logr::Logger> getLogger();
 
 protected:
-  std::shared_ptr<const Logr::Logger> getThisLogger() const;
+  virtual std::shared_ptr<const Logr::Logger> getThisLogger() const;
 
   PacketBuffer& data;
   std::shared_ptr<const Logr::Logger> d_logger;
@@ -204,6 +204,9 @@ struct DNSResponse : DNSQuestion
   DNSResponse(DNSResponse&&) = default;
 
   const std::shared_ptr<DownstreamState>& d_downstream;
+
+protected:
+  std::shared_ptr<const Logr::Logger> getThisLogger() const override;
 };
 
 using pdns::stat_t;
@@ -944,6 +947,8 @@ public:
   }
 
   unsigned int getQPSLimit() const;
+
+  [[nodiscard]] std::shared_ptr<const Logr::Logger> getLogger() const;
 };
 
 void responderThread(std::shared_ptr<DownstreamState> dss);
index 27fb691f5504350cd8c0cd4edcb1704dea96f712..bdc544d6876877f2ad69f4af792fb8cf181454bd 100644 (file)
@@ -167,7 +167,8 @@ public:
 
     if (!unit->ids.selfGenerated) {
       auto udiff = unit->ids.queryRealTime.udiff();
-      vinfolog("Got answer from %s, relayed to %s (DoH3, %d bytes), took %d us", unit->downstream->d_config.remote.toStringWithPort(), unit->ids.origRemote.toStringWithPort(), unit->response.size(), udiff);
+      VERBOSESLOG(infolog("Got answer from %s, relayed to %s (DoH3, %d bytes), took %d us", unit->downstream->d_config.remote.toStringWithPort(), unit->ids.origRemote.toStringWithPort(), unit->response.size(), udiff),
+                  dnsResponse.getLogger()->info("Got answer from backend, relayed to client"));
 
       auto backendProtocol = unit->downstream->getProtocol();
       if (backendProtocol == dnsdist::Protocol::DoUDP && unit->tcp) {
@@ -430,11 +431,13 @@ static void sendBackDOH3Unit(DOH3UnitUniquePtr&& unit, const char* description)
   try {
     if (!unit->dsc->d_responseSender.send(std::move(unit))) {
       ++dnsdist::metrics::g_stats.doh3ResponsePipeFull;
-      vinfolog("Unable to pass a %s to the DoH3 worker thread because the pipe is full", description);
+      VERBOSESLOG(infolog("Unable to pass a %s to the DoH3 worker thread because the pipe is full", description),
+                  dnsdist::logging::getTopLogger()->info(Logr::Info, std::string("Unable to pass a ") + std::string(description) + " to the DoH3 worker thread because the pipe is full"));
     }
   }
   catch (const std::exception& e) {
-    vinfolog("Unable to pass a %s to the DoH3 worker thread because we couldn't write to the pipe: %s", description, e.what());
+    VERBOSESLOG(infolog("Unable to pass a %s to the DoH3 worker thread because we couldn't write to the pipe: %s", description, e.what()),
+                dnsdist::logging::getTopLogger()->error(Logr::Info, e.what(), std::string("Unable to pass a ") + std::string(description) + " to the DoH3 worker thread because we couldn't write to the pipe"));
   }
 }
 
@@ -510,7 +513,8 @@ static void processDOH3Query(DOH3UnitUniquePtr&& doh3Unit)
     ClientState& clientState = *dsc->clientState;
 
     if (!dnsdist::configuration::getCurrentRuntimeConfiguration().d_ACL.match(remote)) {
-      vinfolog("Query from %s (DoH3) dropped because of ACL", remote.toStringWithPort());
+      VERBOSESLOG(infolog("Query from %s (DoH3) dropped because of ACL", remote.toStringWithPort()),
+                  dsc->df->getLogger().info("DoH3 query dropped because of ACL", "address", Logging::Loggable(remote)));
       ++dnsdist::metrics::g_stats.aclDrops;
       unit->response.clear();
 
@@ -645,9 +649,12 @@ static void processDOH3Query(DOH3UnitUniquePtr&& doh3Unit)
     return;
   }
   catch (const std::exception& e) {
-    vinfolog("Got an error in DOH3 question thread while parsing a query from %s, id %d: %s", remote.toStringWithPort(), queryId, e.what());
-    unit->status_code = 500;
-    handleImmediateResponse(std::move(unit), "DoH3 internal error");
+    if (unit) {
+      VERBOSESLOG(infolog("Got an error in DOH3 question thread while parsing a query from %s, id %d: %s", remote.toStringWithPort(), queryId, e.what()),
+                  unit->dsc->df->getLogger().error(Logr::Info, e.what(), "Got an error in DoH3 question thread while parsing a query", "address", Logging::Loggable(remote), "query-id", Logging::Loggable(queryId)));
+      unit->status_code = 500;
+      handleImmediateResponse(std::move(unit), "DoH3 internal error");
+    }
     return;
   }
 }
@@ -668,11 +675,12 @@ static void doh3_dispatch_query(DOH3ServerConfig& dsc, PacketBuffer&& query, con
     processDOH3Query(std::move(unit));
   }
   catch (const std::exception& exp) {
-    vinfolog("Had error handling DoH3 DNS packet from %s: %s", remote.toStringWithPort(), exp.what());
+    VERBOSESLOG(infolog("Had error handling DoH3 DNS packet from %s: %s", remote.toStringWithPort(), exp.what()),
+                dsc.df->getLogger().error(Logr::Info, exp.what(), "Had error handling DoH3 DNS packet", "address", Logging::Loggable(remote)));
   }
 }
 
-static void flushResponses(pdns::channel::Receiver<DOH3Unit>& receiver)
+static void flushResponses(pdns::channel::Receiver<DOH3Unit>& receiver, const Logr::Logger& frontendLogger)
 {
   for (;;) {
     try {
@@ -688,10 +696,12 @@ static void flushResponses(pdns::channel::Receiver<DOH3Unit>& receiver)
       }
     }
     catch (const std::exception& e) {
-      errlog("Error while processing response received over DoH3: %s", e.what());
+      SLOG(errlog("Error while processing response received over DoH3: %s", e.what()),
+           frontendLogger.error(e.what(), "Error while processing response received over DoH3"));
     }
     catch (...) {
-      errlog("Unspecified error while processing response received over DoH3");
+      SLOG(errlog("Unspecified error while processing response received over DoH3"),
+           frontendLogger.info(Logr::Error, "Unspecified error while processing response received over DoH3"));
     }
   }
 }
@@ -999,9 +1009,11 @@ void doh3Thread(ClientState* clientState)
 {
   try {
     std::shared_ptr<DOH3Frontend>& frontend = clientState->doh3Frontend;
+    auto frontendLogger = dnsdist::logging::getTopLogger()->withName("doh3-frontend")->withValues("address", Logging::Loggable(clientState->local));
 
     frontend->d_server_config->clientState = clientState;
     frontend->d_server_config->df = clientState->doh3Frontend;
+    frontend->d_logger = frontendLogger;
 
     setThreadName("dnsdist/doh3");
 
@@ -1027,7 +1039,7 @@ void doh3Thread(ClientState* clientState)
         }
 
         if (std::find(readyFDs.begin(), readyFDs.end(), responseReceiverFD) != readyFDs.end()) {
-          flushResponses(frontend->d_server_config->d_responseReceiver);
+          flushResponses(frontend->d_server_config->d_responseReceiver, *frontendLogger);
         }
 
         for (auto conn = frontend->d_server_config->d_connections.begin(); conn != frontend->d_server_config->d_connections.end();) {
@@ -1054,10 +1066,12 @@ void doh3Thread(ClientState* clientState)
         }
       }
       catch (const std::exception& exp) {
-        vinfolog("Caught exception in the main DoH3 thread: %s", exp.what());
+        VERBOSESLOG(infolog("Caught exception in the main DoH3 thread: %s", exp.what()),
+                    frontendLogger->error(Logr::Info, exp.what(), "Caught exception in the main DoH3 thread"));
       }
       catch (...) {
-        vinfolog("Unknown exception in the main DoH3 thread");
+        VERBOSESLOG(infolog("Unknown exception in the main DoH3 thread"),
+                    frontendLogger->info(Logr::Info, "Caught unknown exception in the main DoH3 thread"));
       }
     }
   }
index 14850fcc700b3dc94baf561d77028bac8c713613..2fa07a9af1beed07e555bf0356f57e2e7dab5d83 100644 (file)
@@ -30,6 +30,7 @@
 
 #ifdef HAVE_DNS_OVER_HTTP3
 #include "channel.hh"
+#include "dolog.hh"
 #include "iputils.hh"
 #include "libssl.hh"
 #include "stat_t.hh"
@@ -59,7 +60,12 @@ struct DOH3Frontend
 
   void setup();
   void reloadCertificates();
+  const Logr::Logger& getLogger()
+  {
+    return *d_logger;
+  }
 
+  std::shared_ptr<const Logr::Logger> d_logger{nullptr};
   std::unique_ptr<DOH3ServerConfig> d_server_config;
   ComboAddress d_local;
 
index ebe43d61af5e956135c8eb3868f91ef0550e7ecc..43a3faa0340097711e4bf24fed51a850ac0d7c73 100644 (file)
@@ -63,7 +63,8 @@ PacketBuffer mintToken(const PacketBuffer& dcid, const ComboAddress& peer)
     return encryptedTokenPacket;
   }
   catch (const std::exception& exp) {
-    vinfolog("Error while minting DoH3 token: %s", exp.what());
+    VERBOSESLOG(infolog("Error while minting DoH3 token: %s", exp.what()),
+                dnsdist::logging::getTopLogger()->error(Logr::Info, exp.what(), "Error while minting DoH3 token"));
     throw;
   }
 }
@@ -121,7 +122,8 @@ std::optional<PacketBuffer> validateToken(const PacketBuffer& token, const Combo
     return PacketBuffer(plainText.begin() + (sizeof(ttd) + addrBytes.size()), plainText.end());
   }
   catch (const std::exception& exp) {
-    vinfolog("Error while validating DoH3 token: %s", exp.what());
+    VERBOSESLOG(infolog("Error while validating DoH3 token: %s", exp.what()),
+                dnsdist::logging::getTopLogger()->error(Logr::Info, exp.what(), "Error while validating DoH3 token"));
     return std::nullopt;
   }
 }
@@ -146,7 +148,8 @@ static void sendFromTo(Socket& sock, const ComboAddress& peer, const ComboAddres
     auto ret = sendto(sock.getHandle(), buffer.data(), buffer.size(), flags, reinterpret_cast<const struct sockaddr*>(&peer), peer.getSocklen());
     if (ret < 0) {
       auto error = errno;
-      vinfolog("Error while sending QUIC datagram of size %d to %s: %s", buffer.size(), peer.toStringWithPort(), stringerror(error));
+      VERBOSESLOG(infolog("Error while sending QUIC datagram of size %d to %s: %s", buffer.size(), peer.toStringWithPort(), stringerror(error)),
+                  dnsdist::logging::getTopLogger()->error(Logr::Info, error, "Error while sending QUIC datagram", "size", Logging::Loggable(buffer.size()), "destination", Logging::Loggable(peer)));
     }
     return;
   }
@@ -155,7 +158,8 @@ static void sendFromTo(Socket& sock, const ComboAddress& peer, const ComboAddres
     sendMsgWithOptions(sock.getHandle(), buffer.data(), buffer.size(), &peer, &local, 0, 0);
   }
   catch (const std::exception& exp) {
-    vinfolog("Error while sending QUIC datagram of size %d from %s to %s: %s", buffer.size(), local.toStringWithPort(), peer.toStringWithPort(), exp.what());
+    VERBOSESLOG(infolog("Error while sending QUIC datagram of size %d from %s to %s: %s", buffer.size(), local.toStringWithPort(), peer.toStringWithPort(), exp.what()),
+                dnsdist::logging::getTopLogger()->error(Logr::Info, exp.what(), "Error while sending QUIC datagram", "size", Logging::Loggable(buffer.size()), "source", Logging::Loggable(local), "destination", Logging::Loggable(peer)));
   }
 }
 
index f197b6a136d0b8c8a980ac110f3683e4286fad50..ba46f52d9ef53b103a7312dda8d1d746db86f766 100644 (file)
@@ -162,7 +162,8 @@ public:
 
     if (!unit->ids.selfGenerated) {
       auto udiff = unit->ids.queryRealTime.udiff();
-      vinfolog("Got answer from %s, relayed to %s (quic, %d bytes), took %d us", unit->downstream->d_config.remote.toStringWithPort(), unit->ids.origRemote.toStringWithPort(), unit->response.size(), udiff);
+      VERBOSESLOG(infolog("Got answer from %s, relayed to %s (quic, %d bytes), took %d us", unit->downstream->d_config.remote.toStringWithPort(), unit->ids.origRemote.toStringWithPort(), unit->response.size(), udiff),
+                  dnsResponse.getLogger()->info("Got answer from backend, relayed to client"));
 
       auto backendProtocol = unit->downstream->getProtocol();
       if (backendProtocol == dnsdist::Protocol::DoUDP && unit->tcp) {
@@ -340,11 +341,13 @@ static void sendBackDOQUnit(DOQUnitUniquePtr&& unit, const char* description)
   try {
     if (!unit->dsc->d_responseSender.send(std::move(unit))) {
       ++dnsdist::metrics::g_stats.doqResponsePipeFull;
-      vinfolog("Unable to pass a %s to the DoQ worker thread because the pipe is full", description);
+      VERBOSESLOG(infolog("Unable to pass a %s to the DoQ worker thread because the pipe is full", description),
+                  dnsdist::logging::getTopLogger()->info(Logr::Info, std::string("Unable to pass a ") + std::string(description) + " to the DoQ worker thread because the pipe is full"));
     }
   }
   catch (const std::exception& e) {
-    vinfolog("Unable to pass a %s to the DoQ worker thread because we couldn't write to the pipe: %s", description, e.what());
+    VERBOSESLOG(infolog("Unable to pass a %s to the DoQ worker thread because we couldn't write to the pipe: %s", description, e.what()),
+                dnsdist::logging::getTopLogger()->error(Logr::Info, e.what(), std::string("Unable to pass a ") + std::string(description) + " to the DoQ worker thread because we couldn't write to the pipe"));
   }
 }
 
@@ -420,7 +423,8 @@ static void processDOQQuery(DOQUnitUniquePtr&& doqUnit)
     ClientState& clientState = *dsc->clientState;
 
     if (!dnsdist::configuration::getCurrentRuntimeConfiguration().d_ACL.match(remote)) {
-      vinfolog("Query from %s (DoQ) dropped because of ACL", remote.toStringWithPort());
+      VERBOSESLOG(infolog("Query from %s (DoQ) dropped because of ACL", remote.toStringWithPort()),
+                  dsc->df->getLogger().info("DoQ query dropped because of ACL", "address", Logging::Loggable(remote)));
       ++dnsdist::metrics::g_stats.aclDrops;
       unit->response.clear();
 
@@ -547,8 +551,11 @@ static void processDOQQuery(DOQUnitUniquePtr&& doqUnit)
     return;
   }
   catch (const std::exception& e) {
-    vinfolog("Got an error in DOQ question thread while parsing a query from %s, id %d: %s", remote.toStringWithPort(), queryId, e.what());
-    handleImmediateResponse(std::move(unit), "DoQ internal error");
+    if (unit) {
+      VERBOSESLOG(infolog("Got an error in DOQ question thread while parsing a query from %s, id %d: %s", remote.toStringWithPort(), queryId, e.what()),
+                  unit->dsc->df->getLogger().error(Logr::Info, e.what(), "Got an error in DOQ question thread while parsing a query", "address", Logging::Loggable(remote), "query-id", Logging::Loggable(queryId)));
+      handleImmediateResponse(std::move(unit), "DoQ internal error");
+    }
     return;
   }
 }
@@ -568,11 +575,12 @@ static void doq_dispatch_query(DOQServerConfig& dsc, PacketBuffer&& query, const
     processDOQQuery(std::move(unit));
   }
   catch (const std::exception& exp) {
-    vinfolog("Had error handling DoQ DNS packet from %s: %s", remote.toStringWithPort(), exp.what());
+    VERBOSESLOG(infolog("Had error handling DoQ DNS packet from %s: %s", remote.toStringWithPort(), exp.what()),
+                dsc.df->getLogger().error(Logr::Info, exp.what(), "Had error handling DoQ DNS packet", "address", Logging::Loggable(remote)));
   }
 }
 
-static void flushResponses(pdns::channel::Receiver<DOQUnit>& receiver)
+static void flushResponses(pdns::channel::Receiver<DOQUnit>& receiver, const Logr::Logger& frontendLogger)
 {
   for (;;) {
     try {
@@ -588,10 +596,12 @@ static void flushResponses(pdns::channel::Receiver<DOQUnit>& receiver)
       }
     }
     catch (const std::exception& e) {
-      errlog("Error while processing response received over DoQ: %s", e.what());
+      SLOG(errlog("Error while processing response received over DoQ: %s", e.what()),
+           frontendLogger.error(e.what(), "Error while processing response received over DoQ"));
     }
     catch (...) {
-      errlog("Unspecified error while processing response received over DoQ");
+      SLOG(errlog("Unspecified error while processing response received over DoQ"),
+           frontendLogger.info(Logr::Error, "Unspecified error while processing response received over DoQ"));
     }
   }
 }
@@ -786,9 +796,11 @@ void doqThread(ClientState* clientState)
 {
   try {
     std::shared_ptr<DOQFrontend>& frontend = clientState->doqFrontend;
+    auto frontendLogger = dnsdist::logging::getTopLogger()->withName("doq-frontend")->withValues("address", Logging::Loggable(clientState->local));
 
     frontend->d_server_config->clientState = clientState;
     frontend->d_server_config->df = clientState->doqFrontend;
+    frontend->d_logger = frontendLogger;
 
     setThreadName("dnsdist/doq");
 
@@ -814,7 +826,7 @@ void doqThread(ClientState* clientState)
         }
 
         if (std::find(readyFDs.begin(), readyFDs.end(), responseReceiverFD) != readyFDs.end()) {
-          flushResponses(frontend->d_server_config->d_responseReceiver);
+          flushResponses(frontend->d_server_config->d_responseReceiver, *frontendLogger);
         }
 
         for (auto conn = frontend->d_server_config->d_connections.begin(); conn != frontend->d_server_config->d_connections.end();) {
@@ -841,10 +853,12 @@ void doqThread(ClientState* clientState)
         }
       }
       catch (const std::exception& exp) {
-        vinfolog("Caught exception in the main DoQ thread: %s", exp.what());
+        VERBOSESLOG(infolog("Caught exception in the main DoQ thread: %s", exp.what()),
+                    frontendLogger->error(Logr::Info, exp.what(), "Caught exception in the main DoQ thread"));
       }
       catch (...) {
-        vinfolog("Unknown exception in the main DoQ thread");
+        VERBOSESLOG(infolog("Unknown exception in the main DoQ thread"),
+                    frontendLogger->info(Logr::Info, "Caught unknown exception in the main DoQ thread"));
       }
     }
   }
index 66b64953df623e09d2ea43c8ac39af1a44a72f6b..1e80e6d8e54421686a9a782e068f51fd2da5feef 100644 (file)
 #include <memory>
 
 #include "config.h"
-#include "channel.hh"
-#include "iputils.hh"
-#include "libssl.hh"
-#include "noinitvector.hh"
-#include "doq.hh"
-#include "stat_t.hh"
 
 struct DOQServerConfig;
 struct DownstreamState;
 
 #ifdef HAVE_DNS_OVER_QUIC
 
+#include "channel.hh"
 #include "dnsdist-idstate.hh"
 #include "doq-common.hh"
+#include "dolog.hh"
+#include "iputils.hh"
+#include "libssl.hh"
+#include "noinitvector.hh"
+#include "stat_t.hh"
 
 struct DOQFrontend
 {
@@ -50,7 +50,12 @@ struct DOQFrontend
 
   void setup();
   void reloadCertificates();
+  const Logr::Logger& getLogger()
+  {
+    return *d_logger;
+  }
 
+  std::shared_ptr<const Logr::Logger> d_logger{nullptr};
   std::unique_ptr<DOQServerConfig> d_server_config;
   dnsdist::doq::QuicheParams d_quicheParams;
   ComboAddress d_local;
index c1b892e55e7b1d9d37e09882d5e8c0d58949aa44..82b18ed325d1e9470b54a03629cc5359d6fe0a04 100644 (file)
@@ -266,7 +266,8 @@ private:
           }
         }
         catch (const std::exception& e) {
-          infolog("Error parsing the status header for stream ID %d: %s", frame->hd.stream_id, e.what());
+          SLOG(infolog("Error parsing the status header for stream ID %d: %s", frame->hd.stream_id, e.what()),
+               dnsdist::logging::getTopLogger()->error(e.what(), "Error parsing the status header for stream", "stream-id", Logging::Loggable(frame->hd.stream_id)));
           return NGHTTP2_ERR_CALLBACK_FAILURE;
         }
       }