dnsdist: Convert the TCP frontend to structured logging

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

diff --git a/pdns/dnsdistdist/Makefile.am b/pdns/dnsdistdist/Makefile.am
index b58b4fb9d3cdcd7c8adb8e9064965a03c973b2a1..401caf0c5e719b4f9366e68c8c12d985f89f7c7b 100644 (file)
--- a/pdns/dnsdistdist/Makefile.am
+++ b/pdns/dnsdistdist/Makefile.am
@@ -629,7 +629,7 @@ fuzz_target_dnsdistcache_SOURCES = \
        dnsdist-dnsparser.cc dnsdist-dnsparser.hh \
        dnsdist-dnsquestion.cc \
        dnsdist-ecs.cc dnsdist-ecs.hh \
-       dnsdist-idstate.hh \
+       dnsdist-idstate.cc dnsdist-idstate.hh \
        dnsdist-logging.cc dnsdist-logging.hh \
        dnsdist-protocols.cc dnsdist-protocols.hh \
        dnslabeltext.cc \

diff --git a/pdns/dnsdistdist/dnsdist-dnsquestion.cc b/pdns/dnsdistdist/dnsdist-dnsquestion.cc
index 5384abfc6803d38b24bbd68e5a88666a2814be51..7c5763d39e46d727d2d3abd889f5ab8acaaa0b56 100644 (file)
--- a/pdns/dnsdistdist/dnsdist-dnsquestion.cc
+++ b/pdns/dnsdistdist/dnsdist-dnsquestion.cc
@@ -60,22 +60,20 @@ DNSQuestion::DNSQuestion(InternalQueryState& ids_, PacketBuffer& data_) :
 {
 }
 
-std::shared_ptr<const Logr::Logger> DNSQuestion::getThisLogger() const
+std::shared_ptr<const Logr::Logger> DNSQuestion::getThisLogger(std::shared_ptr<const Logr::Logger> parent) const
 {
   if (d_logger) {
     return d_logger;
   }
-  auto logger = dnsdist::logging::getTopLogger();
-  logger = logger->withValues("dns.question.name", Logging::Loggable(ids.qname), "dns.question.type", Logging::Loggable(QType(ids.qtype)), "dns.question.class", Logging::Loggable(QClass(ids.qclass)), "source.address", Logging::Loggable(ids.origRemote), "destination.address", Logging::Loggable(ids.origDest), "proto", Logging::Loggable(ids.protocol), "dns.question.id", Logging::Loggable(ntohs(ids.origID)), "dns.question.flags", Logging::Loggable(ids.origFlags));
-  return logger;
+  return ids.getLogger(parent);
 }
 
-std::shared_ptr<const Logr::Logger> DNSResponse::getThisLogger() const
+std::shared_ptr<const Logr::Logger> DNSResponse::getThisLogger(std::shared_ptr<const Logr::Logger> parent) const
 {
   if (d_logger) {
     return d_logger;
   }
-  auto logger = DNSQuestion::getThisLogger();
+  auto logger = DNSQuestion::getThisLogger(parent);
   if (data.size() >= sizeof(dnsheader)) {
     const auto header = getHeader();
     logger = logger->withValues("dns.response.rcode", Logging::Loggable(RCode::to_s(header->rcode)));
@@ -88,16 +86,16 @@ std::shared_ptr<const Logr::Logger> DNSResponse::getThisLogger() const
   return logger;
 }
 
-std::shared_ptr<const Logr::Logger> DNSQuestion::getLogger() const
+std::shared_ptr<const Logr::Logger> DNSQuestion::getLogger(std::shared_ptr<const Logr::Logger> parent) const
 {
-  return getThisLogger();
+  return getThisLogger(parent);
 }
 
-std::shared_ptr<const Logr::Logger> DNSQuestion::getLogger()
+std::shared_ptr<const Logr::Logger> DNSQuestion::getLogger(std::shared_ptr<const Logr::Logger> parent)
 {
   if (d_logger) {
     return d_logger;
   }
-  d_logger = getThisLogger();
+  d_logger = getThisLogger(parent);
   return d_logger;
 }

diff --git a/pdns/dnsdistdist/dnsdist-idstate.cc b/pdns/dnsdistdist/dnsdist-idstate.cc
index 8089b30162102b5be554b66ac5c1d0d894e94219..4a0b011fc4d2af07fe0bbe75f2844056d9c0f0e5 100644 (file)
--- a/pdns/dnsdistdist/dnsdist-idstate.cc
+++ b/pdns/dnsdistdist/dnsdist-idstate.cc
@@ -163,3 +163,12 @@ std::optional<pdns::trace::dnsdist::Tracer::Closer> InternalQueryState::getRules
 #endif
   return ret;
 }
+
+std::shared_ptr<const Logr::Logger> InternalQueryState::getLogger(std::shared_ptr<const Logr::Logger> parent) const
+{
+  if (!parent) {
+    parent = dnsdist::logging::getTopLogger();
+  }
+  auto logger = parent->withValues("dns.question.name", Logging::Loggable(this->qname), "dns.question.type", Logging::Loggable(QType(this->qtype)), "dns.question.class", Logging::Loggable(QClass(this->qclass)), "source.address", Logging::Loggable(this->origRemote), "destination.address", Logging::Loggable(this->origDest), "proto", Logging::Loggable(this->protocol), "dns.question.id", Logging::Loggable(ntohs(this->origID)), "dns.question.flags", Logging::Loggable(this->origFlags));
+  return logger;
+}

diff --git a/pdns/dnsdistdist/dnsdist-idstate.hh b/pdns/dnsdistdist/dnsdist-idstate.hh
index 185ad693a049dca9cc50597b817d08baf5c01f70..6f82350966fc1fc643a807cb36563b78607b18a2 100644 (file)
--- a/pdns/dnsdistdist/dnsdist-idstate.hh
+++ b/pdns/dnsdistdist/dnsdist-idstate.hh
@@ -35,6 +35,7 @@
 #include "dnsdist-configuration.hh"
 #include "dnsdist-edns.hh"
 #include "dnsname.hh"
