From: Otto Moerbeek Date: Tue, 24 May 2022 10:12:30 +0000 (+0200) Subject: Move housekeeping and associated code to strcutured logging X-Git-Tag: auth-4.8.0-alpha0~88^2~1 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=2ed8065e5521868bfcadabf83a5bd28eeb7aa744;p=thirdparty%2Fpdns.git Move housekeeping and associated code to strcutured logging --- diff --git a/pdns/rec-lua-conf.cc b/pdns/rec-lua-conf.cc index 305afe588a..cc80775ca9 100644 --- a/pdns/rec-lua-conf.cc +++ b/pdns/rec-lua-conf.cc @@ -583,10 +583,11 @@ void loadRecursorLuaConfig(const std::string& fname, luaConfigDelayedThreads& de if (interval) { realInterval = static_cast(*interval); } + auto log = g_slog->withName("config"); warnIfDNSSECDisabled("Warning: reading Trust Anchors from file (readTrustAnchorsFromFile), but dnssec is set to 'off'!"); lci.trustAnchorFileInfo.fname = fnamearg; lci.trustAnchorFileInfo.interval = realInterval; - updateTrustAnchorsFromFile(fnamearg, lci.dsAnchors); + updateTrustAnchorsFromFile(fnamearg, lci.dsAnchors, log); }); Lua->writeFunction("setProtobufMasks", [&lci](const uint8_t maskV4, uint8_t maskV6) { diff --git a/pdns/recursordist/rec-main.cc b/pdns/recursordist/rec-main.cc index b8b6b3e65f..fbc5eacd67 100644 --- a/pdns/recursordist/rec-main.cc +++ b/pdns/recursordist/rec-main.cc @@ -1949,6 +1949,7 @@ private: static void houseKeeping(void*) { + auto log = g_slog->withName("housekeeping"); static thread_local bool t_running; // houseKeeping can get suspended in secpoll, and be restarted, which makes us do duplicate work try { @@ -2051,8 +2052,8 @@ static void houseKeeping(void*) // By default, refresh at 80% of max-cache-ttl with a minimum period of 10s const unsigned int minRootRefreshInterval = 10; static PeriodicTask rootUpdateTask{"rootUpdateTask", std::max(SyncRes::s_maxcachettl * 8 / 10, minRootRefreshInterval)}; - rootUpdateTask.runIfDue(now, [=]() { - int res = SyncRes::getRootNS(now, nullptr, 0); + rootUpdateTask.runIfDue(now, [now, &log, minRootRefreshInterval]() { + int res = SyncRes::getRootNS(now, nullptr, 0, log); if (res == 0) { // Success, go back to the defaut period rootUpdateTask.setPeriod(std::max(SyncRes::s_maxcachettl * 8 / 10, minRootRefreshInterval)); @@ -2060,19 +2061,24 @@ static void houseKeeping(void*) primeRootNSZones(g_dnssecmode, 0); } catch (const std::exception& e) { - g_log << Logger::Error << "Exception while priming the root NS zones: " << e.what() << endl; + SLOG(g_log << Logger::Error << "Exception while priming the root NS zones: " << e.what() << endl, + log->error(Logr::Error, e.what(), "Exception while priming the root NS zones")); } catch (const PDNSException& e) { - g_log << Logger::Error << "Exception while priming the root NS zones: " << e.reason << endl; + SLOG(g_log << Logger::Error << "Exception while priming the root NS zones: " << e.reason << endl, + log->error(Logr::Error, e.reason, "Exception while priming the root NS zones")); } catch (const ImmediateServFailException& e) { - g_log << Logger::Error << "Exception while priming the root NS zones: " << e.reason << endl; + SLOG(g_log << Logger::Error << "Exception while priming the root NS zones: " << e.reason << endl, + log->error(Logr::Error, e.reason, "Exception while priming the root NS zones")); } catch (const PolicyHitException& e) { - g_log << Logger::Error << "Policy hit while priming the root NS zones" << endl; + SLOG(g_log << Logger::Error << "Policy hit while priming the root NS zones" << endl, + log->info(Logr::Error, "Policy hit while priming the root NS zones")); } catch (...) { - g_log << Logger::Error << "Exception while priming the root NS zones" << endl; + SLOG(g_log << Logger::Error << "Exception while priming the root NS zones" << endl, + log->info(Logr::Error, "Exception while priming the root NS zones")); } } else { @@ -2085,24 +2091,29 @@ static void houseKeeping(void*) static PeriodicTask secpollTask{"secpollTask", 3600}; static time_t t_last_secpoll; - secpollTask.runIfDue(now, []() { + secpollTask.runIfDue(now, [&log]() { try { - doSecPoll(&t_last_secpoll); + doSecPoll(&t_last_secpoll, log); } catch (const std::exception& e) { - g_log << Logger::Error << "Exception while performing security poll: " << e.what() << endl; + SLOG(g_log << Logger::Error << "Exception while performing security poll: " << e.what() << endl, + log->error(Logr::Error, e.what(), "Exception while performing security poll")); } catch (const PDNSException& e) { - g_log << Logger::Error << "Exception while performing security poll: " << e.reason << endl; + SLOG(g_log << Logger::Error << "Exception while performing security poll: " << e.reason << endl, + log->error(Logr::Error, e.reason, "Exception while performing security poll")); } catch (const ImmediateServFailException& e) { - g_log << Logger::Error << "Exception while performing security poll: " << e.reason << endl; + SLOG(g_log << Logger::Error << "Exception while performing security poll: " << e.reason << endl, + log->error(Logr::Error, e.reason, "Exception while performing security poll")); } catch (const PolicyHitException& e) { - g_log << Logger::Error << "Policy hit while performing security poll" << endl; + SLOG(g_log << Logger::Error << "Policy hit while performing security poll" << endl, + log->info(Logr::Error, "Policy hit while performing security poll")); } catch (...) { - g_log << Logger::Error << "Exception while performing security poll" << endl; + SLOG(g_log << Logger::Error << "Exception while performing security poll" << endl, + log->info(Logr::Error, "Exception while performing security poll")); } }); @@ -2114,19 +2125,21 @@ static void houseKeeping(void*) } // interval might have ben updated trustAnchorTask.setPeriod(std::max(1U, luaconfsLocal->trustAnchorFileInfo.interval) * 3600); - trustAnchorTask.runIfDue(now, [&luaconfsLocal]() { + trustAnchorTask.runIfDue(now, [&luaconfsLocal, &log]() { if (!luaconfsLocal->trustAnchorFileInfo.fname.empty() && luaconfsLocal->trustAnchorFileInfo.interval != 0) { - g_log << Logger::Debug << "Refreshing Trust Anchors from file" << endl; + SLOG(g_log << Logger::Debug << "Refreshing Trust Anchors from file" << endl, + log->info(Logr::Debug, "Refreshing Trust Anchors from file")); try { map dsAnchors; - if (updateTrustAnchorsFromFile(luaconfsLocal->trustAnchorFileInfo.fname, dsAnchors)) { + if (updateTrustAnchorsFromFile(luaconfsLocal->trustAnchorFileInfo.fname, dsAnchors, log)) { g_luaconfs.modify([&dsAnchors](LuaConfigItems& lci) { lci.dsAnchors = dsAnchors; }); } } catch (const PDNSException& pe) { - g_log << Logger::Error << "Unable to update Trust Anchors: " << pe.reason << endl; + SLOG(g_log << Logger::Error << "Unable to update Trust Anchors: " << pe.reason << endl, + log->error(Logr::Error, pe.reason, "Unable to update Trust Anchors")); } } }); @@ -2135,12 +2148,14 @@ static void houseKeeping(void*) } catch (const PDNSException& ae) { t_running = false; - g_log << Logger::Error << "Fatal error in housekeeping thread: " << ae.reason << endl; + SLOG(g_log << Logger::Error << "Fatal error in housekeeping thread: " << ae.reason << endl, + log->error(Logr::Error, ae.reason, "Fatal error in housekeeping thread")); throw; } catch (...) { t_running = false; - g_log << Logger::Error << "Uncaught exception in housekeeping thread" << endl; + SLOG(g_log << Logger::Error << "Uncaught exception in housekeeping thread" << endl, + log->info(Logr::Error, "Uncaught exception in housekeeping thread")); throw; } } @@ -2164,9 +2179,11 @@ static void recursorThread() if (!primeHints()) { threadInfo.setExitCode(EXIT_FAILURE); RecursorControlChannel::stop = 1; - g_log << Logger::Critical << "Priming cache failed, stopping" << endl; + SLOG(g_log << Logger::Critical << "Priming cache failed, stopping" << endl, + log->info(Logr::Critical, "Priming cache failed, stopping")); } - g_log << Logger::Debug << "Done priming cache with root hints" << endl; + SLOG(g_log << Logger::Debug << "Done priming cache with root hints" << endl, + log->info(Logr::Debug, "Done priming cache with root hints")); } } @@ -2186,11 +2203,13 @@ static void recursorThread() if (!::arg()["lua-dns-script"].empty()) { t_pdl = std::make_shared(); t_pdl->loadFile(::arg()["lua-dns-script"]); - g_log << Logger::Warning << "Loaded 'lua' script from '" << ::arg()["lua-dns-script"] << "'" << endl; + SLOG(g_log << Logger::Warning << "Loaded 'lua' script from '" << ::arg()["lua-dns-script"] << "'" << endl, + log->info(Logr::Warning, "Loading Lua script from file", "name", Logging::Loggable(::arg()["lua-dns-script"]))); } } catch (std::exception& e) { - g_log << Logger::Error << "Failed to load 'lua' script from '" << ::arg()["lua-dns-script"] << "': " << e.what() << endl; + SLOG(g_log << Logger::Error << "Failed to load 'lua' script from '" << ::arg()["lua-dns-script"] << "': " << e.what() << endl, + log->error(Logr::Error, e.what(), "Failed to load Lua script from file", "name", Logging::Loggable(::arg()["lua-dns-script"]))); _exit(99); } } @@ -2299,7 +2318,7 @@ static void recursorThread() // Use primes, it avoid not being scheduled in cases where the counter has a regular pattern. // We want to call handler thread often, it gets scheduled about 2 times per second if (((threadInfo.isHandler() || threadInfo.isTaskThread()) && s_counter % 11 == 0) || s_counter % 499 == 0) { - MT->makeThread(houseKeeping, 0); + MT->makeThread(houseKeeping, nullptr); } if (!(s_counter % 55)) { diff --git a/pdns/secpoll-recursor.cc b/pdns/secpoll-recursor.cc index 69618030f8..be3d105d70 100644 --- a/pdns/secpoll-recursor.cc +++ b/pdns/secpoll-recursor.cc @@ -17,7 +17,7 @@ uint32_t g_security_status; string g_security_message; -void doSecPoll(time_t* last_secpoll) +void doSecPoll(time_t* last_secpoll, std::shared_ptr& log) { if (::arg()["security-poll-suffix"].empty()) return; @@ -55,15 +55,18 @@ void doSecPoll(time_t* last_secpoll) state = sr.getValidationState(); } + auto vlog = log->withValues("version", Logging::Loggable(pkgv), "query", Logging::Loggable(query)); if (vStateIsBogus(state)) { - g_log << Logger::Error << "Failed to retrieve security status update for '" + pkgv + "' on '" << query << "', DNSSEC validation result was Bogus!" << endl; + SLOG(g_log << Logger::Error << "Failed to retrieve security status update for '" + pkgv + "' on '" << query << "', DNSSEC validation result was Bogus!" << endl, + vlog->info(Logr::Error, "Failed to retrieve security status update", "validationResult", Logging::Loggable(vStateToString(state)))); if (g_security_status == 1) // If we were OK, go to unknown g_security_status = 0; return; } if (res == RCode::NXDomain && !isReleaseVersion(pkgv)) { - g_log << Logger::Warning << "Not validating response for security status update, this is a non-release version" << endl; + SLOG(g_log << Logger::Warning << "Not validating response for security status update, this is a non-release version" << endl, + vlog->info(Logr::Warning, "Not validating response for security status update, this is a non-release version")); return; } @@ -75,20 +78,25 @@ void doSecPoll(time_t* last_secpoll) } catch (const PDNSException& pe) { g_security_status = security_status; - g_log << Logger::Warning << "Failed to retrieve security status update for '" << pkgv << "' on '" << query << "': " << pe.reason << endl; + SLOG(g_log << Logger::Warning << "Failed to retrieve security status update for '" << pkgv << "' on '" << query << "': " << pe.reason << endl, + vlog->error(Logr::Warning, pe.reason, "Failed to retrieve security status update")); return; } g_security_message = security_message; + auto rlog = vlog->withValues("message", Logging::Loggable(g_security_message), "status", Logging::Loggable(security_status)); if (g_security_status != 1 && security_status == 1) { - g_log << Logger::Warning << "Polled security status of version " << pkgv << ", no known issues reported: " << g_security_message << endl; + SLOG(g_log << Logger::Warning << "Polled security status of version " << pkgv << ", no known issues reported: " << g_security_message << endl, + rlog->info(Logr::Notice, "Polled security status of version, no known issues reported")); } if (security_status == 2) { - g_log << Logger::Error << "PowerDNS Security Update Recommended: " << g_security_message << endl; + SLOG(g_log << Logger::Error << "PowerDNS Security Update Recommended: " << g_security_message << endl, + rlog->info(Logr::Error, "PowerDNS Security Update Recommended")); } if (security_status == 3) { - g_log << Logger::Error << "PowerDNS Security Update Mandatory: " << g_security_message << endl; + SLOG(g_log << Logger::Error << "PowerDNS Security Update Mandatory: " << g_security_message << endl, + rlog->info(Logr::Error, "PowerDNS Security Update Mandatory")); } g_security_status = security_status; diff --git a/pdns/secpoll-recursor.hh b/pdns/secpoll-recursor.hh index 3a06d20e1c..cfa77fa320 100644 --- a/pdns/secpoll-recursor.hh +++ b/pdns/secpoll-recursor.hh @@ -22,8 +22,9 @@ #pragma once #include #include "namespaces.hh" +#include "logr.hh" #include -void doSecPoll(time_t*); +void doSecPoll(time_t*, std::shared_ptr&); extern uint32_t g_security_status; extern std::string g_security_message; diff --git a/pdns/syncres.cc b/pdns/syncres.cc index f0d0140b93..1c6ee2aa0f 100644 --- a/pdns/syncres.cc +++ b/pdns/syncres.cc @@ -2164,7 +2164,8 @@ void SyncRes::getBestNSFromCache(const DNSName &qname, const QType qtype, vector /* let's prevent an infinite loop */ if (!d_updatingRootNS) { primeRootNSZones(g_dnssecmode, depth); - getRootNS(d_now, d_asyncResolve, depth); + auto log = g_slog->withName("housekeeping"); + getRootNS(d_now, d_asyncResolve, depth, log); } } } while(subdomain.chopOff()); @@ -5669,7 +5670,7 @@ int directResolve(const DNSName& qname, const QType qtype, const QClass qclass, return res; } -int SyncRes::getRootNS(struct timeval now, asyncresolve_t asyncCallback, unsigned int depth) { +int SyncRes::getRootNS(struct timeval now, asyncresolve_t asyncCallback, unsigned int depth, std::shared_ptr& log) { SyncRes sr(now); sr.setDoEDNS0(true); sr.setUpdatingRootNS(); @@ -5706,7 +5707,8 @@ int SyncRes::getRootNS(struct timeval now, asyncresolve_t asyncCallback, unsigne } if (res == 0) { - g_log<info(Logr::Debug, "Refreshed . records")); } else { g_log<&); static void addDontQuery(const std::string& mask) { if (!s_dontQuery) diff --git a/pdns/validate-recursor.cc b/pdns/validate-recursor.cc index 4c2bb1086a..545b815ff0 100644 --- a/pdns/validate-recursor.cc +++ b/pdns/validate-recursor.cc @@ -12,14 +12,17 @@ bool g_dnssecLogBogus; bool checkDNSSECDisabled() { - return warnIfDNSSECDisabled(""); + return g_dnssecmode == DNSSECMode::Off; } bool warnIfDNSSECDisabled(const string& msg) { if (g_dnssecmode == DNSSECMode::Off) { - if (!msg.empty()) - g_log << Logger::Warning << msg << endl; + if (!msg.empty()) { + auto log = g_slog->withName("config"); + SLOG(g_log << Logger::Warning << msg << endl, + log->info(Logr::Warning, msg)); + } return true; } return false; @@ -38,7 +41,7 @@ vState increaseXDNSSECStateCounter(const vState& state) } // Returns true if dsAnchors were modified -bool updateTrustAnchorsFromFile(const std::string& fname, map& dsAnchors) +bool updateTrustAnchorsFromFile(const std::string& fname, map& dsAnchors, std::shared_ptr& log) { map newDSAnchors; try { @@ -65,10 +68,12 @@ bool updateTrustAnchorsFromFile(const std::string& fname, map& } } if (dsAnchors == newDSAnchors) { - g_log << Logger::Debug << "Read Trust Anchors from file, no changes detected" << endl; + SLOG(g_log << Logger::Debug << "Read Trust Anchors from file, no changes detected" << endl, + log->info(Logr::Debug, "Read Trust Anchors from file, no changes detected")); return false; } - g_log << Logger::Info << "Read changed Trust Anchors from file, updating" << endl; + SLOG(g_log << Logger::Info << "Read changed Trust Anchors from file, updating" << endl, + log->info(Logr::Info, "Read changed Trust Anchors from file, updating")); dsAnchors = newDSAnchors; return true; } diff --git a/pdns/validate-recursor.hh b/pdns/validate-recursor.hh index 7e31c63c0b..a45304a477 100644 --- a/pdns/validate-recursor.hh +++ b/pdns/validate-recursor.hh @@ -22,7 +22,7 @@ #pragma once #include "namespaces.hh" #include "validate.hh" -#include "logger.hh" +#include "logging.hh" /* Off: 3.x behaviour, we do no DNSSEC, no EDNS ProcessNoValidate: we gather DNSSEC records on all queries, but we will never validate @@ -46,4 +46,4 @@ bool checkDNSSECDisabled(); bool warnIfDNSSECDisabled(const string& msg); vState increaseDNSSECStateCounter(const vState& state); vState increaseXDNSSECStateCounter(const vState& state); -bool updateTrustAnchorsFromFile(const std::string& fname, map& dsAnchors); +bool updateTrustAnchorsFromFile(const std::string& fname, map& dsAnchors, std::shared_ptr&);