From: Otto Moerbeek Date: Fri, 3 Jun 2022 15:00:39 +0000 (+0200) Subject: Structured logging for webserver X-Git-Tag: auth-4.8.0-alpha0~48^2~2 X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=6c88989a9191165381d72ada5d5aadf2b3f3e20a;p=thirdparty%2Fpdns.git Structured logging for webserver --- diff --git a/pdns/webserver.cc b/pdns/webserver.cc index 90ae04043d..7dfd567821 100644 --- a/pdns/webserver.cc +++ b/pdns/webserver.cc @@ -41,12 +41,14 @@ json11::Json HttpRequest::json() { string err; if(this->body.empty()) { - g_log<info(Logr::Debug, "JSON document expected in request body, but body was empty")); throw HttpBadRequestException(); } json11::Json doc = json11::Json::parse(this->body, err); if (doc.is_null()) { - g_log<error(Logr::Debug, err, "parsing of JSON document failed")); throw HttpBadRequestException(); } return doc; @@ -164,7 +166,8 @@ void WebServer::apiWrapper(const WebServer::HandlerFunction& handler, HttpReques resp->headers["access-control-allow-origin"] = "*"; if (!d_apikey) { - g_log<logprefix<<"HTTP API Request \"" << req->url.path << "\": Authentication failed, API Key missing in config" << endl; + SLOG(g_log<logprefix<<"HTTP API Request \"" << req->url.path << "\": Authentication failed, API Key missing in config" << endl, + d_slog->info(Logr::Error, "HTTP API Request: Authentication failed, API Key missing in config", "urlpath", Logging::Loggable(req->url.path))); throw HttpUnauthorizedException("X-API-Key"); } @@ -179,7 +182,8 @@ void WebServer::apiWrapper(const WebServer::HandlerFunction& handler, HttpReques } if (!auth_ok) { - g_log<logprefix<<"HTTP Request \"" << req->url.path << "\": Authentication by API Key failed" << endl; + SLOG(g_log<logprefix<<"HTTP Request \"" << req->url.path << "\": Authentication by API Key failed" << endl, + d_slog->info(Logr::Error, "HTTP Request: Authentication by API Key failed", "urlpath", Logging::Loggable(req->url.path))); throw HttpUnauthorizedException("X-API-Key"); } @@ -218,7 +222,8 @@ void WebServer::webWrapper(const WebServer::HandlerFunction& handler, HttpReques if (d_webserverPassword) { bool auth_ok = req->compareAuthorization(*d_webserverPassword); if (!auth_ok) { - g_log<logprefix<<"HTTP Request \"" << req->url.path << "\": Web Authentication failed" << endl; + SLOG(g_log<logprefix<<"HTTP Request \"" << req->url.path << "\": Web Authentication failed" << endl, + d_slog->info(Logr::Debug, "HTTP Request: Web Authentication failed", "urlpath", Logging::Loggable(req->url.path))); throw HttpUnauthorizedException("Basic"); } } @@ -233,17 +238,21 @@ void WebServer::registerWebHandler(const string& url, const HandlerFunction& han static void *WebServerConnectionThreadStart(const WebServer* webServer, std::shared_ptr client) { setThreadName("pdns-r/webhndlr"); + const std::string msg = "Exception while serving a connection in main webserver thread"; try { webServer->serveConnection(client); } catch(PDNSException &e) { - g_log<d_slog->error(Logr::Error, e.reason, msg, "exception", Logging::Loggable("PDNSException"))); } catch(std::exception &e) { - g_log<d_slog->error(Logr::Error, e.what(), msg, "exception", Logging::Loggable("std::exception"))); } catch(...) { - g_log<d_slog->info(Logr::Error, msg)); } return nullptr; } @@ -255,11 +264,15 @@ void WebServer::handleRequest(HttpRequest& req, HttpResponse& resp) const try { if (!req.complete) { - g_log<info(Logr::Debug, "Incomplete request")); throw HttpBadRequestException(); } - - g_log<withValues("urlpath", Logging::Loggable(req.url.path)); +#endif + SLOG(g_log<info(Logr::Debug, "Handling request")); YaHTTP::strstr_map_t::iterator header; @@ -278,34 +291,41 @@ void WebServer::handleRequest(HttpRequest& req, HttpResponse& resp) const YaHTTP::THandlerFunction handler; if (!YaHTTP::Router::Route(&req, handler)) { - g_log<info(Logr::Debug, "No route found")); throw HttpNotFoundException(); } + const string msg = "HTTP ISE Exception"; try { handler(&req, &resp); - g_log<info(Logr::Debug, "Result", "status", Logging::Loggable(resp.status), "bodyLength", Logging::Loggable(resp.body.size()))); } catch(HttpException&) { throw; } catch(PDNSException &e) { - g_log<error(Logr::Error, e.reason, msg, "exception", Logging::Loggable("PDNSException"))); throw HttpInternalServerErrorException(); } catch(std::exception &e) { - g_log<error(Logr::Error, e.what(), msg, "exception", Logging::Loggable("std::exception"))); throw HttpInternalServerErrorException(); } catch(...) { - g_log<info(Logr::Error, msg)); throw HttpInternalServerErrorException(); } } catch(HttpException &e) { resp = e.response(); // TODO rm this logline? - g_log<error(Logr::Debug, resp.status, "Error result", "urlpath", Logging::Loggable(req.url.path))); string what = YaHTTP::Utility::status2text(resp.status); if (req.accept_json) { resp.headers["Content-Type"] = "application/json"; @@ -332,72 +352,121 @@ void WebServer::handleRequest(HttpRequest& req, HttpResponse& resp) const } } +#ifdef RECURSOR +// Helper to log key-value maps used by YaHTTP +template<> +std::string Logging::IterLoggable::to_string() const +{ + std::ostringstream oss; + bool first = true; + for (auto i = _t1; i != _t2; i++) { + if (!first) { + oss << '\n'; + } + else { + first = false; + } + oss << i->first << ": " << i->second; + } + return oss.str(); +} +#endif + void WebServer::logRequest(const HttpRequest& req, const ComboAddress& remote) const { if (d_loglevel >= WebServer::LogLevel::Detailed) { - auto logprefix = req.logprefix; - g_log<info(Logr::Info, "Request details", "getParams", Logging::IterLoggable(req.getvars.cbegin(), req.getvars.cend()), + "postParams", Logging::IterLoggable(req.postvars.cbegin(), req.postvars.cend()), + "body", Logging::Loggable(req.body), + "address", Logging::Loggable(remote)); + } +#endif } } void WebServer::logResponse(const HttpResponse& resp, const ComboAddress& remote, const string& logprefix) const { if (d_loglevel >= WebServer::LogLevel::Detailed) { - g_log<info(Logr::Info, "Response details", "headers", Logging::IterLoggable(resp.headers.cbegin(), resp.headers.cend()), + "body", Logging::Loggable(resp.body)); } +#endif } } void WebServer::serveConnection(const std::shared_ptr& client) const { - const string logprefix = d_logprefix + to_string(getUniqueID()) + " "; + const auto unique = getUniqueID(); + const string logprefix = d_logprefix + to_string(unique) + " "; HttpRequest req(logprefix); + HttpResponse resp; +#ifdef RECURSOR + auto log = d_slog->withValues("uniqueid", Logging::Loggable(to_string(unique))); + req.setSLog(log); + resp.setSLog(log); +#endif resp.max_response_size=d_maxbodysize; ComboAddress remote; string reply; @@ -425,10 +494,11 @@ void WebServer::serveConnection(const std::shared_ptr& client) const { yarl.finalize(); } catch (YaHTTP::ParseError &e) { // request stays incomplete - g_log<error(Logr::Warning, e.what(), "Unable to parse request")); } - if (d_loglevel >= WebServer::LogLevel::None) { + if (d_loglevel > WebServer::LogLevel::None) { client->getRemote(remote); } @@ -444,18 +514,24 @@ void WebServer::serveConnection(const std::shared_ptr& client) const { client->writenWithTimeout(reply.c_str(), reply.size(), timeout); } catch(PDNSException &e) { - g_log<error(Logr::Error, e.reason, "HTTP Exception", "exception", Logging::Loggable("PDNSException"))); } catch(std::exception &e) { if(strstr(e.what(), "timeout")==nullptr) - g_log<error(Logr::Error, e.what(), "HTTP Exception", "exception", Logging::Loggable("std::exception"))); } catch(...) { - g_log<info(Logr::Error, "HTTP Exception")); } if (d_loglevel >= WebServer::LogLevel::Normal) { - g_log<info(Logr::Info, "Request", "remote", Logging::Loggable(remote), "method", Logging::Loggable(req.method), + "urlpath", Logging::Loggable(req.url.path), "HTTPVersion", Logging::Loggable(req.versionStr(req.version)), + "status", Logging::Loggable(resp.status), "respsize", Logging::Loggable(reply.size()))); } } @@ -471,10 +547,12 @@ void WebServer::bind() { try { d_server = createServer(); - g_log<d_local.toStringWithPort()<d_local.toStringWithPort()<info(Logr::Info, "Listening for HTTP requests", "addres", Logging::Loggable(d_server->d_local))); } catch(NetworkError &e) { - g_log<error(Logr::Error, e.what(), "Listening on HTTP socket failed", "exception", Logging::Loggable("NetworkError"))); d_server = nullptr; } } @@ -483,8 +561,10 @@ void WebServer::go() { if(!d_server) return; + const string msg = "Exception in main webserver thread"; try { while(true) { + const string acceptmsg = "Exception while accepting a connection in main webserver thread"; try { auto client = d_server->accept(); if (!client) { @@ -500,24 +580,30 @@ void WebServer::go() } } catch(PDNSException &e) { - g_log<error(Logr::Error, e.reason, acceptmsg, Logging::Loggable("PDNSException"))); } catch(std::exception &e) { - g_log<error(Logr::Error, e.what(), acceptmsg, Logging::Loggable("std::exception"))); } catch(...) { - g_log<info(Logr::Error, msg)); } } } catch(PDNSException &e) { - g_log<error(Logr::Error, e.reason, msg, Logging::Loggable("PDNSException"))); } catch(std::exception &e) { - g_log<error(Logr::Error, e.what(), msg, Logging::Loggable("std::exception"))); } catch(...) { - g_log<info(Logr::Error, msg)); } _exit(1); } diff --git a/pdns/webserver.hh b/pdns/webserver.hh index 16e6df9fbc..3859117517 100644 --- a/pdns/webserver.hh +++ b/pdns/webserver.hh @@ -31,6 +31,7 @@ #include "credentials.hh" #include "namespaces.hh" #include "sstuff.hh" +#include "logging.hh" class HttpRequest : public YaHTTP::Request { public: @@ -48,6 +49,14 @@ public: bool compareAuthorization(const CredentialsHolder& expectedCredentials) const; bool compareHeader(const string &header_name, const CredentialsHolder& expectedCredentials) const; bool compareHeader(const string &header_name, const string &expected_value) const; + +#ifdef RECURSOR + void setSLog(Logr::log_t log) + { + d_slog = log; + } + std::shared_ptr d_slog; +#endif }; class HttpResponse: public YaHTTP::Response { @@ -61,6 +70,14 @@ public: void setJsonBody(const json11::Json& document); void setErrorResult(const std::string& message, const int status); void setSuccessResult(const std::string& message, const int status = 200); + +#ifdef RECURSOR + void setSLog(Logr::log_t log) + { + d_slog = log; + } + std::shared_ptr d_slog; +#endif }; @@ -163,6 +180,13 @@ public: WebServer(string listenaddress, int port); virtual ~WebServer() { }; +#ifdef RECURSOR + void setSLog(Logr::log_t log) + { + d_slog = log; + } +#endif + void setApiKey(const string &apikey, bool hashPlaintext) { if (!apikey.empty()) { d_apikey = make_unique(std::string(apikey), hashPlaintext); @@ -232,6 +256,10 @@ public: return d_loglevel; }; +#ifdef RECURSOR + std::shared_ptr d_slog; +#endif + protected: void registerBareHandler(const string& url, const HandlerFunction& handler); void logRequest(const HttpRequest& req, const ComboAddress& remote) const; diff --git a/pdns/ws-recursor.cc b/pdns/ws-recursor.cc index 688718b695..7d018010a8 100644 --- a/pdns/ws-recursor.cc +++ b/pdns/ws-recursor.cc @@ -39,6 +39,7 @@ #include "webserver.hh" #include "ws-api.hh" #include "logger.hh" +#include "logging.hh" #include "rec-lua-conf.hh" #include "rpzloader.hh" #include "uuid-utils.hh" @@ -1161,7 +1162,8 @@ static void validatePrometheusMetrics() MetricDefinition metricDetails; if (!s_metricDefinitions.getMetricDetails(metricName, metricDetails)) { - g_log << Logger::Debug << "{ \"" << metricName << "\", MetricDefinition(PrometheusMetricType::counter, \"\")}," << endl; + SLOG(g_log << Logger::Debug << "{ \"" << metricName << "\", MetricDefinition(PrometheusMetricType::counter, \"\")}," << endl, + g_slog->ingo(Logr::Debug, "{ \"" << metricName << "\", MetricDefinition(PrometheusMetricType::counter, \"\")},")); } } } @@ -1176,6 +1178,7 @@ RecursorWebServer::RecursorWebServer(FDMultiplexer* fdm) #endif d_ws = make_unique(fdm, arg()["webserver-address"], arg().asNum("webserver-port")); + d_ws->setSLog(g_slog->withName("webserver")); d_ws->setApiKey(arg()["api-key"], arg().mustDo("webserver-hash-plaintext-credentials")); d_ws->setPassword(arg()["webserver-password"], arg().mustDo("webserver-hash-plaintext-credentials")); @@ -1329,11 +1332,13 @@ void AsyncServerNewConnectionMT(void* p) } catch (NetworkError& e) { // we're running in a shared process/thread, so can't just terminate/abort. - g_log << Logger::Warning << "Network error in web thread: " << e.what() << endl; + SLOG(g_log << Logger::Warning << "Network error in web thread: " << e.what() << endl, + g_slog->withName("webserver")->error(Logr::Warning, e.what(), "Exception in web tread", Logging::Loggable("NetworkError"))); return; } catch (...) { - g_log << Logger::Warning << "Unknown error in web thread" << endl; + SLOG(g_log << Logger::Warning << "Unknown error in web thread" << endl, + g_slog->withName("webserver")->info(Logr::Warning, "Exception in web tread")); return; } @@ -1357,10 +1362,17 @@ void AsyncWebServer::serveConnection(std::shared_ptr client) const return; } - const string logprefix = d_logprefix + to_string(getUniqueID()) + " "; + const auto unique = getUniqueID(); + const string logprefix = d_logprefix + to_string(unique) + " "; HttpRequest req(logprefix); HttpResponse resp; +#ifdef RECURSOR + auto log = d_slog->withValues("uniqueid", Logging::Loggable(to_string(unique))); + req.setSLog(log); + resp.setSLog(log); +#endif + ComboAddress remote; PacketBuffer reply; @@ -1374,6 +1386,9 @@ void AsyncWebServer::serveConnection(std::shared_ptr client) const g_networkTimeoutMsec / 1000, static_cast(g_networkTimeoutMsec) % 1000 * 1000 }; std::shared_ptr tlsCtx{nullptr}; + if (d_loglevel > WebServer::LogLevel::None) { + client->getRemote(remote); + } auto handler = std::make_shared("", false, client->releaseHandle(), timeout, tlsCtx, time(nullptr)); PacketBuffer data; @@ -1393,11 +1408,8 @@ void AsyncWebServer::serveConnection(std::shared_ptr client) const } catch (YaHTTP::ParseError& e) { // request stays incomplete - g_log << Logger::Warning << logprefix << "Unable to parse request: " << e.what() << endl; - } - - if (d_loglevel >= WebServer::LogLevel::None) { - client->getRemote(remote); + SLOG(g_log << Logger::Warning << logprefix << "Unable to parse request: " << e.what() << endl, + req.d_slog->error(Logr::Warning, e.what(), "Unable to parse request")); } logRequest(req, remote); @@ -1412,23 +1424,29 @@ void AsyncWebServer::serveConnection(std::shared_ptr client) const // now send the reply if (asendtcp(reply, handler) != LWResult::Result::Success || reply.empty()) { - g_log << Logger::Error << logprefix << "Failed sending reply to HTTP client" << endl; + SLOG(g_log << Logger::Error << logprefix << "Failed sending reply to HTTP client" << endl, + req.d_slog->info(Logr::Error, "Failed sending reply to HTTP client")); } handler->close(); // needed to signal "done" to client } catch (PDNSException& e) { - g_log << Logger::Error << logprefix << "Exception: " << e.reason << endl; + SLOG(g_log << Logger::Error << logprefix << "Exception: " << e.reason << endl, + req.d_slog->error(Logr::Error, e.reason, "Exception handing request", "exception", Logging::Loggable("PDNSException"))); } catch (std::exception& e) { if (strstr(e.what(), "timeout") == 0) - g_log << Logger::Error << logprefix << "STL Exception: " << e.what() << endl; + SLOG(g_log << Logger::Error << logprefix << "STL Exception: " << e.what() << endl, + req.d_slog->error(Logr::Error, e.what(), "Exception handing request", "exception", Logging::Loggable("std::exception"))); } catch (...) { - g_log << Logger::Error << logprefix << "Unknown exception" << endl; - } + SLOG(g_log << Logger::Error << logprefix << "Unknown exception" << endl, + req.d_slog->error(Logr::Error, "Exception handing request")) } if (d_loglevel >= WebServer::LogLevel::Normal) { - g_log << Logger::Notice << logprefix << remote << " \"" << req.method << " " << req.url.path << " HTTP/" << req.versionStr(req.version) << "\" " << resp.status << " " << reply.size() << endl; + SLOG(g_log << Logger::Notice << logprefix << remote << " \"" << req.method << " " << req.url.path << " HTTP/" << req.versionStr(req.version) << "\" " << resp.status << " " << reply.size() << endl, + req.d_slog->info(Logr::Info, "Request", "remote", Logging::Loggable(remote), "method", Logging::Loggable(req.method), + "urlpath", Logging::Loggable(req.url.path), "HTTPVersion", Logging::Loggable(req.versionStr(req.version)), + "status", Logging::Loggable(resp.status), "respsize", Logging::Loggable(reply.size()))); } }