dnsdist: Convert security status polling to structured logging

Signed-off-by: Remi Gacogne <remi.gacogne@powerdns.com>

diff --git a/pdns/dnsdistdist/dnsdist-secpoll.cc b/pdns/dnsdistdist/dnsdist-secpoll.cc
index 647b09fb83ae1f4b062c7e2d6a882761345d730b..92c5bec3aac79ca9e42831ba4591f37875807242 100644 (file)
--- a/pdns/dnsdistdist/dnsdist-secpoll.cc
+++ b/pdns/dnsdistdist/dnsdist-secpoll.cc
@@ -87,10 +87,8 @@ static std::string getFirstTXTAnswer(const std::string& answer)
   throw std::runtime_error("No TXT record in answer");
 }
 
-static std::string getSecPollStatus(const std::string& queriedName, int timeout = 2)
+static std::string getSecPollStatus(const Logr::Logger& logger, const std::string& queriedName, int timeout = 2)
 {
-  const auto verbose = dnsdist::configuration::getCurrentRuntimeConfiguration().d_verbose;
-
   const DNSName sentName(queriedName);
   std::vector<uint8_t> packet;
   DNSPacketWriter writer(packet, sentName, QType::TXT);
@@ -104,6 +102,7 @@ static std::string getSecPollStatus(const std::string& queriedName, int timeout
   }
 
   for (const auto& dest : resolversForStub) {
+    const auto resolverLogger = logger.withValues("network.peer.address", Logging::Loggable(dest));
     Socket sock(dest.sin4.sin_family, SOCK_DGRAM);
     sock.setNonBlocking();
     sock.connect(dest);
@@ -112,15 +111,13 @@ static std::string getSecPollStatus(const std::string& queriedName, int timeout
     string reply;
     int ret = waitForData(sock.getHandle(), timeout, 0);
     if (ret < 0) {
-      if (verbose) {
-        warnlog("Error while waiting for the secpoll response from stub resolver %s: %d", dest.toString(), ret);
-      }
+      VERBOSESLOG(warnlog("Error while waiting for the secpoll response from stub resolver %s: %d", dest.toString(), ret),
+                  resolverLogger->error(Logr::Warning, ret, "Error while waiting for the security status polling response from stub resolver"));
       continue;
     }
     if (ret == 0) {
-      if (verbose) {
-        warnlog("Timeout while waiting for the secpoll response from stub resolver %s", dest.toString());
-      }
+      VERBOSESLOG(warnlog("Timeout while waiting for the secpoll response from stub resolver %s", dest.toString()),
+                  resolverLogger->info(Logr::Warning, "Timeout while waiting for the security status polling response from stub resolver"));
       continue;
     }
 
@@ -128,32 +125,28 @@ static std::string getSecPollStatus(const std::string& queriedName, int timeout
       sock.read(reply);
     }
     catch (const std::exception& exp) {
-      if (verbose) {
-        warnlog("Error while reading for the secpoll response from stub resolver %s: %s", dest.toString(), exp.what());
-      }
+      VERBOSESLOG(warnlog("Error while reading for the secpoll response from stub resolver %s: %s", dest.toString(), exp.what()),
+                  resolverLogger->error(Logr::Warning, exp.what(), "Error while reading the security status polling response from stub resolver"));
       continue;
     }
 
     if (reply.size() <= sizeof(struct dnsheader)) {
-      if (verbose) {
-        warnlog("Too short answer of size %d received from the secpoll stub resolver %s", reply.size(), dest.toString());
-      }
+      VERBOSESLOG(warnlog("Too short answer of size %d received from the secpoll stub resolver %s", reply.size(), dest.toString()),
+                  resolverLogger->info(Logr::Warning, "Security status polling response received from the stub resolver is too small", "dns.response.size", Logging::Loggable(reply.size())));
       continue;
     }
 
     dnsheader dnsHeader{};
     memcpy(&dnsHeader, reply.c_str(), sizeof(dnsHeader));
     if (dnsHeader.id != writer.getHeader()->id) {
-      if (verbose) {
-        warnlog("Invalid ID (%d / %d) received from the secpoll stub resolver %s", dnsHeader.id, writer.getHeader()->id, dest.toString());
-      }
+      VERBOSESLOG(warnlog("Invalid ID (%d / %d) received from the secpoll stub resolver %s", dnsHeader.id, writer.getHeader()->id, dest.toString()),
+                  resolverLogger->info(Logr::Warning, "Invalid ID in security status polling response received from the stub resolver", "dns.response.size", Logging::Loggable(reply.size()), "dns.response.id", Logging::Loggable(dnsHeader.id), "dns.query.id", Logging::Loggable(writer.getHeader()->id)));
       continue;
     }
 
     if (dnsHeader.rcode != RCode::NoError) {
-      if (verbose) {
-        warnlog("Response code '%s' received from the secpoll stub resolver %s for '%s'", RCode::to_s(dnsHeader.rcode), dest.toString(), queriedName);
-      }
+      VERBOSESLOG(warnlog("Response code '%s' received from the secpoll stub resolver %s for '%s'", RCode::to_s(dnsHeader.rcode), dest.toString(), queriedName),
+                  resolverLogger->info(Logr::Warning, "Non-zero response code in status polling response received from the stub resolver", "dns.response.size", Logging::Loggable(reply.size()), "dns.response.id", Logging::Loggable(dnsHeader.id), "dns.response.code", Logging::Loggable(RCode::to_s(dnsHeader.rcode))));
 
       /* no need to try another resolver if the domain does not exist */
       if (dnsHeader.rcode == RCode::NXDomain) {
@@ -163,9 +156,8 @@ static std::string getSecPollStatus(const std::string& queriedName, int timeout
     }
 
     if (ntohs(dnsHeader.qdcount) != 1 || ntohs(dnsHeader.ancount) != 1) {
-      if (verbose) {
-        warnlog("Invalid answer (qdcount %d / ancount %d) received from the secpoll stub resolver %s", ntohs(dnsHeader.qdcount), ntohs(dnsHeader.ancount), dest.toString());
-      }
+      VERBOSESLOG(warnlog("Invalid answer (qdcount %d / ancount %d) received from the secpoll stub resolver %s", ntohs(dnsHeader.qdcount), ntohs(dnsHeader.ancount), dest.toString()),
+                  resolverLogger->info(Logr::Warning, "Invalid status polling response received from the stub resolver", "dns.response.size", Logging::Loggable(reply.size()), "dns.response.id", Logging::Loggable(dnsHeader.id), "dns.response.qdcount", Logging::Loggable(ntohs(dnsHeader.qdcount)), "dns.response.ancount", Logging::Loggable(ntohs(dnsHeader.ancount))));
       continue;
     }
 
@@ -174,9 +166,8 @@ static std::string getSecPollStatus(const std::string& queriedName, int timeout
     DNSName receivedName(reply.c_str(), reply.size(), sizeof(dnsheader), false, &receivedType, &receivedClass);
 
     if (receivedName != sentName || receivedType != QType::TXT || receivedClass != QClass::IN) {
-      if (verbose) {
-        warnlog("Invalid answer, either the qname (%s / %s), qtype (%s / %s) or qclass (%s / %s) does not match, received from the secpoll stub resolver %s", receivedName, sentName, QType(receivedType).toString(), QType(QType::TXT).toString(), QClass(receivedClass).toString(), QClass::IN.toString(), dest.toString());
-      }
+      VERBOSESLOG(warnlog("Invalid answer, either the qname (%s / %s), qtype (%s / %s) or qclass (%s / %s) does not match, received from the secpoll stub resolver %s", receivedName, sentName, QType(receivedType).toString(), QType(QType::TXT).toString(), QClass(receivedClass).toString(), QClass::IN.toString(), dest.toString()),
+                  resolverLogger->info(Logr::Warning, "Invalid status polling response received from the stub resolver, either the name, type or qclass does not match", "dns.response.size", Logging::Loggable(reply.size()), "dns.response.id", Logging::Loggable(dnsHeader.id), "dns.response.name", Logging::Loggable(receivedName), "dns.response.type", Logging::Loggable(QType(receivedType)), "dns.response.class", Logging::Loggable(QClass(receivedClass))));
       continue;
     }
 
@@ -191,14 +182,14 @@ namespace dnsdist::secpoll
 void doSecPoll(const std::string& suffix)
 {
   static bool s_secPollDone{false};
+  constexpr std::string_view pkgv(PACKAGEVERSION);
+  const bool releaseVersion = std::count(pkgv.begin(), pkgv.end(), '.') == 2;
 
   if (suffix.empty()) {
     return;
   }
 
-  const std::string pkgv(PACKAGEVERSION);
-  bool releaseVersion = std::count(pkgv.begin(), pkgv.end(), '.') == 2;
-  const std::string version = "dnsdist-" + pkgv;
+  const std::string version = std::string("dnsdist-") + std::string(pkgv);
   std::string queriedName = version.substr(0, 63) + ".security-status." + suffix;
 
   if (*queriedName.rbegin() != '.') {
@@ -208,21 +199,26 @@ void doSecPoll(const std::string& suffix)
   std::replace(queriedName.begin(), queriedName.end(), '+', '_');
   std::replace(queriedName.begin(), queriedName.end(), '~', '_');
 
+  auto logger = dnsdist::logging::getTopLogger()->withName("security-status-polling")->withValues("version", Logging::Loggable(pkgv), "dns.query.name", Logging::Loggable(queriedName));
+
   try {
-    std::string status = getSecPollStatus(queriedName);
-    pair<string, string> split = splitField(unquotify(status), ' ');
+    const std::string status = getSecPollStatus(*logger, queriedName);
+    const std::pair<string, string> split = splitField(unquotify(status), ' ');
 
-    int securityStatus = std::stoi(split.first);
-    std::string securityMessage = split.second;
+    const auto securityStatus = pdns::checked_stoi<uint8_t>(split.first);
+    const std::string& securityMessage = split.second;
 
     if (securityStatus == 1 && !s_secPollDone) {
-      infolog("Polled security status of version %s at startup, no known issues reported: %s", std::string(VERSION), securityMessage);
+      SLOG(infolog("Polled security status of version %s at startup, no known issues reported: %s", std::string(VERSION), securityMessage),
+           logger->info(Logr::Info, "Polled security status at startup, no known issues reported", "message", Logging::Loggable(securityMessage), "status", Logging::Loggable(securityStatus)));
     }
     if (securityStatus == 2) {
-      errlog("PowerDNS DNSDist Security Update Recommended: %s", securityMessage);
+      SLOG(errlog("PowerDNS DNSDist Security Update Recommended: %s", securityMessage),
+           logger->error(Logr::Error, securityMessage, "PowerDNS DNSDist Security Update Recommended", "status", Logging::Loggable(securityStatus)));
     }
     else if (securityStatus == 3) {
-      errlog("PowerDNS DNSDist Security Update Mandatory: %s", securityMessage);
+      SLOG(errlog("PowerDNS DNSDist Security Update Mandatory: %s", securityMessage),
+           logger->error(Logr::Error, securityMessage, "PowerDNS DNSDist Security Update Mandatory", "status", Logging::Loggable(securityStatus)));
     }
 
     dnsdist::metrics::g_stats.securityStatus = securityStatus;
@@ -231,19 +227,22 @@ void doSecPoll(const std::string& suffix)
   }
   catch (const std::exception& exp) {
     if (releaseVersion) {
-      warnlog("Error while retrieving the security update for version %s: %s", version, exp.what());
+      SLOG(warnlog("Error while retrieving the security update for version %s: %s", version, exp.what()),
+           logger->error(Logr::Warning, exp.what(), "Error while retrieving the security status"));
     }
     else if (!s_secPollDone) {
-      infolog("Error while retrieving the security update for version %s: %s", version, exp.what());
+      SLOG(infolog("Error while retrieving the security update for version %s: %s", version, exp.what()),
+           logger->error(Logr::Info, exp.what(), "Error while retrieving the security status"));
     }
   }
 
   if (releaseVersion) {
-    warnlog("Failed to retrieve security status update for '%s' on %s", pkgv, queriedName);
+    SLOG(warnlog("Failed to retrieve security status update for '%s' on %s", pkgv, queriedName),
+         logger->info(Logr::Warning, "Failed to retrieve security status"));
   }
   else if (!s_secPollDone) {
-    infolog("Not validating response for security status update, this is a non-release version.");
-
+    SLOG(infolog("Not validating response for security status update, this is a non-release version."),
+         logger->info(Logr::Info, "Not validating response for security status update, this is a non-release version."));
     /* for non-released versions, there is no use sending the same message several times,
        let's just accept that there will be no security polling for this exact version */
     s_secPollDone = true;