From: Otto Moerbeek Date: Wed, 18 May 2022 14:32:10 +0000 (+0200) Subject: Some more conversions to structured logging X-Git-Tag: auth-4.8.0-alpha0~95^2~4 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=e4565646e748ef49cd150f1f649bb370dadec450;p=thirdparty%2Fpdns.git Some more conversions to structured logging --- diff --git a/pdns/logging.hh b/pdns/logging.hh index d8ff96a2d7..75a7ac48b7 100644 --- a/pdns/logging.hh +++ b/pdns/logging.hh @@ -73,6 +73,8 @@ template <> std::string Loggable::to_string() const; template <> std::string Loggable>::to_string() const; +template <> +std::string Loggable>::to_string() const; // Loggable::Loggable(const std::string& v): _t(v) {} diff --git a/pdns/recursordist/logging.cc b/pdns/recursordist/logging.cc index f6083df59c..6ac2bcc4dc 100644 --- a/pdns/recursordist/logging.cc +++ b/pdns/recursordist/logging.cc @@ -143,6 +143,23 @@ std::string Loggable>::to_string() const return oss.str(); } +template <> +std::string Loggable>::to_string() const +{ + std::ostringstream oss; + bool first = true; + for (const auto& e : _t) { + if (!first) { + oss << ' '; + } + else { + first = false; + } + oss << e; + } + return oss.str(); +} + std::shared_ptr Logger::withName(const std::string& name) const { std::shared_ptr res; diff --git a/pdns/recursordist/rec-main.cc b/pdns/recursordist/rec-main.cc index 9adb6a4afc..06e4c86a01 100644 --- a/pdns/recursordist/rec-main.cc +++ b/pdns/recursordist/rec-main.cc @@ -111,14 +111,15 @@ unsigned int RecThreadInfo::s_numDistributorThreads; unsigned int RecThreadInfo::s_numWorkerThreads; thread_local unsigned int RecThreadInfo::t_id; -static std::map> parseCPUMap() +static std::map> parseCPUMap(std::shared_ptr& log) { std::map> result; const std::string value = ::arg()["cpu-map"]; if (!value.empty() && !isSettingThreadCPUAffinitySupported()) { - g_log << Logger::Warning << "CPU mapping requested but not supported, skipping" << endl; + SLOG(g_log << Logger::Warning << "CPU mapping requested but not supported, skipping" << endl, + log->info(Logr::Warning, "CPU mapping requested but not supported, skipping")); return result; } @@ -147,14 +148,15 @@ static std::map> parseCPUMap() } } catch (const std::exception& e) { - g_log << Logger::Error << "Error parsing cpu-map entry '" << part << "': " << e.what() << endl; + SLOG(g_log << Logger::Error << "Error parsing cpu-map entry '" << part << "': " << e.what() << endl, + log->error(Logr::Error, e.what(), "Error parsing cpu-map entry", "entry", Logging::Loggable(part))); } } return result; } -static void setCPUMap(const std::map>& cpusMap, unsigned int n, pthread_t tid) +static void setCPUMap(const std::map>& cpusMap, unsigned int n, pthread_t tid, std::shared_ptr& log) { const auto& cpuMapping = cpusMap.find(n); if (cpuMapping == cpusMap.cend()) { @@ -162,24 +164,34 @@ static void setCPUMap(const std::map>& cpusMap, unsi } int rc = mapThreadToCPUList(tid, cpuMapping->second); if (rc == 0) { - g_log << Logger::Info << "CPU affinity for thread " << n << " has been set to CPU map:"; - for (const auto cpu : cpuMapping->second) { - g_log << Logger::Info << " " << cpu; + if (!g_slogStructured) { + g_log << Logger::Info << "CPU affinity for thread " << n << " has been set to CPU map:"; + for (const auto cpu : cpuMapping->second) { + g_log << Logger::Info << " " << cpu; + } + g_log << Logger::Info << endl; + } + else { + log->info(Logr::Info, "CPU affinity has been set", "thread", Logging::Loggable(n), "cpumap", Logging::Loggable(cpuMapping->second)); } - g_log << Logger::Info << endl; } else { - g_log << Logger::Warning << "Error setting CPU affinity for thread " << n << " to CPU map:"; - for (const auto cpu : cpuMapping->second) { - g_log << Logger::Info << " " << cpu; + if (!g_slogStructured) { + g_log << Logger::Warning << "Error setting CPU affinity for thread " << n << " to CPU map:"; + for (const auto cpu : cpuMapping->second) { + g_log << Logger::Info << " " << cpu; + } + g_log << Logger::Info << ' ' << strerror(rc) << endl; + } + else { + log->info(Logr::Warning, "Error setting CPU affinity", "thread", Logging::Loggable(n), "cpumap", Logging::Loggable(cpuMapping->second)); } - g_log << Logger::Info << ' ' << strerror(rc) << endl; } } static void recursorThread(); -void RecThreadInfo::start(unsigned int id, const string& tname, const std::map>& cpusMap) +void RecThreadInfo::start(unsigned int id, const string& tname, const std::map>& cpusMap, std::shared_ptr& log) { name = tname; thread = std::thread([id, tname] { @@ -188,14 +200,14 @@ void RecThreadInfo::start(unsigned int id, const string& tname, const std::map& log) { int ret = EXIT_SUCCESS; unsigned int currentThreadId = 1; - const auto cpusMap = parseCPUMap(); + const auto cpusMap = parseCPUMap(log); if (RecThreadInfo::numDistributors() + RecThreadInfo::numWorkers() == 1) { SLOG(g_log << Logger::Warning << "Operating with single distributor/worker thread" << endl, @@ -204,10 +216,10 @@ int RecThreadInfo::runThreads(std::shared_ptr& log) /* This thread handles the web server, carbon, statistics and the control channel */ auto& handlerInfo = RecThreadInfo::info(0); handlerInfo.setHandler(); - handlerInfo.start(0, "web+stat", cpusMap); + handlerInfo.start(0, "web+stat", cpusMap, log); auto& taskInfo = RecThreadInfo::info(2); taskInfo.setTaskThread(); - taskInfo.start(2, "taskThread", cpusMap); + taskInfo.start(2, "taskThread", cpusMap, log); auto& info = RecThreadInfo::info(currentThreadId); info.setListener(); @@ -248,7 +260,7 @@ int RecThreadInfo::runThreads(std::shared_ptr& log) log->info(Logr::Notice, "Launching distributor threads", "count", Logging::Loggable(RecThreadInfo::numDistributors()))); for (unsigned int n = 0; n < RecThreadInfo::numDistributors(); ++n) { auto& info = RecThreadInfo::info(currentThreadId); - info.start(currentThreadId++, "distr", cpusMap); + info.start(currentThreadId++, "distr", cpusMap, log); } } SLOG(g_log << Logger::Warning << "Launching " << RecThreadInfo::numWorkers() << " worker threads" << endl, @@ -256,18 +268,18 @@ int RecThreadInfo::runThreads(std::shared_ptr& log) for (unsigned int n = 0; n < RecThreadInfo::numWorkers(); ++n) { auto& info = RecThreadInfo::info(currentThreadId); - info.start(currentThreadId++, "worker", cpusMap); + info.start(currentThreadId++, "worker", cpusMap, log); } for (unsigned int n = 0; n < RecThreadInfo::numTaskThreads(); ++n) { auto& info = RecThreadInfo::info(currentThreadId); - info.start(currentThreadId++, "taskThread", cpusMap); + info.start(currentThreadId++, "taskThread", cpusMap, log); } /* This thread handles the web server, carbon, statistics and the control channel */ auto& info = RecThreadInfo::info(0); info.setHandler(); - info.start(0, "web+stat", cpusMap); + info.start(0, "web+stat", cpusMap, log); for (auto& ti : RecThreadInfo::infos()) { ti.thread.join(); @@ -279,11 +291,12 @@ int RecThreadInfo::runThreads(std::shared_ptr& log) return ret; } -void RecThreadInfo::makeThreadPipes() +void RecThreadInfo::makeThreadPipes(std::shared_ptr& log) { auto pipeBufferSize = ::arg().asNum("distribution-pipe-buffer-size"); if (pipeBufferSize > 0) { - g_log << Logger::Info << "Resizing the buffer of the distribution pipe to " << pipeBufferSize << endl; + SLOG(g_log << Logger::Info << "Resizing the buffer of the distribution pipe to " << pipeBufferSize << endl, + log->info(Logr::Info, "Resizing the buffer of the distribution pipe", "size", Logging::Loggable(pipeBufferSize))); } /* thread 0 is the handler / SNMP, worker threads start at 1 */ @@ -317,10 +330,12 @@ void RecThreadInfo::makeThreadPipes() if (pipeBufferSize > 0) { if (!setPipeBufferSize(threadInfo.pipes.writeQueriesToThread, pipeBufferSize)) { int err = errno; - g_log << Logger::Warning << "Error resizing the buffer of the distribution pipe for thread " << n << " to " << pipeBufferSize << ": " << strerror(err) << endl; + SLOG(g_log << Logger::Warning << "Error resizing the buffer of the distribution pipe for thread " << n << " to " << pipeBufferSize << ": " << strerror(err) << endl, + log->error(Logr::Warning, err, "Error resizing the buffer of the distribution pipe for thread", "thread", Logging::Loggable(n), "size", Logging::Loggable(pipeBufferSize))); auto existingSize = getPipeBufferSize(threadInfo.pipes.writeQueriesToThread); if (existingSize > 0) { - g_log << Logger::Warning << "The current size of the distribution pipe's buffer for thread " << n << " is " << existingSize << endl; + SLOG(g_log << Logger::Warning << "The current size of the distribution pipe's buffer for thread " << n << " is " << existingSize << endl, + log->info(Logr::Warning, "The current size of the distribution pipe's buffer for thread", "thread", Logging::Loggable(n), "size", Logging::Loggable(existingSize))); } } } @@ -1756,7 +1771,7 @@ static int serviceMain(int argc, char* argv[], std::shared_ptr& lo startLuaConfigDelayedThreads(delayedLuaThreads, g_luaconfs.getCopy().generation); delayedLuaThreads.rpzPrimaryThreads.clear(); // no longer needed - RecThreadInfo::makeThreadPipes(); + RecThreadInfo::makeThreadPipes(log); g_tcpTimeout = ::arg().asNum("client-tcp-timeout"); g_maxTCPPerClient = ::arg().asNum("max-tcp-per-client"); diff --git a/pdns/recursordist/rec-main.hh b/pdns/recursordist/rec-main.hh index 7ee40a64e0..7fe9a1568d 100644 --- a/pdns/recursordist/rec-main.hh +++ b/pdns/recursordist/rec-main.hh @@ -447,7 +447,7 @@ public: } static int runThreads(std::shared_ptr&); - static void makeThreadPipes(); + static void makeThreadPipes(std::shared_ptr&); void setExitCode(int e) { @@ -468,7 +468,7 @@ public: uint64_t numberOfDistributedQueries{0}; private: - void start(unsigned int id, const string& name, const std::map>& cpusMap); + void start(unsigned int id, const string& name, const std::map>& cpusMap, std::shared_ptr&); std::string name; std::thread thread; @@ -480,7 +480,7 @@ private: bool listener{false}; // process queries bool worker{false}; - // run async tasks: from TastQueue and ZoneToCache + // run async tasks: from TaskQueue and ZoneToCache bool taskThread{false}; static thread_local unsigned int t_id; diff --git a/pdns/reczones.cc b/pdns/reczones.cc index 228e70d094..091a706bf3 100644 --- a/pdns/reczones.cc +++ b/pdns/reczones.cc @@ -53,9 +53,11 @@ bool primeHints(time_t ignored) time_t now = time(nullptr); + auto log = g_slog->withName("config"); const string hintfile = ::arg()["hint-file"]; if (hintfile == "no") { - g_log << Logger::Debug << "Priming root disabled by hint-file=no" << endl; + SLOG(g_log << Logger::Debug << "Priming root disabled by hint-file=no" << endl, + log->info(Logr::Debug, "Priming root disabled by hint-file=no")); return true; } if (hintfile.empty()) { @@ -146,7 +148,6 @@ bool primeHints(time_t ignored) break; } } - auto log = g_slog->withName("config"); if (SyncRes::s_doIPv4 && !SyncRes::s_doIPv6 && !reachableA) { SLOG(g_log << Logger::Error << "Running IPv4 only but no IPv4 root hints" << endl, log->info(Logr::Error, "Running IPv4 only but no IPv4 root hints")); @@ -546,7 +547,8 @@ std::tuple, std::shared_ptr> ifstream ifs(fname.c_str()); if (!ifs) { - g_log << Logger::Warning << "Could not open " << fname << " for reading" << endl; + SLOG(g_log << Logger::Warning << "Could not open " << fname << " for reading" << endl, + log->error(Logr::Warning, "Could not open file for reading", "file", Logging::Loggable(fname))); } else { string searchSuffix = ::arg()["export-etc-hosts-search-suffix"]; @@ -602,7 +604,8 @@ std::tuple, std::shared_ptr> } if (auto anff = ::arg()["allow-notify-for-file"]; !anff.empty()) { - g_log << Logger::Warning << "Reading NOTIFY-allowed zones from '" << anff << "'" << endl; + SLOG(g_log << Logger::Warning << "Reading NOTIFY-allowed zones from '" << anff << "'" << endl, + log->info(Logr::Notice, "Reading NOTIFY-allowed zones from file", "file", Logging::Loggable(anff))); auto fp = std::unique_ptr(fopen(anff.c_str(), "r"), fclose); if (!fp) { throw PDNSException("Error opening allow-notify-for-file '" + anff + "': " + stringerror());