From: Remi Gacogne Date: Thu, 28 Sep 2023 13:32:29 +0000 (+0200) Subject: dnsdist: Set proper levels when logging messages X-Git-Tag: rec-5.0.0-alpha2~39^2 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=f8e1161f37e310279c635de0cc79c031b0e7e270;p=thirdparty%2Fpdns.git dnsdist: Set proper levels when logging messages This PR re-evaluates the log level of all messages in the DNSdist code base. The rules are simple: - 'Error' should only be used when a critical service will not function properly - 'Warning' should be used when a non-essential feature may not be working as expected - 'Info' is for everything that should not go unnoticed but also cannot be triggered by an outside attacker, otherwise we might be flooding our logs - 'Verbose' can be used for everything else. There are a few exceptions, something we log at the 'info' level for events that might be happening a lot, but only when told to do so, like for example with verbose health-check reporting. --- diff --git a/pdns/dnsdist-console.cc b/pdns/dnsdist-console.cc index f2e381f222..d1a42663d1 100644 --- a/pdns/dnsdist-console.cc +++ b/pdns/dnsdist-console.cc @@ -988,7 +988,7 @@ static void controlClientThread(ConsoleConnection&& conn) } } catch (const std::exception& e) { - errlog("Got an exception in client connection from %s: %s", conn.getClient().toStringWithPort(), e.what()); + infolog("Got an exception in client connection from %s: %s", conn.getClient().toStringWithPort(), e.what()); } } @@ -1026,7 +1026,7 @@ void controlThread(int fd, ComboAddress local) t.detach(); } catch (const std::exception& e) { - errlog("Control connection died: %s", e.what()); + infolog("Control connection died: %s", e.what()); } } } diff --git a/pdns/dnsdist-lua.cc b/pdns/dnsdist-lua.cc index a3a9bf3bdc..6d17445068 100644 --- a/pdns/dnsdist-lua.cc +++ b/pdns/dnsdist-lua.cc @@ -1595,9 +1595,9 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck) g_frontends.push_back(std::move(cs)); } - catch (std::exception& e) { - errlog(e.what()); - g_outputBuffer = "Error: " + string(e.what()) + "\n"; + catch (const std::exception& e) { + errlog("Error during addDNSCryptBind() processing: %s", e.what()); + g_outputBuffer = "Error during addDNSCryptBind() processing: " + string(e.what()) + "\n"; } }); @@ -2560,13 +2560,13 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck) result = g_dohlocals.at(index); } else { - errlog("Error: trying to get DOH frontend with index %zu but we only have %zu frontend(s)\n", index, g_dohlocals.size()); + errlog("Error: trying to get DOH frontend with index %d but we only have %d frontend(s)\n", index, g_dohlocals.size()); g_outputBuffer = "Error: trying to get DOH frontend with index " + std::to_string(index) + " but we only have " + std::to_string(g_dohlocals.size()) + " frontend(s)\n"; } } catch (const std::exception& e) { g_outputBuffer = "Error while trying to get DOH frontend with index " + std::to_string(index) + ": " + string(e.what()) + "\n"; - errlog("Error while trying to get DOH frontend with index %zu: %s\n", index, string(e.what())); + errlog("Error while trying to get DOH frontend with index %d: %s\n", index, string(e.what())); } #else g_outputBuffer="DNS over HTTPS support is not present!\n"; @@ -2755,13 +2755,13 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck) result = g_tlslocals.at(index)->getContext(); } else { - errlog("Error: trying to get TLS context with index %zu but we only have %zu context(s)\n", index, g_tlslocals.size()); + errlog("Error: trying to get TLS context with index %d but we only have %d context(s)\n", index, g_tlslocals.size()); g_outputBuffer = "Error: trying to get TLS context with index " + std::to_string(index) + " but we only have " + std::to_string(g_tlslocals.size()) + " context(s)\n"; } } catch (const std::exception& e) { g_outputBuffer = "Error while trying to get TLS context with index " + std::to_string(index) + ": " + string(e.what()) + "\n"; - errlog("Error while trying to get TLS context with index %zu: %s\n", index, string(e.what())); + errlog("Error while trying to get TLS context with index %d: %s\n", index, string(e.what())); } #else g_outputBuffer="DNS over TLS support is not present!\n"; @@ -2778,13 +2778,13 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck) result = g_tlslocals.at(index); } else { - errlog("Error: trying to get TLS frontend with index %zu but we only have %zu frontends\n", index, g_tlslocals.size()); + errlog("Error: trying to get TLS frontend with index %d but we only have %d frontends\n", index, g_tlslocals.size()); g_outputBuffer = "Error: trying to get TLS frontend with index " + std::to_string(index) + " but we only have " + std::to_string(g_tlslocals.size()) + " frontend(s)\n"; } } catch (const std::exception& e) { g_outputBuffer = "Error while trying to get TLS frontend with index " + std::to_string(index) + ": " + string(e.what()) + "\n"; - errlog("Error while trying to get TLS frontend with index %zu: %s\n", index, string(e.what())); + errlog("Error while trying to get TLS frontend with index %d: %s\n", index, string(e.what())); } #else g_outputBuffer="DNS over TLS support is not present!\n"; @@ -2971,7 +2971,7 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck) auto result = dnsdist::metrics::declareCustomMetric(name, type, description, customName ? std::optional(*customName) : std::nullopt); if (result) { g_outputBuffer += *result + "\n"; - errlog("%s", *result); + errlog("Error in declareMetric: %s", *result); return false; } return true; @@ -2980,7 +2980,7 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck) auto result = dnsdist::metrics::incrementCustomCounter(name, step ? *step : 1); if (const auto* errorStr = std::get_if(&result)) { g_outputBuffer = *errorStr + "'\n"; - errlog("%s", *errorStr); + errlog("Error in incMetric: %s", *errorStr); return static_cast(0); } return std::get(result); @@ -2989,7 +2989,7 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck) auto result = dnsdist::metrics::decrementCustomCounter(name, step ? *step : 1); if (const auto* errorStr = std::get_if(&result)) { g_outputBuffer = *errorStr + "'\n"; - errlog("%s", *errorStr); + errlog("Error in decMetric: %s", *errorStr); return static_cast(0); } return std::get(result); @@ -2998,7 +2998,7 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck) auto result = dnsdist::metrics::setCustomGauge(name, value); if (const auto* errorStr = std::get_if(&result)) { g_outputBuffer = *errorStr + "'\n"; - errlog("%s", *errorStr); + errlog("Error in setMetric: %s", *errorStr); return 0.; } return std::get(result); @@ -3007,7 +3007,7 @@ static void setupLuaConfig(LuaContext& luaCtx, bool client, bool configCheck) auto result = dnsdist::metrics::getCustomMetric(name); if (const auto* errorStr = std::get_if(&result)) { g_outputBuffer = *errorStr + "'\n"; - errlog("%s", *errorStr); + errlog("Error in getMetric: %s", *errorStr); return 0.; } return std::get(result); diff --git a/pdns/dnsdist-tcp.cc b/pdns/dnsdist-tcp.cc index c55574ef27..7b94e00e51 100644 --- a/pdns/dnsdist-tcp.cc +++ b/pdns/dnsdist-tcp.cc @@ -1446,43 +1446,43 @@ static void tcpClientThread(pdns::channel::Receiver&& queryRecei if (g_tcpStatesDumpRequested > 0) { /* no race here, we took the lock so it can only be increased in the meantime */ --g_tcpStatesDumpRequested; - errlog("Dumping the TCP states, as requested:"); + infolog("Dumping the TCP states, as requested:"); data.mplexer->runForAllWatchedFDs([](bool isRead, int fd, const FDMultiplexer::funcparam_t& param, struct timeval ttd) { struct timeval lnow; gettimeofday(&lnow, nullptr); if (ttd.tv_sec > 0) { - errlog("- Descriptor %d is in %s state, TTD in %d", fd, (isRead ? "read" : "write"), (ttd.tv_sec-lnow.tv_sec)); + infolog("- Descriptor %d is in %s state, TTD in %d", fd, (isRead ? "read" : "write"), (ttd.tv_sec-lnow.tv_sec)); } else { - errlog("- Descriptor %d is in %s state, no TTD set", fd, (isRead ? "read" : "write")); + infolog("- Descriptor %d is in %s state, no TTD set", fd, (isRead ? "read" : "write")); } if (param.type() == typeid(std::shared_ptr)) { auto state = boost::any_cast>(param); - errlog(" - %s", state->toString()); + infolog(" - %s", state->toString()); } #ifdef HAVE_NGHTTP2 else if (param.type() == typeid(std::shared_ptr)) { auto state = boost::any_cast>(param); - errlog(" - %s", state->toString()); + infolog(" - %s", state->toString()); } #endif /* HAVE_NGHTTP2 */ else if (param.type() == typeid(std::shared_ptr)) { auto conn = boost::any_cast>(param); - errlog(" - %s", conn->toString()); + infolog(" - %s", conn->toString()); } else if (param.type() == typeid(TCPClientThreadData*)) { - errlog(" - Worker thread pipe"); + infolog(" - Worker thread pipe"); } }); - errlog("The TCP/DoT client cache has %d active and %d idle outgoing connections cached", t_downstreamTCPConnectionsManager.getActiveCount(), t_downstreamTCPConnectionsManager.getIdleCount()); + infolog("The TCP/DoT client cache has %d active and %d idle outgoing connections cached", t_downstreamTCPConnectionsManager.getActiveCount(), t_downstreamTCPConnectionsManager.getIdleCount()); } } } } catch (const std::exception& e) { - errlog("Error in TCP worker thread: %s", e.what()); + warnlog("Error in TCP worker thread: %s", e.what()); } } } diff --git a/pdns/dnsdist-web.cc b/pdns/dnsdist-web.cc index 5037985972..4ceacaa991 100644 --- a/pdns/dnsdist-web.cc +++ b/pdns/dnsdist-web.cc @@ -225,7 +225,7 @@ bool addMetricDefinition(const dnsdist::prometheus::PrometheusMetricDefinition& static bool apiWriteConfigFile(const string& filebasename, const string& content) { if (!g_apiReadWrite) { - errlog("Not writing content to %s since the API is read-only", filebasename); + warnlog("Not writing content to %s since the API is read-only", filebasename); return false; } @@ -1757,10 +1757,10 @@ static void connectionThread(WebClientConnection&& conn) vinfolog("Webserver thread died with parse error exception while processing a request from %s: %s", conn.getClient().toStringWithPort(), e.what()); } catch (const std::exception& e) { - errlog("Webserver thread died with exception while processing a request from %s: %s", conn.getClient().toStringWithPort(), e.what()); + vinfolog("Webserver thread died with exception while processing a request from %s: %s", conn.getClient().toStringWithPort(), e.what()); } catch (...) { - errlog("Webserver thread died with exception while processing a request from %s", conn.getClient().toStringWithPort()); + vinfolog("Webserver thread died with exception while processing a request from %s", conn.getClient().toStringWithPort()); } } @@ -1843,7 +1843,7 @@ void dnsdistWebserverThread(int sock, const ComboAddress& local) t.detach(); } catch (const std::exception& e) { - errlog("Had an error accepting new webserver connection: %s", e.what()); + vinfolog("Had an error accepting new webserver connection: %s", e.what()); } } } diff --git a/pdns/dnsdist.cc b/pdns/dnsdist.cc index a23c03f048..cde7fd061b 100644 --- a/pdns/dnsdist.cc +++ b/pdns/dnsdist.cc @@ -338,7 +338,7 @@ bool responseContentMatches(const PacketBuffer& response, const DNSName& qname, } catch (const std::exception& e) { if (remote && response.size() > 0 && static_cast(response.size()) > sizeof(dnsheader)) { - infolog("Backend %s sent us a response with id %d that did not parse: %s", remote->d_config.remote.toStringWithPort(), ntohs(dh->id), e.what()); + vinfolog("Backend %s sent us a response with id %d that did not parse: %s", remote->d_config.remote.toStringWithPort(), ntohs(dh->id), e.what()); } ++dnsdist::metrics::g_stats.nonCompliantResponses; if (remote) { @@ -1956,9 +1956,9 @@ static void maintThread() (*f)(); secondsToWaitLog = 0; } - catch(const std::exception &e) { + catch (const std::exception &e) { if (secondsToWaitLog <= 0) { - infolog("Error during execution of maintenance function: %s", e.what()); + warnlog("Error during execution of maintenance function: %s", e.what()); secondsToWaitLog = 61; } secondsToWaitLog -= interval; diff --git a/pdns/dnsdistdist/dnsdist-kvs.cc b/pdns/dnsdistdist/dnsdist-kvs.cc index c2b6272ac4..d20aa1e980 100644 --- a/pdns/dnsdistdist/dnsdist-kvs.cc +++ b/pdns/dnsdistdist/dnsdist-kvs.cc @@ -96,8 +96,8 @@ bool LMDBKVStore::getValue(const std::string& key, std::string& value) return false; } } - catch(const std::exception& e) { - warnlog("Error while looking up key '%s' from LMDB file '%s', database '%s': %s", key, d_fname, d_dbName, e.what()); + catch (const std::exception& e) { + vinfolog("Error while looking up key '%s' from LMDB file '%s', database '%s': %s", key, d_fname, d_dbName, e.what()); } return false; } @@ -115,8 +115,8 @@ bool LMDBKVStore::keyExists(const std::string& key) return false; } } - catch(const std::exception& e) { - warnlog("Error while looking up key '%s' from LMDB file '%s', database '%s': %s", key, d_fname, d_dbName, e.what()); + catch (const std::exception& e) { + vinfolog("Error while looking up key '%s' from LMDB file '%s', database '%s': %s", key, d_fname, d_dbName, e.what()); } return false; } @@ -163,7 +163,7 @@ bool LMDBKVStore::getRangeValue(const std::string& key, std::string& value) return false; } } - catch(const std::exception& e) { + catch (const std::exception& e) { vinfolog("Error while looking up a range from LMDB file '%s', database '%s': %s", d_fname, d_dbName, e.what()); } return false; @@ -230,7 +230,7 @@ void CDBKVStore::refreshDBIfNeeded(time_t now) d_nextCheck = now + d_refreshDelay; d_refreshing.clear(); } - catch(...) { + catch (...) { d_refreshing.clear(); throw; } @@ -252,8 +252,8 @@ bool CDBKVStore::getValue(const std::string& key, std::string& value) } } } - catch(const std::exception& e) { - warnlog("Error while looking up key '%s' from CDB file '%s': %s", key, d_fname, e.what()); + catch (const std::exception& e) { + vinfolog("Error while looking up key '%s' from CDB file '%s': %s", key, d_fname, e.what()); } return false; } @@ -276,8 +276,8 @@ bool CDBKVStore::keyExists(const std::string& key) return (*cdb)->keyExists(key); } } - catch(const std::exception& e) { - warnlog("Error while looking up key '%s' from CDB file '%s': %s", key, d_fname, e.what()); + catch (const std::exception& e) { + vinfolog("Error while looking up key '%s' from CDB file '%s': %s", key, d_fname, e.what()); } return false; } diff --git a/pdns/dnsdistdist/dnsdist-lua-bindings-dnscrypt.cc b/pdns/dnsdistdist/dnsdist-lua-bindings-dnscrypt.cc index 72936ca975..0385550e0a 100644 --- a/pdns/dnsdistdist/dnsdist-lua-bindings-dnscrypt.cc +++ b/pdns/dnsdistdist/dnsdist-lua-bindings-dnscrypt.cc @@ -121,9 +121,9 @@ void setupLuaBindingsDNSCrypt(LuaContext& luaCtx, bool client) ctx.addNewCertificate(cert, privateKey); } } - catch(const std::exception& e) { - errlog(e.what()); - g_outputBuffer="Error: "+string(e.what())+"\n"; + catch (const std::exception& e) { + errlog("Error generating a DNSCrypt certificate: %s", e.what()); + g_outputBuffer = "Error generating a DNSCrypt certificate: " + string(e.what()) + "\n"; } }); @@ -167,8 +167,8 @@ void setupLuaBindingsDNSCrypt(LuaContext& luaCtx, bool client) } } catch (const std::exception& e) { - errlog(e.what()); - g_outputBuffer = "Error: " + string(e.what()) + "\n"; + errlog("Error generating a DNSCrypt certificate: %s", e.what()); + g_outputBuffer = "Error generating a DNSCrypt certificate: " + string(e.what()) + "\n"; } }); @@ -195,8 +195,8 @@ void setupLuaBindingsDNSCrypt(LuaContext& luaCtx, bool client) g_outputBuffer = "Provider fingerprint is: " + DNSCryptContext::getProviderFingerprint(publicKey) + "\n"; } catch (const std::exception& e) { - errlog(e.what()); - g_outputBuffer = "Error: " + string(e.what()) + "\n"; + errlog("Error generating a DNSCrypt provider key: %s", e.what()); + g_outputBuffer = "Error generating a DNSCrypt provider key: " + string(e.what()) + "\n"; } sodium_memzero(privateKey, sizeof(privateKey)); @@ -219,8 +219,8 @@ void setupLuaBindingsDNSCrypt(LuaContext& luaCtx, bool client) g_outputBuffer = "Provider fingerprint is: " + DNSCryptContext::getProviderFingerprint(publicKey) + "\n"; } catch (const std::exception& e) { - errlog(e.what()); - g_outputBuffer = "Error: " + string(e.what()) + "\n"; + errlog("Error getting a DNSCrypt provider fingerprint: %s", e.what()); + g_outputBuffer = "Error getting a DNSCrypt provider fingerprint: " + string(e.what()) + "\n"; } }); #endif diff --git a/pdns/dnsdistdist/dnsdist-nghttp2-in.cc b/pdns/dnsdistdist/dnsdist-nghttp2-in.cc index b22da0c397..7bd9f75855 100644 --- a/pdns/dnsdistdist/dnsdist-nghttp2-in.cc +++ b/pdns/dnsdistdist/dnsdist-nghttp2-in.cc @@ -407,7 +407,7 @@ void IncomingHTTP2Connection::handleIO() } } catch (const std::exception& e) { - infolog("Exception when processing IO for incoming DoH connection from %s: %s", d_ci.remote.toStringWithPort(), e.what()); + vinfolog("Exception when processing IO for incoming DoH connection from %s: %s", d_ci.remote.toStringWithPort(), e.what()); d_connectionDied = true; stopIO(); } diff --git a/pdns/dnsdistdist/dnsdist-nghttp2.cc b/pdns/dnsdistdist/dnsdist-nghttp2.cc index 352e864dec..163d2df092 100644 --- a/pdns/dnsdistdist/dnsdist-nghttp2.cc +++ b/pdns/dnsdistdist/dnsdist-nghttp2.cc @@ -889,31 +889,31 @@ static void dohClientThread(pdns::channel::Receiver&& receiv if (g_dohStatesDumpRequested > 0) { /* no race here, we took the lock so it can only be increased in the meantime */ --g_dohStatesDumpRequested; - errlog("Dumping the DoH client states, as requested:"); + infolog("Dumping the DoH client states, as requested:"); data.mplexer->runForAllWatchedFDs([](bool isRead, int fd, const FDMultiplexer::funcparam_t& param, struct timeval ttd) { struct timeval lnow; gettimeofday(&lnow, nullptr); if (ttd.tv_sec > 0) { - errlog("- Descriptor %d is in %s state, TTD in %d", fd, (isRead ? "read" : "write"), (ttd.tv_sec - lnow.tv_sec)); + infolog("- Descriptor %d is in %s state, TTD in %d", fd, (isRead ? "read" : "write"), (ttd.tv_sec - lnow.tv_sec)); } else { - errlog("- Descriptor %d is in %s state, no TTD set", fd, (isRead ? "read" : "write")); + infolog("- Descriptor %d is in %s state, no TTD set", fd, (isRead ? "read" : "write")); } if (param.type() == typeid(std::shared_ptr)) { auto conn = boost::any_cast>(param); - errlog(" - %s", conn->toString()); + infolog(" - %s", conn->toString()); } else if (param.type() == typeid(DoHClientThreadData*)) { - errlog(" - Worker thread pipe"); + infolog(" - Worker thread pipe"); } }); - errlog("The DoH client cache has %d active and %d idle outgoing connections cached", t_downstreamDoHConnectionsManager.getActiveCount(), t_downstreamDoHConnectionsManager.getIdleCount()); + infolog("The DoH client cache has %d active and %d idle outgoing connections cached", t_downstreamDoHConnectionsManager.getActiveCount(), t_downstreamDoHConnectionsManager.getIdleCount()); } } } catch (const std::exception& e) { - errlog("Error in outgoing DoH thread: %s", e.what()); + warnlog("Error in outgoing DoH thread: %s", e.what()); } } } diff --git a/pdns/dnsdistdist/dnsdist-secpoll.cc b/pdns/dnsdistdist/dnsdist-secpoll.cc index 7964d1490b..3bc9aeb40c 100644 --- a/pdns/dnsdistdist/dnsdist-secpoll.cc +++ b/pdns/dnsdistdist/dnsdist-secpoll.cc @@ -211,10 +211,10 @@ void doSecPoll(const std::string& suffix) int securityStatus = std::stoi(split.first); std::string securityMessage = split.second; - if(securityStatus == 1 && !g_secPollDone) { - warnlog("Polled security status of version %s at startup, no known issues reported: %s", std::string(VERSION), securityMessage); + if (securityStatus == 1 && !g_secPollDone) { + infolog("Polled security status of version %s at startup, no known issues reported: %s", std::string(VERSION), securityMessage); } - if(securityStatus == 2) { + if (securityStatus == 2) { errlog("PowerDNS DNSDist Security Update Recommended: %s", securityMessage); } else if(securityStatus == 3) { @@ -225,7 +225,7 @@ void doSecPoll(const std::string& suffix) g_secPollDone = true; return; } - catch(const std::exception& e) { + catch (const std::exception& e) { if (releaseVersion) { warnlog("Error while retrieving the security update for version %s: %s", version, e.what()); } diff --git a/pdns/dnsdistdist/doh.cc b/pdns/dnsdistdist/doh.cc index 8a9f5fef2a..128bee4126 100644 --- a/pdns/dnsdistdist/doh.cc +++ b/pdns/dnsdistdist/doh.cc @@ -1182,7 +1182,7 @@ static int doh_handler(h2o_handler_t *self, h2o_req_t *req) return 0; } catch (const std::exception& e) { - errlog("DOH Handler function failed with error %s", e.what()); + vinfolog("DOH Handler function failed with error: '%s'", e.what()); return 0; } } @@ -1264,10 +1264,10 @@ static void dnsdistclient(pdns::channel::Receiver&& receiver) processDOHQuery(std::move(dohUnit), false); } catch (const std::exception& e) { - errlog("Error while processing query received over DoH: %s", e.what()); + vinfolog("Error while processing query received over DoH: %s", e.what()); } catch (...) { - errlog("Unspecified error while processing query received over DoH"); + vinfolog("Unspecified error while processing query received over DoH"); } } } @@ -1298,7 +1298,7 @@ static void on_dnsdist(h2o_socket_t *listener, const char *err) dohUnit = std::move(*tmp); } catch (const std::exception& e) { - errlog("Error reading a DOH internal response: %s", e.what()); + warnlog("Error reading a DOH internal response: %s", e.what()); return; } diff --git a/pdns/tcpiohandler.cc b/pdns/tcpiohandler.cc index d0c82b69c9..a5d00ed73b 100644 --- a/pdns/tcpiohandler.cc +++ b/pdns/tcpiohandler.cc @@ -1309,7 +1309,7 @@ public: else if (res == GNUTLS_E_AGAIN) { return IOState::NeedWrite; } - warnlog("Warning, non-fatal error while writing to TLS connection: %s", gnutls_strerror(res)); + vinfolog("Warning, non-fatal error while writing to TLS connection: %s", gnutls_strerror(res)); } } while (pos < toWrite); @@ -1345,7 +1345,7 @@ public: else if (res == GNUTLS_E_AGAIN) { return IOState::NeedRead; } - warnlog("Warning, non-fatal error while writing to TLS connection: %s", gnutls_strerror(res)); + vinfolog("Warning, non-fatal error while writing to TLS connection: %s", gnutls_strerror(res)); } } while (pos < toRead);