From: Remi Gacogne Date: Tue, 9 Dec 2025 16:17:07 +0000 (+0100) Subject: dnsdist: More structured logging conversions X-Git-Tag: rec-5.4.0-beta1~33^2~41 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=9f8419f9216df15c74467e6b5c6ddee1fea15014;p=thirdparty%2Fpdns.git dnsdist: More structured logging conversions Signed-off-by: Remi Gacogne --- diff --git a/pdns/dnsdistdist/Makefile.am b/pdns/dnsdistdist/Makefile.am index eb615dc02e..b58b4fb9d3 100644 --- a/pdns/dnsdistdist/Makefile.am +++ b/pdns/dnsdistdist/Makefile.am @@ -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 \ diff --git a/pdns/dnsdistdist/dnsdist-actions-factory.cc b/pdns/dnsdistdist/dnsdist-actions-factory.cc index 7807547370..290b29021c 100644 --- a/pdns/dnsdistdist/dnsdist-actions-factory.cc +++ b/pdns/dnsdistdist/dnsdist-actions-factory.cc @@ -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(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(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(dnsquestion->getQueryRealTime().tv_sec), static_cast(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(dnsquestion->getQueryRealTime().tv_sec), static_cast(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(response->getQueryRealTime().tv_sec), static_cast(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(response->getQueryRealTime().tv_sec), static_cast(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; } diff --git a/pdns/dnsdistdist/dnsdist-async.cc b/pdns/dnsdistdist/dnsdist-async.cc index 194077cdf7..65241b5f99 100644 --- a/pdns/dnsdistdist/dnsdist-async.cc +++ b/pdns/dnsdistdist/dnsdist-async.cc @@ -135,7 +135,8 @@ void AsynchronousHolder::mainThread(std::shared_ptr 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) } } 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 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&& 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&& 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((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((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; diff --git a/pdns/dnsdistdist/dnsdist-backend.cc b/pdns/dnsdistdist/dnsdist-backend.cc index a755f5be41..48ce881ec8 100644 --- a/pdns/dnsdistdist/dnsdist-backend.cc +++ b/pdns/dnsdistdist/dnsdist-backend.cc @@ -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 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 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 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>& 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 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; diff --git a/pdns/dnsdistdist/dnsdist-dnsquestion.cc b/pdns/dnsdistdist/dnsdist-dnsquestion.cc index 5b6d2a050a..d91b3fe6b7 100644 --- a/pdns/dnsdistdist/dnsdist-dnsquestion.cc +++ b/pdns/dnsdistdist/dnsdist-dnsquestion.cc @@ -66,7 +66,25 @@ std::shared_ptr 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 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; } diff --git a/pdns/dnsdistdist/dnsdist-doh-common.hh b/pdns/dnsdistdist/dnsdist-doh-common.hh index 48d29a46b9..a3f2bb7067 100644 --- a/pdns/dnsdistdist/dnsdist-doh-common.hh +++ b/pdns/dnsdistdist/dnsdist-doh-common.hh @@ -27,6 +27,7 @@ #include #include "config.h" +#include "dolog.hh" #include "iputils.hh" #include "libssl.hh" #include "noinitvector.hh" @@ -99,6 +100,7 @@ struct DOHFrontend std::shared_ptr d_dsc{nullptr}; std::shared_ptr>> d_responsesMap; std::shared_ptr d_tlsContext; + std::shared_ptr d_logger; std::string d_serverTokens{"dnsdist"}; std::unordered_map 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() { diff --git a/pdns/dnsdistdist/dnsdist-lua-web.cc b/pdns/dnsdistdist/dnsdist-lua-web.cc index 7dbd515042..d3f476cefb 100644 --- a/pdns/dnsdistdist/dnsdist-lua-web.cc +++ b/pdns/dnsdistdist/dnsdist-lua-web.cc @@ -27,7 +27,7 @@ namespace dnsdist::webserver { -void registerWebHandler(const std::string& endpoint, std::function handler, bool isLua); +void registerWebHandler(const std::string& endpoint, std::function 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 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("path", [](const YaHTTP::Request& req) -> std::string { return req.url.path; }, [](YaHTTP::Request& req, const std::string& path) { (void)req; (void) path; }); diff --git a/pdns/dnsdistdist/dnsdist-web.cc b/pdns/dnsdistdist/dnsdist-web.cc index 836d3d3f23..9eb6fc1c6e 100644 --- a/pdns/dnsdistdist/dnsdist-web.cc +++ b/pdns/dnsdistdist/dnsdist-web.cc @@ -25,6 +25,7 @@ #include #include #include +#include #include "ext/json11/json11.hpp" #include @@ -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 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(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(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; -struct WebHandlerContext -{ - WebHandler d_handler; - bool d_isLua{false}; -}; +using BuiltinWebHandler = std::function; +using LuaWebHandler = std::function; +using WebHandler = std::variant; + +static SharedLockGuarded> s_webHandlers; -static SharedLockGuarded> 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 = "

Unauthorized

"; @@ -1911,22 +1945,22 @@ static void connectionThread(WebClientConnection&& conn) resp.status = 405; } else { - std::optional handlerCtx{std::nullopt}; + std::optional 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(&*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(&*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")); } } } diff --git a/pdns/dnsdistdist/dnsdist-xsk.cc b/pdns/dnsdistdist/dnsdist-xsk.cc index 325b1353ec..cbe41dd706 100644 --- a/pdns/dnsdistdist/dnsdist-xsk.cc +++ b/pdns/dnsdistdist/dnsdist-xsk.cc @@ -39,6 +39,8 @@ void XskResponderThread(std::shared_ptr dss, std::shared_ptrwithName("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 dss, std::shared_ptrmarkAsFree(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 dss, std::shared_ptrerror(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 xsk) { setThreadName("dnsdist/XskRouter"); + auto logger = dnsdist::logging::getTopLogger()->withName("xsk-router"); + uint32_t failed = 0; // packets to be submitted for sending vector fillInTx; @@ -188,7 +199,8 @@ void XskRouter(std::shared_ptr 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")); } } } diff --git a/pdns/dnsdistdist/dnsdist.cc b/pdns/dnsdistdist/dnsdist.cc index 9f6c37e1c1..61542d92d9 100644 --- a/pdns/dnsdistdist/dnsdist.cc +++ b/pdns/dnsdistdist/dnsdist.cc @@ -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 getUDPCrossProtocolQueryFromDQ(DNSQuestion& ProcessQueryResult processQuery(DNSQuestion& dnsQuestion, std::shared_ptr& 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(maxTCPClientThreads, std::vector()); #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))); } } } diff --git a/pdns/dnsdistdist/dnsdist.hh b/pdns/dnsdistdist/dnsdist.hh index 058ed174e7..44ab854604 100644 --- a/pdns/dnsdistdist/dnsdist.hh +++ b/pdns/dnsdistdist/dnsdist.hh @@ -173,7 +173,7 @@ struct DNSQuestion std::shared_ptr getLogger(); protected: - std::shared_ptr getThisLogger() const; + virtual std::shared_ptr getThisLogger() const; PacketBuffer& data; std::shared_ptr d_logger; @@ -204,6 +204,9 @@ struct DNSResponse : DNSQuestion DNSResponse(DNSResponse&&) = default; const std::shared_ptr& d_downstream; + +protected: + std::shared_ptr getThisLogger() const override; }; using pdns::stat_t; @@ -944,6 +947,8 @@ public: } unsigned int getQPSLimit() const; + + [[nodiscard]] std::shared_ptr getLogger() const; }; void responderThread(std::shared_ptr dss); diff --git a/pdns/dnsdistdist/doh3.cc b/pdns/dnsdistdist/doh3.cc index 27fb691f55..bdc544d687 100644 --- a/pdns/dnsdistdist/doh3.cc +++ b/pdns/dnsdistdist/doh3.cc @@ -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& receiver) +static void flushResponses(pdns::channel::Receiver& receiver, const Logr::Logger& frontendLogger) { for (;;) { try { @@ -688,10 +696,12 @@ static void flushResponses(pdns::channel::Receiver& 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& 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")); } } } diff --git a/pdns/dnsdistdist/doh3.hh b/pdns/dnsdistdist/doh3.hh index 14850fcc70..2fa07a9af1 100644 --- a/pdns/dnsdistdist/doh3.hh +++ b/pdns/dnsdistdist/doh3.hh @@ -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 d_logger{nullptr}; std::unique_ptr d_server_config; ComboAddress d_local; diff --git a/pdns/dnsdistdist/doq-common.cc b/pdns/dnsdistdist/doq-common.cc index ebe43d61af..43a3faa034 100644 --- a/pdns/dnsdistdist/doq-common.cc +++ b/pdns/dnsdistdist/doq-common.cc @@ -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 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(&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))); } } diff --git a/pdns/dnsdistdist/doq.cc b/pdns/dnsdistdist/doq.cc index f197b6a136..ba46f52d9e 100644 --- a/pdns/dnsdistdist/doq.cc +++ b/pdns/dnsdistdist/doq.cc @@ -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& receiver) +static void flushResponses(pdns::channel::Receiver& receiver, const Logr::Logger& frontendLogger) { for (;;) { try { @@ -588,10 +596,12 @@ static void flushResponses(pdns::channel::Receiver& 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& 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")); } } } diff --git a/pdns/dnsdistdist/doq.hh b/pdns/dnsdistdist/doq.hh index 66b64953df..1e80e6d8e5 100644 --- a/pdns/dnsdistdist/doq.hh +++ b/pdns/dnsdistdist/doq.hh @@ -24,20 +24,20 @@ #include #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 d_logger{nullptr}; std::unique_ptr d_server_config; dnsdist::doq::QuicheParams d_quicheParams; ComboAddress d_local; diff --git a/pdns/dnsdistdist/test-dnsdistnghttp2-in_cc.cc b/pdns/dnsdistdist/test-dnsdistnghttp2-in_cc.cc index c1b892e55e..82b18ed325 100644 --- a/pdns/dnsdistdist/test-dnsdistnghttp2-in_cc.cc +++ b/pdns/dnsdistdist/test-dnsdistnghttp2-in_cc.cc @@ -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; } }