+#include "dnsdist-logging.hh"
 #include "dnsdist-protocols.hh"
 #include "ednsextendederror.hh"
 #include "gettime.hh"
@@ -177,6 +178,8 @@ struct InternalQueryState
 
   InternalQueryState partialCloneForXFR() const;
 
+  std::shared_ptr<const Logr::Logger> getLogger(std::shared_ptr<const Logr::Logger> parent = nullptr) const;
+
   std::optional<Netmask> subnet{std::nullopt}; // 40
   std::string poolName; // 32
 #if !defined(DISABLE_PROTOBUF)

diff --git a/pdns/dnsdistdist/dnsdist-lua.cc b/pdns/dnsdistdist/dnsdist-lua.cc
index 526a5fa163d3a3d5fc15718fe375827c08ee3905..1856d010cf49551a6465e41b09e6d3393299c346 100644 (file)
--- a/pdns/dnsdistdist/dnsdist-lua.cc
+++ b/pdns/dnsdistdist/dnsdist-lua.cc
@@ -2340,7 +2340,6 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck)
       if (!frontend->d_tlsContext->d_provider.empty()) {
         VERBOSESLOG(infolog("Loading TLS provider '%s'", frontend->d_tlsContext->d_provider),
                     getLogger("addDOHLocal")->info(Logr::Info, "Loading TLS provider for DoH frontend", "frontend.address", Logging::Loggable(addr), "tls.provider", Logging::Loggable(frontend->d_tlsContext->d_provider)));
-
       }
       else {
 #ifdef HAVE_LIBSSL
@@ -2660,7 +2659,7 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck)
     catch (const std::exception& e) {
       g_outputBuffer = "Error while trying to get DOH3 frontend with index " + std::to_string(index) + ": " + string(e.what()) + "\n";
       SLOG(errlog("Error while trying to get DOH3 frontend with index %d: %s\n", index, e.what()),
-                  getLogger("getDOH3Frontend")->error(Logr::Error, e.what(), "Error while trying to get DOH3 frontend", "index", Logging::Loggable(index)));
+           getLogger("getDOH3Frontend")->error(Logr::Error, e.what(), "Error while trying to get DOH3 frontend", "index", Logging::Loggable(index)));
     }
     return result;
   });
@@ -2888,7 +2887,6 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck)
       if (!frontend->d_provider.empty()) {
         VERBOSESLOG(infolog("Loading TLS provider '%s'", frontend->d_provider),
                     getLogger("addTLSLocal")->info(Logr::Info, "Loading TLS provider for DoT frontend", "frontend.address", Logging::Loggable(addr), "tls.provider", Logging::Loggable(frontend->d_provider)));
-
       }
       else {
 #ifdef HAVE_LIBSSL
@@ -2898,7 +2896,6 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck)
 #endif
         VERBOSESLOG(infolog("Loading default TLS provider '%s'", provider),
                     getLogger("addTLSLocal")->info(Logr::Info, "Loading default TLS provider for DoT frontend", "frontend.address", Logging::Loggable(addr), "tls.provider", Logging::Loggable(provider)));
-
       }
       // only works pre-startup, so no sync necessary
       auto clientState = std::make_shared<ClientState>(frontend->d_addr, true, reusePort, tcpFastOpenQueueSize, interface, cpus, enableProxyProtocol);
@@ -2972,7 +2969,6 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck)
       g_outputBuffer = "Error while trying to get TLS frontend with index " + std::to_string(index) + ": " + string(e.what()) + "\n";
       SLOG(errlog("Error while trying to get TLS frontend with index %d: %s\n", index, e.what()),
            getLogger("getTLSFrontend")->error(Logr::Error, e.what(), "Error while trying to get DOT frontend", "index", Logging::Loggable(index)));
-
     }
 #else
         g_outputBuffer="DNS over TLS support is not present!\n";

diff --git a/pdns/dnsdistdist/dnsdist-nghttp2.cc b/pdns/dnsdistdist/dnsdist-nghttp2.cc
index 87fe34aa599912eddb7a9f29a589e3cef628c40a..9df2092cd8bc2371d22a27bb2af909a4e322b863 100644 (file)
--- a/pdns/dnsdistdist/dnsdist-nghttp2.cc
+++ b/pdns/dnsdistdist/dnsdist-nghttp2.cc
@@ -62,6 +62,11 @@ public:
     return o.str();
   }
 
