From: Otto Moerbeek Date: Wed, 15 Jun 2022 08:43:37 +0000 (+0200) Subject: Remaining structured logging, "only" sending/receiving questions and answers, validat... X-Git-Tag: auth-4.8.0-alpha0~50^2~1 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=adfe9b1664961edd3ced49ef434b73792d5abe58;p=thirdparty%2Fpdns.git Remaining structured logging, "only" sending/receiving questions and answers, validation and tracing remain. --- diff --git a/pdns/lua-base4.cc b/pdns/lua-base4.cc index 31c2da0cf7..f3d0751e47 100644 --- a/pdns/lua-base4.cc +++ b/pdns/lua-base4.cc @@ -3,6 +3,7 @@ #include #include #include "logger.hh" +#include "logging.hh" #include "iputils.hh" #include "dnsname.hh" #include "dnsparser.hh" @@ -21,7 +22,8 @@ int BaseLua4::loadFile(const std::string &fname) { std::ifstream ifs(fname); if (!ifs) { ret = errno; - g_log<withName("lua")->error(Logr::Error, ret, "Unable to read configuration file", "file", Logging::Loggable(fname))); return ret; } loadStream(ifs); @@ -167,7 +169,10 @@ void BaseLua4::prepareContext() { else cas.insert(boost::get(in)); } - catch(std::exception& e) { g_log <withName("lua")->error(Logr::Error, e.what(), "Exception in newCAS", "exception", Logging::Loggable("std::exception"))); + } }); d_lw->registerFunction("check",[](const cas_t& cas, const ComboAddress&ca) { return cas.count(ca)>0; }); @@ -229,7 +234,10 @@ void BaseLua4::prepareContext() { d_lw->registerFunction("changeContent", [](DNSRecord& dr, const std::string& newContent) { dr.d_content = shared_ptr(DNSRecordContent::mastermake(dr.d_type, 1, newContent)); }); // pdnsload - d_lw->writeFunction("pdnslog", [](const std::string& msg, boost::optional loglevel) { g_log << (Logger::Urgency)loglevel.get_value_or(Logger::Warning) << msg<writeFunction("pdnslog", [](const std::string& msg, boost::optional loglevel) { + SLOG(g_log << (Logger::Urgency)loglevel.get_value_or(Logger::Warning) << msg<withName("lua")->info(static_cast(loglevel.get_value_or(Logr::Warning)), msg)); + }); d_lw->writeFunction("pdnsrandom", [](boost::optional maximum) { return dns_random(maximum.get_value_or(0xffffffff)); }); // certain constants diff --git a/pdns/nod.cc b/pdns/nod.cc index 07d3928238..6dc93a233a 100644 --- a/pdns/nod.cc +++ b/pdns/nod.cc @@ -30,6 +30,7 @@ #include "threadname.hh" #include #include "logger.hh" +#include "logging.hh" #include "misc.hh" using namespace nod; @@ -58,6 +59,7 @@ bool PersistentSBF::init(bool ignore_pid) { if (d_init) return false; + auto log = g_slog->withName("nod"); std::lock_guard lock(d_cachedir_mutex); if (d_cachedir.length()) { filesystem::path p(d_cachedir); @@ -86,7 +88,8 @@ bool PersistentSBF::init(bool ignore_pid) { std::ifstream infile; try { infile.open(filename, std::ios::in | std::ios::binary); - g_log << Logger::Warning << "Found SBF file " << filename << endl; + SLOG(g_log << Logger::Warning << "Found SBF file " << filename << endl, + log->info(Logr::Warning, "Found SBF File", "file", Logging::Loggable(filename))); // read the file into the sbf d_sbf.lock()->restore(infile); infile.close(); @@ -98,13 +101,15 @@ bool PersistentSBF::init(bool ignore_pid) { catch (const std::runtime_error& e) { infile.close(); filesystem::remove(newest_file); - g_log<error(Logr::Warning, e.what(), "NODDB init: Cannot parse file, removed", "file", Logging::Loggable(filename))); } } } } catch (const filesystem::filesystem_error& e) { - g_log<error(Logr::Warning, e.what(), "NODDB init failed", "exception", Logging::Loggable("filesystem::filesystem_error"))); return false; } } @@ -130,6 +135,7 @@ void PersistentSBF::setCacheDir(const std::string& cachedir) // file IO to complete bool PersistentSBF::snapshotCurrent(std::thread::id tid) { + auto log = g_slog->withName("nod"); if (d_cachedir.length()) { filesystem::path p(d_cachedir); filesystem::path f(d_cachedir); @@ -165,18 +171,21 @@ bool PersistentSBF::snapshotCurrent(std::thread::id tid) filesystem::rename(ftmp, f); } catch (const std::runtime_error& e) { - g_log<error(Logr::Warning, e.what(), "NODDB snapshot: Cannot rename file", "exception", Logging::Loggable("std::runtime_error"))); filesystem::remove(ftmp); throw; } return true; } catch (const std::runtime_error& e) { - g_log<error(Logr::Warning, e.what(), "NODDB snapshot: Cannot write file", "exception", Logging::Loggable("std::runtime_error"))); } } else { - g_log<info(Logr::Warning, "NODDB snapshot: Cannot write file", "file", Logging::Loggable(f.string()))); } } return false; diff --git a/pdns/rec-carbon.cc b/pdns/rec-carbon.cc index a8e67a6bae..8e28309b2b 100644 --- a/pdns/rec-carbon.cc +++ b/pdns/rec-carbon.cc @@ -6,6 +6,7 @@ #include "rec_channel.hh" #include "iputils.hh" #include "logger.hh" +#include "logging.hh" #include "arguments.hh" #include "lock.hh" @@ -13,6 +14,7 @@ GlobalStateHolder g_carbonConfig; void doCarbonDump(void*) { + auto log = g_slog->withName("carbon"); try { static thread_local auto configHolder = g_carbonConfig.getLocal(); @@ -66,21 +68,27 @@ void doCarbonDump(void*) auto ret = asendtcp(msg, handler); // this will actually do the right thing waiting on the connect if (ret == LWResult::Result::Timeout) { - g_log << Logger::Warning << "Timeout connecting/writing carbon data to " << remote.toStringWithPort() << endl; + SLOG(g_log << Logger::Warning << "Timeout connecting/writing carbon data to " << remote.toStringWithPort() << endl, + log->info(Logr::Warning, "Timeout connecting/writing carbon data", "address", Logging::Loggable(remote))); } else if (ret != LWResult::Result::Success) { - g_log << Logger::Warning << "Error writing carbon data to " << remote.toStringWithPort() << ": " << stringerror() << endl; + int err = errno; + SLOG(g_log << Logger::Warning << "Error writing carbon data to " << remote.toStringWithPort() << ": " << stringerror(err) << endl, + log->error(Logr::Warning, err, "Error writing carbon data", "address", Logging::Loggable(remote))); } handler->close(); } } catch (const PDNSException& e) { - g_log << Logger::Error << "Error in carbon thread: " << e.reason << endl; + SLOG(g_log << Logger::Error << "Error in carbon thread: " << e.reason << endl, + log->error(Logr::Error, e.reason, "Error in carbon thread", "exception", Logging::Loggable("PDNSException"))); } catch (const std::exception& e) { - g_log << Logger::Error << "Error in carbon thread: " << e.what() << endl; + SLOG(g_log << Logger::Error << "Error in carbon thread: " << e.what() << endl, + log->error(Logr::Error, e.what(), "Error in carbon thread", "exception", Logging::Loggable("std::exception"))); } catch (...) { - g_log << Logger::Error << "Unknown error in carbon thread" << endl; + SLOG(g_log << Logger::Error << "Unknown error in carbon thread" << endl, + log->info(Logr::Error, "Error in carbon thread")); } } diff --git a/pdns/rec-snmp.cc b/pdns/rec-snmp.cc index 0f76cadd83..d3eb3e4c4c 100644 --- a/pdns/rec-snmp.cc +++ b/pdns/rec-snmp.cc @@ -5,6 +5,7 @@ #include "rec_channel.hh" #include "logger.hh" +#include "logging.hh" #ifdef HAVE_NET_SNMP @@ -200,12 +201,14 @@ static int handleDisabledCounter64Stats(netsnmp_mib_handler* handler, static void registerCounter64Stat(const std::string& name, const oid statOID[], size_t statOIDLength) { if (statOIDLength != OID_LENGTH(questionsOID)) { - g_log << Logger::Error << "Invalid OID for SNMP Counter64 statistic " << name << endl; + SLOG(g_log << Logger::Error << "Invalid OID for SNMP Counter64 statistic " << name << endl, + g_slog->withName("snmp")->info(Logr::Error, "Invalid OID for SNMP Counter64 statistic", "name", Logging::Loggable(name))); return; } if (s_statsMap.find(statOID[statOIDLength - 1]) != s_statsMap.end()) { - g_log << Logger::Error << "OID for SNMP Counter64 statistic " << name << " has already been registered" << endl; + SLOG(g_log << Logger::Error << "OID for SNMP Counter64 statistic " << name << " has already been registered" << endl, + g_slog->withName("snmp")->info(Logr::Error, "OID for SNMP Counter64 statistic has already been registered", "name", Logging::Loggable(name))); return; } diff --git a/pdns/recursordist/pubsuffixloader.cc b/pdns/recursordist/pubsuffixloader.cc index e9a25bfc16..ea8b9908d0 100644 --- a/pdns/recursordist/pubsuffixloader.cc +++ b/pdns/recursordist/pubsuffixloader.cc @@ -25,6 +25,7 @@ #include "dnsname.hh" #include "logger.hh" +#include "logging.hh" #include "misc.hh" #include "pubsuffix.hh" @@ -66,11 +67,13 @@ void initPublicSuffixList(const std::string& file) } } - g_log << Logger::Info << "Loaded the Public Suffix List from '" << file << "'" << endl; + SLOG(g_log << Logger::Info << "Loaded the Public Suffix List from '" << file << "'" << endl, + g_slog->withName("runtime")->info(Logr::Info, "Loaded the Public Suffix List", "file", Logging::Loggable(file))); loaded = true; } catch (const std::exception& e) { - g_log << Logger::Warning << "Error while loading the Public Suffix List from '" << file << "', falling back to the built-in list: " << e.what() << endl; + SLOG(g_log << Logger::Warning << "Error while loading the Public Suffix List from '" << file << "', falling back to the built-in list: " << e.what() << endl, + g_slog->withName("runtime")->error(Logr::Error, e.what(), "Loaded the Public Suffix List", "file", Logging::Loggable(file))); } } diff --git a/pdns/rpzloader.cc b/pdns/rpzloader.cc index 52a0386db9..a92ee3f8b9 100644 --- a/pdns/rpzloader.cc +++ b/pdns/rpzloader.cc @@ -468,7 +468,7 @@ void RPZIXFRTracker(const std::vector& primaries, const boost::opt auto soa = getRR(dr); auto serial = soa ? soa->d_st.serial : 0; SLOG(g_log<info(Logr::Info, "Getting IXFR deltas", "address", Logging::Loggable(primary))); + logger->info(Logr::Info, "Getting IXFR deltas", "address", Logging::Loggable(primary), "ourserial", Logging::Loggable(serial))); ComboAddress local(localAddress); if (local == ComboAddress()) { diff --git a/pdns/syncres.cc b/pdns/syncres.cc index 07fdafe868..c137dcd560 100644 --- a/pdns/syncres.cc +++ b/pdns/syncres.cc @@ -5012,8 +5012,13 @@ static void updateDoTStatus(ComboAddress address, DoTStatus::Status status, time bool SyncRes::tryDoT(const DNSName& qname, const QType qtype, const DNSName& nsName, ComboAddress address, time_t now) { - auto logHelper = [](const string& msg) { - g_log<withName("taskq")->withValues("method", Logging::Loggable("tryDoT"), "name", Logging::Loggable(qname), "qtype", Logging::Loggable(QType(qtype).toString()), "ip", Logging::Loggable(address)); + + auto logHelper1 = [&log](const string& ename) { + log->info(Logr::Debug, "Failed to probe DoT records, got an exception", "exception", Logging::Loggable(ename)); + }; + auto logHelper2 = [&log](const string& msg, const string& ename) { + log->error(Logr::Debug, msg, "Failed to probe DoT records, got an exception", "exception", Logging::Loggable(ename)); }; LWResult lwr; bool truncated; @@ -5027,19 +5032,19 @@ bool SyncRes::tryDoT(const DNSName& qname, const QType qtype, const DNSName& nsN ok = ok && lwr.d_rcode == RCode::NoError && lwr.d_records.size() > 0; } catch(const PDNSException& e) { - logHelper(e.reason); + logHelper2(e.reason, "PDNSException"); } catch(const ImmediateServFailException& e) { - logHelper(e.reason); + logHelper2(e.reason, "ImmediateServFailException"); } catch(const PolicyHitException& e) { - logHelper("PolicyHitException"); + logHelper1("PolicyHitException"); } catch(const std::exception& e) { - logHelper(e.what()); + logHelper2(e.what(), "std::exception"); } catch(...) { - logHelper("other"); + logHelper1("other"); } updateDoTStatus(address, ok ? DoTStatus::Good : DoTStatus::Bad, now + (ok ? dotSuccessWait : dotFailWait), true); return ok; diff --git a/pdns/threadname.cc b/pdns/threadname.cc index 4318117d0a..39e904ce91 100644 --- a/pdns/threadname.cc +++ b/pdns/threadname.cc @@ -35,6 +35,7 @@ #include "dolog.hh" #else #include "logger.hh" +#include "logging.hh" #endif #include "threadname.hh" @@ -72,7 +73,8 @@ void setThreadName(const std::string& threadName) { #ifdef DNSDIST warnlog("Could not set thread name %s for thread: %s", threadName, strerror(retval)); #else - g_log<withName("runtime")->error(Logr::Warning, retval, "Could not set thread name", "name", Logging::Loggable(threadName))); #endif } } diff --git a/pdns/unix_utility.cc b/pdns/unix_utility.cc index 8d209275d2..763885916f 100644 --- a/pdns/unix_utility.cc +++ b/pdns/unix_utility.cc @@ -26,9 +26,10 @@ #include #include #include -#include +#include #include "pdnsexception.hh" #include "logger.hh" +#include "logging.hh" #include "misc.hh" #include #include @@ -83,23 +84,35 @@ void Utility::setBindAny(int af, sock_t sock) (void) one; // avoids 'unused var' warning on systems that have none of the defines checked below #ifdef IP_FREEBIND - if (setsockopt(sock, IPPROTO_IP, IP_FREEBIND, &one, sizeof(one)) < 0) - g_log<withName("runtime")->error(Logr::Warning, err, "Warning: IP_FREEBIND setsockopt failed")); + } #endif #ifdef IP_BINDANY if (af == AF_INET) - if (setsockopt(sock, IPPROTO_IP, IP_BINDANY, &one, sizeof(one)) < 0) - g_log<withName("runtime")->error(Logr::Warning, err, "Warning: IP_BINDANY setsockopt failed")); + } #endif #ifdef IPV6_BINDANY - if (af == AF_INET6) - if (setsockopt(sock, IPPROTO_IPV6, IPV6_BINDANY, &one, sizeof(one)) < 0) - g_log<withName("runtime")->error(Logr::Warning, err, ""Warning: IPV6_BINDANY setsockopt failed")); + } + } #endif #ifdef SO_BINDANY - if (setsockopt(sock, SOL_SOCKET, SO_BINDANY, &one, sizeof(one)) < 0) - g_log<withName("runtime")->error(Logr::Warning, err, "Warning: SO_BINDANY setsockopt failed")); + } #endif } @@ -128,22 +141,30 @@ void Utility::dropGroupPrivs( uid_t uid, gid_t gid ) { if(gid && gid != getegid()) { if(setgid(gid)<0) { - g_log<withName("runtime")->error(Logr::Critical, err, "Unable to set effective group id", "gid", Logging::Loggable(gid))); exit(1); } - else - g_log<withName("runtime")->info(Logr::Info, "Set effective group id", "gid", Logging::Loggable(gid))); + } struct passwd *pw=getpwuid(uid); if(!pw) { - g_log<withName("runtime")->info(Logr::Warning, "Unable to determine user name", "uid", Logging::Loggable(uid))); if (setgroups(0, nullptr)<0) { - g_log<withName("runtime")->error(Logr::Critical, err, "Unable to drop supplementary gids")); exit(1); } } else { if (initgroups(pw->pw_name, gid)<0) { - g_log<withName("runtime")->error(Logr::Critical, err, "Unable to drop supplementary groups")); exit(1); } } @@ -156,11 +177,15 @@ void Utility::dropUserPrivs( uid_t uid ) { if(uid && uid != geteuid()) { if(setuid(uid)<0) { - g_log<withName("runtime")->error(Logr::Error, err, "Unable to set effective user id", "uid", Logging::Loggable(uid))); exit(1); } - else - g_log<withName("runtime")->info("Set effective user", "uid", Logging::Loggable(uid))); + } } }