From: Remi Gacogne Date: Fri, 18 Aug 2023 12:51:53 +0000 (+0200) Subject: dnsdist: Add a structured log-like logging option X-Git-Tag: rec-5.0.0-rc1~20^2~3 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=86e28d2d3113511b8d8838bf5cc54e186065454f;p=thirdparty%2Fpdns.git dnsdist: Add a structured log-like logging option --- diff --git a/.not-formatted b/.not-formatted index 1d1912ccd3..c711068a57 100644 --- a/.not-formatted +++ b/.not-formatted @@ -131,7 +131,6 @@ ./pdns/dnswriter.cc ./pdns/dnswriter.hh ./pdns/doh.hh -./pdns/dolog.hh ./pdns/dumresp.cc ./pdns/dynhandler.cc ./pdns/dynhandler.hh diff --git a/pdns/dnsdist-console.cc b/pdns/dnsdist-console.cc index 437c6493d4..b3c2443456 100644 --- a/pdns/dnsdist-console.cc +++ b/pdns/dnsdist-console.cc @@ -726,6 +726,7 @@ const std::vector g_consoleKeywords{ { "setServerPolicyLuaFFIPerThread", true, "name, code", "set server selection policy to one named 'name' and returned by the Lua FFI code passed in 'code'" }, { "setServFailWhenNoServer", true, "bool", "if set, return a ServFail when no servers are available, instead of the default behaviour of dropping the query" }, { "setStaleCacheEntriesTTL", true, "n", "allows using cache entries expired for at most n seconds when there is no backend available to answer for a query" }, + { "setStructuredLogging", true, "value [, options]", "set whether log messages should be in structured-logging-like format" }, { "setSyslogFacility", true, "facility", "set the syslog logging facility to 'facility'. Defaults to LOG_DAEMON" }, { "setTCPDownstreamCleanupInterval", true, "interval", "minimum interval in seconds between two cleanups of the idle TCP downstream connections" }, { "setTCPFastOpenKey", true, "string", "TCP Fast Open Key" }, diff --git a/pdns/dnsdist-lua.cc b/pdns/dnsdist-lua.cc index 396ba3e9d9..e8d28dafec 100644 --- a/pdns/dnsdist-lua.cc +++ b/pdns/dnsdist-lua.cc @@ -1782,12 +1782,33 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck) } try { auto stream = std::ofstream(dest.c_str()); - g_verboseStream = std::move(stream); + dnsdist::logging::LoggingConfiguration::setVerboseStream(std::move(stream)); } catch (const std::exception& e) { errlog("Error while opening the verbose logging destination file %s: %s", dest, e.what()); } }); + luaCtx.writeFunction("setStructuredLogging", [](bool enable, boost::optional> options) { + std::string levelPrefix; + std::string timeFormat; + if (options) { + getOptionalValue(options, "levelPrefix", levelPrefix); + if (getOptionalValue(options, "timeFormat", timeFormat) == 1) { + if (timeFormat == "numeric") { + dnsdist::logging::LoggingConfiguration::setStructuredTimeFormat(dnsdist::logging::LoggingConfiguration::TimeFormat::Numeric); + } + else if (timeFormat == "ISO8601") { + dnsdist::logging::LoggingConfiguration::setStructuredTimeFormat(dnsdist::logging::LoggingConfiguration::TimeFormat::ISO8601); + } + else { + warnlog("Unknown value '%s' to setStructuredLogging's 'timeFormat' parameter", timeFormat); + } + } + checkAllParametersConsumed("setStructuredLogging", options); + } + + dnsdist::logging::LoggingConfiguration::setStructuredLogging(enable, levelPrefix); + }); luaCtx.writeFunction("setStaleCacheEntriesTTL", [](uint64_t ttl) { checkParameterBound("setStaleCacheEntriesTTL", ttl, std::numeric_limits::max()); diff --git a/pdns/dnsdist.cc b/pdns/dnsdist.cc index a5c1d88735..58d1ca0b2c 100644 --- a/pdns/dnsdist.cc +++ b/pdns/dnsdist.cc @@ -98,12 +98,9 @@ using std::thread; bool g_verbose; -std::optional g_verboseStream{std::nullopt}; uint16_t g_maxOutstanding{std::numeric_limits::max()}; uint32_t g_staleCacheEntriesTTL{0}; -bool g_syslog{true}; -bool g_logtimestamps{false}; bool g_allowEmptyResponse{false}; GlobalStateHolder g_ACL; @@ -2530,7 +2527,7 @@ static void sigTermHandler(int) we crash trying to exit, but let's try to avoid the warnings in our tests. */ - if (g_syslog) { + if (dnsdist::logging::LoggingConfiguration::getSyslog()) { syslog(LOG_INFO, "Exiting on user request"); } std::cout<<"Exiting on user request"< +#include + +#include "dolog.hh" + +namespace dnsdist::logging +{ +std::optional LoggingConfiguration::s_verboseStream{std::nullopt}; +std::string LoggingConfiguration::s_structuredLevelPrefix{"prio"}; +LoggingConfiguration::TimeFormat LoggingConfiguration::s_structuredTimeFormat{LoggingConfiguration::TimeFormat::Numeric}; +bool LoggingConfiguration::s_structuredLogging{false}; +bool LoggingConfiguration::s_logTimestamps{false}; +bool LoggingConfiguration::s_syslog{false}; + +namespace +{ + const char* getTimeFormat() + { + if (!dnsdist::logging::LoggingConfiguration::getStructuredLogging()) { + return "%b %d %H:%M:%S "; + } + + auto format = dnsdist::logging::LoggingConfiguration::getStructuredLoggingTimeFormat(); + if (format == dnsdist::logging::LoggingConfiguration::TimeFormat::ISO8601) { + return "%FT%H:%M:%S%z"; + } + return nullptr; + } +} + +void logTime(std::ostream& stream) +{ + std::array buffer{""}; + + if (LoggingConfiguration::getStructuredLogging() && LoggingConfiguration::getStructuredLoggingTimeFormat() == LoggingConfiguration::TimeFormat::Numeric) { + struct timeval now + { + }; + gettimeofday(&now, nullptr); + snprintf(buffer.data(), buffer.size(), "%lld.%03ld", static_cast(now.tv_sec), now.tv_usec / 1000); + } + else { + const auto* timeFormat = getTimeFormat(); + if (timeFormat == nullptr) { + return; + } + + time_t now{0}; + time(&now); + struct tm localNow + { + }; + localtime_r(&now, &localNow); + + { + // strftime is not thread safe, it can access locale information + static std::mutex mutex; + auto lock = std::lock_guard(mutex); + + if (strftime(buffer.data(), buffer.size(), timeFormat, &localNow) == 0) { + buffer[0] = '\0'; + } + } + } + + if (dnsdist::logging::LoggingConfiguration::getStructuredLogging()) { + stream << "tm=\"" << buffer.data() << "\" "; + } + else { + stream << buffer.data(); + } +} + +} diff --git a/pdns/dnsdistdist/test-dnsdistlbpolicies_cc.cc b/pdns/dnsdistdist/test-dnsdistlbpolicies_cc.cc index 9d437578f7..09e95df1f1 100644 --- a/pdns/dnsdistdist/test-dnsdistlbpolicies_cc.cc +++ b/pdns/dnsdistdist/test-dnsdistlbpolicies_cc.cc @@ -20,8 +20,6 @@ DNSDistSNMPAgent* g_snmpAgent{nullptr}; #if BENCH_POLICIES bool g_verbose{true}; -bool g_syslog{true}; -bool g_logtimestamps{false}; #include "dnsdist-rings.hh" Rings g_rings; GlobalStateHolder> g_dynblockNMG; diff --git a/pdns/dolog.hh b/pdns/dolog.hh index bd32207806..17af3a07b8 100644 --- a/pdns/dolog.hh +++ b/pdns/dolog.hh @@ -22,6 +22,7 @@ #pragma once #include #include +#include #include #include #include @@ -32,13 +33,12 @@ #include "logger.hh" #endif // RECURSOR - /* This file is intended not to be metronome specific, and is simple example of C++2011 variadic templates in action. - The goal is rapid easy to use logging to console & syslog. + The goal is rapid easy to use logging to console & syslog. - Usage: + Usage: string address="localhost"; vinfolog("Got TCP connection from %s", remote); infolog("Bound to %s port %d", address, port); @@ -51,13 +51,13 @@ This will happily print a string to %d! Doesn't do further format processing. */ -template +template inline void dolog(O& outputStream, const char* str) { outputStream << str; } -template +template void dolog(O& outputStream, const char* formatStr, T value, const Args&... args) { while (*formatStr) { @@ -65,14 +65,14 @@ void dolog(O& outputStream, const char* formatStr, T value, const Args&... args) // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic) if (*(formatStr + 1) == '%') { // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic) - ++formatStr; + ++formatStr; } else { - outputStream << value; + outputStream << value; // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic) - formatStr += 2; - dolog(outputStream, formatStr, args...); - return; + formatStr += 2; + dolog(outputStream, formatStr, args...); + return; } } // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic) @@ -81,108 +81,203 @@ void dolog(O& outputStream, const char* formatStr, T value, const Args&... args) } #if !defined(RECURSOR) -//NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables) +// NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables) extern bool g_verbose; -//NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables) -extern bool g_syslog; + #ifdef DNSDIST -//NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables) -extern bool g_logtimestamps; -//NOLINTNEXTLINE(cppcoreguidelines-avoid-non-const-global-variables) -extern std::optional g_verboseStream; +namespace dnsdist::logging +{ +class LoggingConfiguration +{ +public: + enum class TimeFormat + { + Numeric, + ISO8601 + }; + + static void setVerbose(bool value = true) + { + g_verbose = value; + } + static void setSyslog(bool value = true) + { + s_syslog = value; + } + static void setStructuredLogging(bool value = true, std::string levelPrefix = "") + { + s_structuredLogging = value; + if (value) { + s_structuredLevelPrefix = levelPrefix.empty() ? "prio" : std::move(levelPrefix); + } + } + static void setLogTimestamps(bool value = true) + { + s_logTimestamps = value; + } + static void setStructuredTimeFormat(TimeFormat format) + { + s_structuredTimeFormat = format; + } + static void setVerboseStream(std::ofstream&& stream) + { + s_verboseStream = std::move(stream); + } + static bool getVerbose() + { + return g_verbose; + } + static bool getSyslog() + { + return s_syslog; + } + static bool getLogTimestamps() + { + return s_logTimestamps; + } + static std::optional& getVerboseStream() + { + return s_verboseStream; + } + static bool getStructuredLogging() + { + return s_structuredLogging; + } + static const std::string& getStructuredLoggingLevelPrefix() + { + return s_structuredLevelPrefix; + } + + static TimeFormat getStructuredLoggingTimeFormat() + { + return s_structuredTimeFormat; + } + +private: + static std::optional s_verboseStream; + static std::string s_structuredLevelPrefix; + static TimeFormat s_structuredTimeFormat; + static bool s_structuredLogging; + static bool s_logTimestamps; + static bool s_syslog; +}; + +extern void logTime(std::ostream& stream); +} #endif inline void setSyslogFacility(int facility) { /* we always call openlog() right away at startup */ closelog(); - openlog("dnsdist", LOG_PID|LOG_NDELAY, facility); + openlog("dnsdist", LOG_PID | LOG_NDELAY, facility); +} + +namespace +{ +inline const char* syslogLevelToStr(int level) +{ + static constexpr std::array levelStrs{ + "emergency", + "alert", + "critical", + "error", + "warning", + "notice", + "info", + "debug"}; + return levelStrs.at(level); +} } -template -void genlog(std::ostream& stream, int level, bool doSyslog, const char* formatStr, const Args&... args) +template +void genlog(std::ostream& stream, [[maybe_unused]] int level, [[maybe_unused]] bool skipSyslog, const char* formatStr, const Args&... args) { std::ostringstream str; dolog(str, formatStr, args...); auto output = str.str(); - if (doSyslog) { +#ifdef DNSDIST + if (!skipSyslog && dnsdist::logging::LoggingConfiguration::getSyslog()) { // NOLINTNEXTLINE(cppcoreguidelines-pro-type-vararg): syslog is what it is syslog(level, "%s", output.c_str()); } -#ifdef DNSDIST - if (g_logtimestamps) { - std::array buffer{""}; - time_t now{0}; - time(&now); - struct tm localNow{}; - localtime_r(&now, &localNow); - if (strftime(buffer.data(), buffer.size(), "%b %d %H:%M:%S ", &localNow) == 0) { - buffer[0] = '\0'; - } - stream << buffer.data(); + if (dnsdist::logging::LoggingConfiguration::getLogTimestamps()) { + dnsdist::logging::logTime(stream); } -#endif + if (dnsdist::logging::LoggingConfiguration::getStructuredLogging()) { + stream << dnsdist::logging::LoggingConfiguration::getStructuredLoggingLevelPrefix() << "=\"" << syslogLevelToStr(level) << "\" "; + stream << "msg=" << std::quoted(output) << std::endl; + } + else { + stream << output << std::endl; + } +#else stream << output << std::endl; +#endif } -template +template void verboselog(const char* formatStr, const Args&... args) { #ifdef DNSDIST - if (g_verboseStream) { - genlog(*g_verboseStream, LOG_DEBUG, false, formatStr, args...); + if (auto& stream = dnsdist::logging::LoggingConfiguration::getVerboseStream()) { + genlog(*stream, LOG_DEBUG, true, formatStr, args...); } else { #endif /* DNSDIST */ - genlog(std::cout, LOG_DEBUG, g_syslog, formatStr, args...); + genlog(std::cout, LOG_DEBUG, false, formatStr, args...); #ifdef DNSDIST } #endif /* DNSDIST */ } -#define vinfolog if (g_verbose) verboselog +#define vinfolog \ + if (g_verbose) \ + verboselog -template +template void infolog(const char* formatStr, const Args&... args) { - genlog(std::cout, LOG_INFO, g_syslog, formatStr, args...); + genlog(std::cout, LOG_INFO, false, formatStr, args...); } -template +template void warnlog(const char* formatStr, const Args&... args) { - genlog(std::cout, LOG_WARNING, g_syslog, formatStr, args...); + genlog(std::cout, LOG_WARNING, false, formatStr, args...); } -template +template void errlog(const char* formatStr, const Args&... args) { - genlog(std::cout, LOG_ERR, g_syslog, formatStr, args...); + genlog(std::cout, LOG_ERR, false, formatStr, args...); } #else // RECURSOR #define g_verbose 0 -#define vinfolog if(g_verbose)infolog +#define vinfolog \ + if (g_verbose) \ + infolog -template +template void infolog(const char* formatStr, const Args&... args) { g_log << Logger::Info; dolog(g_log, formatStr, args...); } -template +template void warnlog(const char* formatStr, const Args&... args) { g_log << Logger::Warning; dolog(g_log, formatStr, args...); } -template +template void errlog(const char* formatStr, const Args&... args) { g_log << Logger::Error; diff --git a/pdns/recursordist/lwres.cc b/pdns/recursordist/lwres.cc index 5b255b2980..3561d11cfd 100644 --- a/pdns/recursordist/lwres.cc +++ b/pdns/recursordist/lwres.cc @@ -94,8 +94,6 @@ void remoteLoggerQueueData(RemoteLoggerInterface& r, const std::string& data) #include "dnstap.hh" #include "fstrm_logger.hh" -bool g_syslog; - static bool isEnabledForQueries(const std::shared_ptr>>& fstreamLoggers) { if (fstreamLoggers == nullptr) { diff --git a/pdns/sdig.cc b/pdns/sdig.cc index 60d14b6bfe..e48e1f95bc 100644 --- a/pdns/sdig.cc +++ b/pdns/sdig.cc @@ -23,7 +23,6 @@ StatBag S; // Vars below used by tcpiohandler.cc bool g_verbose = true; -bool g_syslog = false; static bool hidettl = false; diff --git a/pdns/test-dnscrypt_cc.cc b/pdns/test-dnscrypt_cc.cc index f19010c738..239c560c45 100644 --- a/pdns/test-dnscrypt_cc.cc +++ b/pdns/test-dnscrypt_cc.cc @@ -32,9 +32,6 @@ #include bool g_verbose{false}; -bool g_syslog{true}; -bool g_logtimestamps{false}; -std::optional g_verboseStream{std::nullopt}; BOOST_AUTO_TEST_SUITE(test_dnscrypt_cc)