+  std::shared_ptr<const Logr::Logger> getLogger() const override
+  {
+    return ConnectionToBackend::getLogger()->withName("outgoing-doh-connection")->withValues("concurrent_streams", Logging::Loggable(getConcurrentStreamsCount()), "health_check_query", Logging::Loggable(d_healthCheckQuery));
+  }
+
   void setHealthCheck(bool h)
   {
     d_healthCheckQuery = h;

diff --git a/pdns/dnsdistdist/dnsdist-tcp-downstream.cc b/pdns/dnsdistdist/dnsdist-tcp-downstream.cc
index 8d83181e9fb7118bb65be5b1c62cf4a310868f31..27f302e06ea62ca6ca638fc98b862be2c23f2cfb 100644 (file)
--- a/pdns/dnsdistdist/dnsdist-tcp-downstream.cc
+++ b/pdns/dnsdistdist/dnsdist-tcp-downstream.cc
@@ -898,6 +898,21 @@ bool TCPConnectionToBackend::isXFRFinished(const TCPResponse& response, TCPQuery
   return done;
 }
 
+std::shared_ptr<const Logr::Logger> ConnectionToBackend::getLogger() const
+{
+  auto logger = dnsdist::logging::getTopLogger()->withName("outgoing-tcp-connection")->withValues("fresh_connection", Logging::Loggable(d_fresh), "tcp_fast_open", Logging::Loggable(d_enableFastOpen), "proxy_protocol_payload_sent", Logging::Loggable(d_proxyProtocolPayloadSent), "downstream_failures", Logging::Loggable(d_downstreamFailures), "highest_stream_id", Logging::Loggable(d_highestStreamID), "queries_count", Logging::Loggable(d_queries), "io_state", Logging::Loggable(d_ioState ? d_ioState->getState() : "empty"));
+  if (d_ds) {
+    logger = logger->withValues("backend.address", Logging::Loggable(d_ds->d_config.remote), "backend.name", Logging::Loggable(d_ds->getName()));
+  }
+
+  return logger;
+}
+
+std::shared_ptr<const Logr::Logger> TCPConnectionToBackend::getLogger() const
+{
+  return ConnectionToBackend::getLogger()->withValues("state", Logging::Loggable(static_cast<int>(d_state)), "pending_queries", Logging::Loggable(d_pendingQueries.size()), "pending_responses", Logging::Loggable(d_pendingResponses.size()));
+}
+
 void setTCPDownstreamMaxIdleConnectionsPerBackend(uint64_t max)
 {
   DownstreamTCPConnectionsManager::setMaxIdleConnectionsPerDownstream(max);

diff --git a/pdns/dnsdistdist/dnsdist-tcp-downstream.hh b/pdns/dnsdistdist/dnsdist-tcp-downstream.hh
index b6faa41aac93253ca67fa4ecb278b8ce184b8f0b..be223c8a6bbb1b38ec1886efe507ac404c0f4a8b 100644 (file)
--- a/pdns/dnsdistdist/dnsdist-tcp-downstream.hh
+++ b/pdns/dnsdistdist/dnsdist-tcp-downstream.hh
@@ -142,6 +142,8 @@ public:
 
   virtual std::string toString() const = 0;
 
+  virtual std::shared_ptr<const Logr::Logger> getLogger() const;
+
 protected:
   bool reconnect();
 
@@ -267,6 +269,8 @@ public:
 
   void setProxyProtocolValuesSent(std::unique_ptr<std::vector<ProxyProtocolValue>>&& proxyProtocolValuesSent);
 
+  std::shared_ptr<const Logr::Logger> getLogger() const override;
+
 private:
   /* waitingForResponseFromBackend is a state where we have not yet started reading the size,
      so we can still switch to sending instead */

diff --git a/pdns/dnsdistdist/dnsdist-tcp.cc b/pdns/dnsdistdist/dnsdist-tcp.cc
index 322f4780519b573db8e306bcd9aaf5172d2e012f..5c12f2f813c4eb230c01d7fd6482280fbd573a9b 100644 (file)
--- a/pdns/dnsdistdist/dnsdist-tcp.cc
+++ b/pdns/dnsdistdist/dnsdist-tcp.cc
@@ -193,10 +193,12 @@ void TCPClientCollection::addTCPClientThread(std::vector<ClientState*>& tcpAccep
 
     auto [crossProtocolResponseChannelSender, crossProtocolResponseChannelReceiver] = pdns::channel::createObjectQueue<TCPCrossProtocolResponse>(pdns::channel::SenderBlockingMode::SenderNonBlocking, pdns::channel::ReceiverBlockingMode::ReceiverNonBlocking, internalPipeBufferSize);
 
-    vinfolog("Adding TCP Client thread");
+    VERBOSESLOG(infolog("Adding TCP Client thread"),
+                dnsdist::logging::getTopLogger()->info(Logr::Info, "Adding TCP worker thread to handle TCP connections from clients"));
 
     if (d_numthreads >= d_tcpclientthreads.size()) {
-      vinfolog("Adding a new TCP client thread would exceed the vector size (%d/%d), skipping. Consider increasing the maximum amount of TCP client threads with setMaxTCPClientThreads() in the configuration.", d_numthreads.load(), d_tcpclientthreads.size());
+      VERBOSESLOG(infolog("Adding a new TCP client thread would exceed the vector size (%d/%d), skipping. Consider increasing the maximum amount of TCP client threads with setMaxTCPClientThreads() in the configuration.", d_numthreads.load(), d_tcpclientthreads.size()),
+                  dnsdist::logging::getTopLogger()->info(Logr::Info, "Adding a new TCP client thread would exceed the vector size, skipping. Consider increasing the maximum amount of TCP client threads with setMaxTCPClientThreads() in the configuration.", "workers_count", Logging::Loggable(d_numthreads.load()), "workers_limit", Logging::Loggable(d_tcpclientthreads.size())));
       return;
     }
 
@@ -207,7 +209,8 @@ void TCPClientCollection::addTCPClientThread(std::vector<ClientState*>& tcpAccep
       clientThread.detach();
     }
     catch (const std::runtime_error& e) {
-      errlog("Error creating a TCP thread: %s", e.what());
+      SLOG(errlog("Error creating a TCP thread: %s", e.what()),
+           dnsdist::logging::getTopLogger()->error(Logr::Error, e.what(), "Error creating a TCP worker thread"));
       return;
     }
 
@@ -215,7 +218,8 @@ void TCPClientCollection::addTCPClientThread(std::vector<ClientState*>& tcpAccep
     ++d_numthreads;
   }
   catch (const std::exception& e) {
-    errlog("Error creating TCP worker: %s", e.what());
+    SLOG(errlog("Error creating TCP worker: %s", e.what()),
+         dnsdist::logging::getTopLogger()->error(Logr::Error, e.what(), "Error creating a TCP worker"));
   }
 }
 
@@ -252,7 +256,8 @@ void IncomingTCPConnectionState::handleResponseSent(TCPResponse& currentResponse
   if (!currentResponse.d_idstate.selfGenerated && backend) {
     const auto& ids = currentResponse.d_idstate;
     auto udiff = ids.queryRealTime.udiff();
-    vinfolog("Got answer from %s, relayed to %s (%s, %d bytes), took %d us", backend->d_config.remote.toStringWithPort(), ids.origRemote.toStringWithPort(), getProtocol().toString(), sentBytes, udiff);
+    VERBOSESLOG(infolog("Got answer from %s, relayed to %s (%s, %d bytes), took %d us", backend->d_config.remote.toStringWithPort(), ids.origRemote.toStringWithPort(), getProtocol().toString(), sentBytes, udiff),
+                ids.getLogger(getLogger())->info(Logr::Info, "Relayed response to client", "backend.name", Logging::Loggable(backend->getName()), "backend.address", Logging::Loggable(backend->d_config.remote), "dns.response.size", Logging::Loggable(sentBytes), "dns.response.latency-us", Logging::Loggable(udiff)));
 
     auto backendProtocol = backend->getProtocol();
     if (backendProtocol == dnsdist::Protocol::DoUDP && !currentResponse.d_idstate.forwardedOverUDP) {
@@ -304,12 +309,14 @@ bool IncomingTCPConnectionState::canAcceptNewQueries(const struct timeval& now)
 
   const auto& currentConfig = dnsdist::configuration::getCurrentRuntimeConfiguration();
   if (currentConfig.d_maxTCPQueriesPerConn != 0 && d_queriesCount > currentConfig.d_maxTCPQueriesPerConn) {
-    vinfolog("not accepting new queries from %s because it reached the maximum number of queries per conn (%d / %d)", d_ci.remote.toStringWithPort(), d_queriesCount, currentConfig.d_maxTCPQueriesPerConn);
+    VERBOSESLOG(infolog("not accepting new queries from %s because it reached the maximum number of queries per conn (%d / %d)", d_ci.remote.toStringWithPort(), d_queriesCount, currentConfig.d_maxTCPQueriesPerConn),
+                getLogger()->info(Logr::Info, "Not accepting new queries: reached the maximum number of queries per connection", "queries_count", Logging::Loggable(d_queriesCount), "queries_count_limit", Logging::Loggable(currentConfig.d_maxTCPQueriesPerConn)));
     return false;
   }
 
   if (maxConnectionDurationReached(currentConfig.d_maxTCPConnectionDuration, now)) {
-    vinfolog("not accepting new queries from %s because it reached the maximum TCP connection duration", d_ci.remote.toStringWithPort());
+    VERBOSESLOG(infolog("not accepting new queries from %s because it reached the maximum TCP connection duration", d_ci.remote.toStringWithPort()),
+                getLogger()->info(Logr::Info, "Not accepting new queries: reached the maximum TCP connection duration"));
     return false;
   }
 
@@ -457,8 +464,8 @@ IOState IncomingTCPConnectionState::sendResponse(const struct timeval& now, TCPR
     return iostate;
   }
   catch (const std::exception& e) {
-    vinfolog("Closing TCP client connection with %s: %s", d_ci.remote.toStringWithPort(), e.what());
-    DEBUGLOG("Closing TCP client connection: " << e.what());
+    VERBOSESLOG(infolog("Closing TCP client connection with %s: %s", d_ci.remote.toStringWithPort(), e.what()),
+                getLogger()->error(Logr::Info, e.what(), "Closing TCP client connection"));
     ++d_ci.cs->tcpDiedSendingResponse;
 
     terminateClientConnection();
@@ -619,7 +626,8 @@ void IncomingTCPConnectionState::handleResponse(const struct timeval& now, TCPRe
               response.d_connection->release(true);
             }
             catch (const std::exception& e) {
-              vinfolog("Error releasing connection: %s", e.what());
+              VERBOSESLOG(infolog("Error releasing connection: %s", e.what()),
+                          getLogger()->error(Logr::Info, e.what(), "Error releasing connection to backend"));
             }
             list.erase(it);
             break;
@@ -663,7 +671,8 @@ void IncomingTCPConnectionState::handleResponse(const struct timeval& now, TCPRe
       }
     }
     catch (const std::exception& e) {
-      vinfolog("Unexpected exception while handling response from backend: %s", e.what());
+      VERBOSESLOG(infolog("Unexpected exception while handling response from backend: %s", e.what()),
+                  getLogger()->error(Logr::Info, e.what(), "Unexpected exception while handling response from backend"));
       state->terminateClientConnection();
       return;
     }
@@ -754,11 +763,13 @@ void IncomingTCPConnectionState::handleCrossProtocolResponse(const struct timeva
     auto ptr = std::make_unique<TCPCrossProtocolResponse>(std::move(response), state, now);
     if (!state->d_threadData.crossProtocolResponseSender.send(std::move(ptr))) {
       ++dnsdist::metrics::g_stats.tcpCrossProtocolResponsePipeFull;
-      vinfolog("Unable to pass a cross-protocol response to the TCP worker thread because the pipe is full");
+      VERBOSESLOG(infolog("Unable to pass a cross-protocol response to the TCP worker thread because the pipe is full"),
+                  getLogger()->info(Logr::Info, "Unable to pass a cross-protocol response to the TCP worker thread because the pipe is full"));
     }
   }
   catch (const std::exception& e) {
-    vinfolog("Unable to pass a cross-protocol response to the TCP worker thread because we couldn't write to the pipe: %s", stringerror());
+    VERBOSESLOG(infolog("Unable to pass a cross-protocol response to the TCP worker thread because we couldn't write to the pipe: %s", e.what()),
+                getLogger()->error(Logr::Info, e.what(), "Unable to pass a cross-protocol response to the TCP worker thread because we couldn't write to the pipe"));
   }
 }
 
@@ -939,7 +950,8 @@ IncomingTCPConnectionState::QueryProcessingResult IncomingTCPConnectionState::ha
 
   std::string proxyProtocolPayload;
   if (backend->isDoH()) {
-    vinfolog("Got query for %s|%s from %s (%s, %d bytes), relayed to %s", ids.qname.toLogString(), QType(ids.qtype).toString(), d_proxiedRemote.toStringWithPort(), getProtocol().toString(), query.size(), backend->getNameWithAddr());
+    VERBOSESLOG(infolog("Got query for %s|%s from %s (%s, %d bytes), relayed to %s", ids.qname.toLogString(), QType(ids.qtype).toString(), d_proxiedRemote.toStringWithPort(), getProtocol().toString(), query.size(), backend->getNameWithAddr()),
+                ids.getLogger(getLogger())->info(Logr::Info, "Relayed query to backend", "backend.name", Logging::Loggable(backend->getName()), "backend.address", Logging::Loggable(backend->d_config.remote)));
 
     /* we need to do this _before_ creating the cross protocol query because
        after that the buffer will have been moved */
@@ -995,7 +1007,9 @@ IncomingTCPConnectionState::QueryProcessingResult IncomingTCPConnectionState::ha
     tcpquery.d_proxyProtocolPayload = std::move(proxyProtocolPayload);
   }
 
-  vinfolog("Got query for %s|%s from %s (%s, %d bytes), relayed to %s", tcpquery.d_idstate.qname.toLogString(), QType(tcpquery.d_idstate.qtype).toString(), d_proxiedRemote.toStringWithPort(), getProtocol().toString(), tcpquery.d_buffer.size(), backend->getNameWithAddr());
+  VERBOSESLOG(infolog("Got query for %s|%s from %s (%s, %d bytes), relayed to %s", tcpquery.d_idstate.qname.toLogString(), QType(tcpquery.d_idstate.qtype).toString(), d_proxiedRemote.toStringWithPort(), getProtocol().toString(), tcpquery.d_buffer.size(), backend->getNameWithAddr()),
+              tcpquery.d_idstate.getLogger(getLogger())->info(Logr::Info, "Relayed query to backend", "backend.name", Logging::Loggable(backend->getName()), "backend.address", Logging::Loggable(backend->d_config.remote)));
+
   std::shared_ptr<TCPQuerySender> incoming = state;
   downstreamConnection->queueQuery(incoming, std::move(tcpquery));
   return QueryProcessingResult::Forwarded;
@@ -1043,7 +1057,8 @@ IncomingTCPConnectionState::ProxyProtocolResult IncomingTCPConnectionState::hand
       d_buffer.resize(d_currentPos);
       ssize_t remaining = isProxyHeaderComplete(d_buffer);
       if (remaining == 0) {
-        vinfolog("Unable to consume proxy protocol header in packet from TCP client %s", d_ci.remote.toStringWithPort());
+        VERBOSESLOG(infolog("Unable to consume proxy protocol header in packet from TCP client %s", d_ci.remote.toStringWithPort()),
+                    getLogger()->info(Logr::Info, "Unable to consume proxy protocol header in packet from TCP client"));
         ++dnsdist::metrics::g_stats.proxyProtocolInvalid;
         return ProxyProtocolResult::Error;
       }
@@ -1056,7 +1071,8 @@ IncomingTCPConnectionState::ProxyProtocolResult IncomingTCPConnectionState::hand
         /* proxy header received */
         std::vector<ProxyProtocolValue> proxyProtocolValues;
         if (!handleProxyProtocol(d_ci.remote, true, dnsdist::configuration::getCurrentRuntimeConfiguration().d_ACL, d_buffer, d_proxiedRemote, d_proxiedDestination, proxyProtocolValues)) {
-          vinfolog("Error handling the Proxy Protocol received from TCP client %s", d_ci.remote.toStringWithPort());
+          VERBOSESLOG(infolog("Error handling the Proxy Protocol received from TCP client %s", d_ci.remote.toStringWithPort()),
+                      getLogger()->info(Logr::Info, "Error handling the Proxy Protocol received from TCP client"));
           return ProxyProtocolResult::Error;
         }
 
@@ -1151,12 +1167,12 @@ void IncomingTCPConnectionState::handleExceptionDuringIO(const std::exception& e
   }
 
   if (d_ioState->isWaitingForWrite() || d_queriesCount == 0) {
-    DEBUGLOG("Got an exception while handling TCP query: " << exp.what());
-    vinfolog("Got an exception while handling (%s) TCP query from %s: %s", (d_ioState->isWaitingForRead() ? "reading" : "writing"), d_ci.remote.toStringWithPort(), exp.what());
+    VERBOSESLOG(infolog("Got an exception while handling (%s) TCP query from %s: %s", (d_ioState->isWaitingForRead() ? "reading" : "writing"), d_ci.remote.toStringWithPort(), exp.what()),
+                getLogger()->error(Logr::Info, exp.what(), "Got an exception while handling TCP query", "io", Logging::Loggable(d_ioState->isWaitingForRead() ? "reading" : "writing")));
   }
   else {
-    vinfolog("Closing TCP client connection with %s: %s", d_ci.remote.toStringWithPort(), exp.what());
-    DEBUGLOG("Closing TCP client connection: " << exp.what());
+    VERBOSESLOG(infolog("Closing TCP client connection with %s: %s", d_ci.remote.toStringWithPort(), exp.what()),
+                getLogger()->error(Logr::Info, exp.what(), "Closing TCP client connection"));
   }
   /* remove this FD from the IO multiplexer */
   terminateClientConnection();
@@ -1234,7 +1250,8 @@ void IncomingTCPConnectionState::handleIO()
     IOStateGuard ioGuard(d_ioState);
 
     if (maxConnectionDurationReached(dnsdist::configuration::getCurrentRuntimeConfiguration().d_maxTCPConnectionDuration, now)) {
-      vinfolog("Terminating TCP connection from %s because it reached the maximum TCP connection duration", d_ci.remote.toStringWithPort());
+      VERBOSESLOG(infolog("Terminating TCP connection from %s because it reached the maximum TCP connection duration", d_ci.remote.toStringWithPort()),
+                  getLogger()->info(Logr::Info, "Terminating TCP connection because it reached the maximum TCP connection duration"));
       // will be handled by the ioGuard
       // handleNewIOState(state, IOState::Done, fd, handleIOCallback);
       return;
@@ -1242,7 +1259,8 @@ void IncomingTCPConnectionState::handleIO()
 
     const auto& immutable = dnsdist::configuration::getImmutableConfiguration();
     if (immutable.d_maxTCPReadIOsPerQuery > 0 && d_readIOsCurrentQuery >= immutable.d_maxTCPReadIOsPerQuery) {
-      vinfolog("Terminating TCP connection from %s for reaching the maximum number of read IO events per query (%d)", d_ci.remote.toStringWithPort(), immutable.d_maxTCPReadIOsPerQuery);
+      VERBOSESLOG(infolog("Terminating TCP connection from %s for reaching the maximum number of read IO events per query (%d)", d_ci.remote.toStringWithPort(), immutable.d_maxTCPReadIOsPerQuery),
+                  getLogger()->info(Logr::Info, "Terminating TCP connection for reaching the maximum number of read IO events per query", "maximum_tcp_read_ios_per_query", Logging::Loggable(immutable.d_maxTCPReadIOsPerQuery)));
       dnsdist::IncomingConcurrentTCPConnectionsManager::banClientFor(d_ci.remote, time(nullptr), immutable.d_tcpBanDurationForExceedingMaxReadIOsPerQuery);
       return;
     }
@@ -1326,7 +1344,8 @@ void IncomingTCPConnectionState::handleIO()
       }
 
       if (d_state != State::idle && d_state != State::doingHandshake && d_state != State::readingProxyProtocolHeader && d_state != State::waitingForQuery && d_state != State::readingQuerySize && d_state != State::readingQuery && d_state != State::sendingResponse) {
-        vinfolog("Unexpected state %d in handleIOCallback", static_cast<int>(d_state));
+        VERBOSESLOG(infolog("Unexpected state %d in handleIOCallback", static_cast<int>(d_state)),
+                    getLogger()->info(Logr::Info, "Unexpected state in handleIOCallback", "state", Logging::Loggable(static_cast<int>(d_state))));
       }
     }
     catch (const std::exception& exp) {
@@ -1380,7 +1399,8 @@ void IncomingTCPConnectionState::notifyIOError(const struct timeval& now, TCPRes
       }
     }
     catch (const std::exception& e) {
-      vinfolog("Exception in notifyIOError: %s", e.what());
+      VERBOSESLOG(infolog("Exception in notifyIOError: %s", e.what()),
+                  getLogger()->error(Logr::Info, e.what(), "Exception in notifyIOError"));
     }
   }
   else {
@@ -1435,7 +1455,8 @@ void IncomingTCPConnectionState::handleXFRResponse(const struct timeval& now, TC
 
 void IncomingTCPConnectionState::handleTimeout(std::shared_ptr<IncomingTCPConnectionState>& state, bool write)
 {
-  vinfolog("Timeout while %s TCP client %s", (write ? "writing to" : "reading from"), state->d_ci.remote.toStringWithPort());
+  VERBOSESLOG(infolog("Timeout while %s TCP client %s", (write ? "writing to" : "reading from"), state->d_ci.remote.toStringWithPort()),
+              state->getLogger()->info(Logr::Info, "Timeout on network operation", "io", Logging::Loggable(write ? "writing to" : "reading from")));
   DEBUGLOG("client timeout");
   DEBUGLOG("Processed " << state->d_queriesCount << " queries, current count is " << state->d_currentQueriesCount << ", " << state->d_ownedConnectionsToBackend.size() << " owned connections, " << state->d_queuedResponses.size() << " response queued");
 
@@ -1453,7 +1474,7 @@ void IncomingTCPConnectionState::handleTimeout(std::shared_ptr<IncomingTCPConnec
 
 std::shared_ptr<const Logr::Logger> IncomingTCPConnectionState::getLogger() const
 {
-  auto logger = dnsdist::logging::getTopLogger()->withName("incoming-tcp-connection")->withValues("client.address", Logging::Loggable(d_proxiedRemote), "frontend.address", Logging::Loggable(d_ci.cs->local), "protocol", Logging::Loggable(d_ci.cs->getProtocol()), "network.peer.address", Logging::Loggable(d_ci.remote), "destination.address", Logging::Loggable(d_proxiedDestination));
+  return dnsdist::logging::getTopLogger()->withName("incoming-tcp-connection")->withValues("client.address", Logging::Loggable(d_proxiedRemote), "frontend.address", Logging::Loggable(d_ci.cs->local), "protocol", Logging::Loggable(d_ci.cs->getProtocol()), "network.peer.address", Logging::Loggable(d_ci.remote), "destination.address", Logging::Loggable(d_proxiedDestination));
 }
 
 static void handleIncomingTCPQuery(int pipefd, FDMultiplexer::funcparam_t& param)
@@ -1519,7 +1540,8 @@ static void handleCrossProtocolQuery(int pipefd, FDMultiplexer::funcparam_t& par
 
     prependSizeToTCPQuery(query.d_buffer, query.d_idstate.d_proxyProtocolPayloadSize);
 
-    vinfolog("Got query for %s|%s from %s (%s, %d bytes), relayed to %s", query.d_idstate.qname.toLogString(), QType(query.d_idstate.qtype).toString(), query.d_idstate.origRemote.toStringWithPort(), query.d_idstate.protocol.toString(), query.d_buffer.size(), downstreamServer->getNameWithAddr());
+    VERBOSESLOG(infolog("Got query for %s|%s from %s (%s, %d bytes), relayed to %s", query.d_idstate.qname.toLogString(), QType(query.d_idstate.qtype).toString(), query.d_idstate.origRemote.toStringWithPort(), query.d_idstate.protocol.toString(), query.d_buffer.size(), downstreamServer->getNameWithAddr()),
+                query.d_idstate.getLogger()->info(Logr::Info, "Relayed query to backend", "dns.query.size", Logging::Loggable(query.d_buffer.size())));
 
     downstream->queueQuery(tqs, std::move(query));
   }
@@ -1580,7 +1602,8 @@ static void scanForTimeouts(const TCPClientThreadData& data, const timeval& now)
     if (cbData.second.type() == typeid(std::shared_ptr<IncomingTCPConnectionState>)) {
       auto state = boost::any_cast<std::shared_ptr<IncomingTCPConnectionState>>(cbData.second);
       if (cbData.first == state->d_handler.getDescriptor()) {
-        vinfolog("Timeout (read) from remote TCP client %s", state->d_ci.remote.toStringWithPort());
+        VERBOSESLOG(infolog("Timeout (read) from remote TCP client %s", state->d_ci.remote.toStringWithPort()),
+                    state->getLogger()->info(Logr::Info, "Timeout (read) from remote TCP client"));
         state->handleTimeout(state, false);
       }
     }
@@ -1588,7 +1611,8 @@ static void scanForTimeouts(const TCPClientThreadData& data, const timeval& now)
     else if (cbData.second.type() == typeid(std::shared_ptr<IncomingHTTP2Connection>)) {
       auto state = boost::any_cast<std::shared_ptr<IncomingHTTP2Connection>>(cbData.second);
       if (cbData.first == state->d_handler.getDescriptor()) {
-        vinfolog("Timeout (read) from remote H2 client %s", state->d_ci.remote.toStringWithPort());
+        VERBOSESLOG(infolog("Timeout (read) from remote H2 client %s", state->d_ci.remote.toStringWithPort()),
+                    state->getLogger()->info(Logr::Info, "Timeout (read) from remote H2 client"));
         std::shared_ptr<IncomingTCPConnectionState> parentState = state;
         state->handleTimeout(parentState, false);
       }
@@ -1596,7 +1620,8 @@ static void scanForTimeouts(const TCPClientThreadData& data, const timeval& now)
 #endif /* HAVE_DNS_OVER_HTTPS && HAVE_NGHTTP2 */
     else if (cbData.second.type() == typeid(std::shared_ptr<TCPConnectionToBackend>)) {
       auto conn = boost::any_cast<std::shared_ptr<TCPConnectionToBackend>>(cbData.second);
-      vinfolog("Timeout (read) from remote backend %s", conn->getBackendName());
+      VERBOSESLOG(infolog("Timeout (read) from remote backend %s", conn->getBackendName()),
+                  conn->getLogger()->info(Logr::Info, "Timeout (read) from remote backend"));
       conn->handleTimeout(now, false);
     }
   }
@@ -1606,7 +1631,8 @@ static void scanForTimeouts(const TCPClientThreadData& data, const timeval& now)
     if (cbData.second.type() == typeid(std::shared_ptr<IncomingTCPConnectionState>)) {
       auto state = boost::any_cast<std::shared_ptr<IncomingTCPConnectionState>>(cbData.second);
       if (cbData.first == state->d_handler.getDescriptor()) {
-        vinfolog("Timeout (write) from remote TCP client %s", state->d_ci.remote.toStringWithPort());
+        VERBOSESLOG(infolog("Timeout (write) from remote TCP client %s", state->d_ci.remote.toStringWithPort()),
+                    state->getLogger()->info(Logr::Info, "Timeout (write) from remote TCP client"));
         state->handleTimeout(state, true);
       }
     }
@@ -1614,7 +1640,8 @@ static void scanForTimeouts(const TCPClientThreadData& data, const timeval& now)
     else if (cbData.second.type() == typeid(std::shared_ptr<IncomingHTTP2Connection>)) {
       auto state = boost::any_cast<std::shared_ptr<IncomingHTTP2Connection>>(cbData.second);
       if (cbData.first == state->d_handler.getDescriptor()) {
-        vinfolog("Timeout (write) from remote H2 client %s", state->d_ci.remote.toStringWithPort());
+        VERBOSESLOG(infolog("Timeout (write) from remote H2 client %s", state->d_ci.remote.toStringWithPort()),
+                    state->getLogger()->info(Logr::Info, "Timeout (write) from remote H2 client"));
         std::shared_ptr<IncomingTCPConnectionState> parentState = state;
         state->handleTimeout(parentState, true);
       }
@@ -1622,7 +1649,8 @@ static void scanForTimeouts(const TCPClientThreadData& data, const timeval& now)
 #endif /* HAVE_DNS_OVER_HTTPS && HAVE_NGHTTP2 */
     else if (cbData.second.type() == typeid(std::shared_ptr<TCPConnectionToBackend>)) {
       auto conn = boost::any_cast<std::shared_ptr<TCPConnectionToBackend>>(cbData.second);
-      vinfolog("Timeout (write) from remote backend %s", conn->getBackendName());
+      VERBOSESLOG(infolog("Timeout (write) from remote backend %s", conn->getBackendName()),
+                  conn->getLogger()->info(Logr::Info, "Timeout (write) from remote backend"));
       conn->handleTimeout(now, true);
     }
   }
@@ -1636,6 +1664,7 @@ static void dumpTCPStates(const TCPClientThreadData& data)
   if (g_tcpStatesDumpRequested > 0) {
     /* no race here, we took the lock so it can only be increased in the meantime */
     --g_tcpStatesDumpRequested;
+    /* no point dumping these in structured format */
     infolog("Dumping the TCP states, as requested:");
     data.mplexer->runForAllWatchedFDs([](bool isRead, int desc, const FDMultiplexer::funcparam_t& param, struct timeval ttd) {
       timeval lnow{};
@@ -1676,6 +1705,7 @@ static void tcpClientThread(pdns::channel::Receiver<ConnectionInfo>&& queryRecei
      from that point on */
 
   setThreadName("dnsdist/tcpClie");
+  auto logger = dnsdist::logging::getTopLogger()->withName("incoming-tcp-worker");
 
   try {
     TCPClientThreadData data;
@@ -1737,12 +1767,14 @@ static void tcpClientThread(pdns::channel::Receiver<ConnectionInfo>&& queryRecei
         }
       }
       catch (const std::exception& e) {
-        warnlog("Error in TCP worker thread: %s", e.what());
+        SLOG(warnlog("Error in TCP worker thread: %s", e.what()),
+             logger->error(Logr::Warning, e.what(), "Error in incoming TCP worker thread"));
       }
     }
   }
   catch (const std::exception& e) {
-    errlog("Fatal error in TCP worker thread: %s", e.what());
+    SLOG(errlog("Fatal error in TCP worker thread: %s", e.what()),
+         logger->error(Logr::Error, e.what(), "Fatal error in incoming TCP worker thread"));
   }
 }
 
@@ -1775,12 +1807,14 @@ static void acceptNewConnection(const TCPAcceptorParam& param, TCPClientThreadDa
 
     if (checkACL && !dnsdist::configuration::getCurrentRuntimeConfiguration().d_ACL.match(remote)) {
       ++dnsdist::metrics::g_stats.aclDrops;
-      vinfolog("Dropped TCP connection from %s because of ACL", remote.toStringWithPort());
+      VERBOSESLOG(infolog("Dropped TCP connection from %s because of ACL", remote.toStringWithPort()),
+                  dnsdist::logging::getTopLogger()->withName("incoming-tcp-worker")->info(Logr::Info, "Dropped TCP connection because of ACL", "frontend.address", Logging::Loggable(param.local), "client.address", Logging::Loggable(remote)));
       return;
     }
 
     if (clientState.d_tcpConcurrentConnectionsLimit > 0 && concurrentConnections > clientState.d_tcpConcurrentConnectionsLimit) {
-      vinfolog("Dropped TCP connection from %s because of concurrent connections limit", remote.toStringWithPort());
+      VERBOSESLOG(infolog("Dropped TCP connection from %s because of concurrent connections limit", remote.toStringWithPort()),
+                  dnsdist::logging::getTopLogger()->withName("incoming-tcp-worker")->info(Logr::Info, "Dropped TCP connection because of concurrent connections limit", "frontend.address", Logging::Loggable(param.local), "client.address", Logging::Loggable(remote)));
       return;
     }
 
@@ -1798,7 +1832,8 @@ static void acceptNewConnection(const TCPAcceptorParam& param, TCPClientThreadDa
 
     const auto maxTCPQueuedConnections = dnsdist::configuration::getImmutableConfiguration().d_maxTCPQueuedConnections;
     if (maxTCPQueuedConnections > 0 && g_tcpclientthreads->getQueuedCount() >= maxTCPQueuedConnections) {
-      vinfolog("Dropping TCP connection from %s because we have too many queued already", remote.toStringWithPort());
+      VERBOSESLOG(infolog("Dropping TCP connection from %s because we have too many queued already", remote.toStringWithPort()),
+                  dnsdist::logging::getTopLogger()->withName("incoming-tcp-worker")->info(Logr::Info, "Dropped TCP connection because we have too many queued already", "frontend.address", Logging::Loggable(param.local), "client.address", Logging::Loggable(remote)));
       return;
     }
 
@@ -1811,7 +1846,8 @@ static void acceptNewConnection(const TCPAcceptorParam& param, TCPClientThreadDa
       connInfo.d_restricted = true;
     }
 
-    vinfolog("Got TCP connection from %s", remote.toStringWithPort());
+    VERBOSESLOG(infolog("Got TCP connection from %s", remote.toStringWithPort()),
+                dnsdist::logging::getTopLogger()->withName("incoming-tcp-worker")->info(Logr::Info, "Accepted new TCP connection", "frontend.address", Logging::Loggable(param.local), "client.address", Logging::Loggable(remote)));
 
     connInfo.remote = remote;
 
@@ -1839,7 +1875,8 @@ static void acceptNewConnection(const TCPAcceptorParam& param, TCPClientThreadDa
     }
   }
   catch (const std::exception& e) {
-    errlog("While reading a TCP question: %s", e.what());
+    SLOG(errlog("While reading a TCP question: %s", e.what()),
+         dnsdist::logging::getTopLogger()->withName("incoming-tcp-worker")->error(Logr::Error, e.what(), "Error while accepting a TCP connection", "frontend.address", Logging::Loggable(param.local)));
     if (tcpClientCountIncremented) {
       dnsdist::IncomingConcurrentTCPConnectionsManager::accountClosedTCPConnection(remote);
     }

diff --git a/pdns/dnsdistdist/dnsdist.hh b/pdns/dnsdistdist/dnsdist.hh
index 44ab85460463cebd2f7bced6c613496c80297d69..e4483af0e22fc9519ca36a6bbf5f6c2202ef941a 100644 (file)
--- a/pdns/dnsdistdist/dnsdist.hh
+++ b/pdns/dnsdistdist/dnsdist.hh
@@ -169,11 +169,11 @@ struct DNSQuestion
     return ids.cs;
   }
 
-  std::shared_ptr<const Logr::Logger> getLogger() const;
-  std::shared_ptr<const Logr::Logger> getLogger();
+  std::shared_ptr<const Logr::Logger> getLogger(std::shared_ptr<const Logr::Logger> parent = nullptr) const;
+  std::shared_ptr<const Logr::Logger> getLogger(std::shared_ptr<const Logr::Logger> parent = nullptr);
 
 protected:
-  virtual std::shared_ptr<const Logr::Logger> getThisLogger() const;
+  virtual std::shared_ptr<const Logr::Logger> getThisLogger(std::shared_ptr<const Logr::Logger> parent) const;
 
   PacketBuffer& data;
   std::shared_ptr<const Logr::Logger> d_logger;
@@ -206,7 +206,7 @@ struct DNSResponse : DNSQuestion
   const std::shared_ptr<DownstreamState>& d_downstream;
 
 protected:
-  std::shared_ptr<const Logr::Logger> getThisLogger() const override;
+  std::shared_ptr<const Logr::Logger> getThisLogger(std::shared_ptr<const Logr::Logger> parent) const override;
 };
 
 using pdns::stat_t;