Structured logging for webserver

diff --git a/pdns/webserver.cc b/pdns/webserver.cc
index 90ae04043d4b5641ca76b76f039237fa4bb22f75..7dfd5678214e30761f7fe48e79f964b1d70df554 100644 (file)
--- a/pdns/webserver.cc
+++ b/pdns/webserver.cc
@@ -41,12 +41,14 @@ json11::Json HttpRequest::json()
 {
   string err;
   if(this->body.empty()) {
-    g_log<<Logger::Debug<<logprefix<<"JSON document expected in request body, but body was empty" << endl;
+    SLOG(g_log<<Logger::Debug<<logprefix<<"JSON document expected in request body, but body was empty" << endl,
+         d_slog->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<<Logger::Debug<<logprefix<<"parsing of JSON document failed:" << err << endl;
+    SLOG(g_log<<Logger::Debug<<logprefix<<"parsing of JSON document failed:" << err << endl,
+         d_slog->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<<Logger::Error<<req->logprefix<<"HTTP API Request \"" << req->url.path << "\": Authentication failed, API Key missing in config" << endl;
+    SLOG(g_log<<Logger::Error<<req->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<<Logger::Error<<req->logprefix<<"HTTP Request \"" << req->url.path << "\": Authentication by API Key failed" << endl;
+    SLOG(g_log<<Logger::Error<<req->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<<Logger::Debug<<req->logprefix<<"HTTP Request \"" << req->url.path << "\": Web Authentication failed" << endl;
+      SLOG(g_log<<Logger::Debug<<req->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<Socket> 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<<Logger::Error<<"PDNSException while serving a connection in main webserver thread: "<<e.reason<<endl;
+    SLOG(g_log<<Logger::Error<<"PDNSException while serving a connection in main webserver thread: "<<e.reason<<endl,
+         webServer->d_slog->error(Logr::Error, e.reason, msg, "exception", Logging::Loggable("PDNSException")));
   }
   catch(std::exception &e) {
-    g_log<<Logger::Error<<"STL Exception while serving a connection in main webserver thread: "<<e.what()<<endl;
+    SLOG(g_log<<Logger::Error<<"STL Exception while serving a connection in main webserver thread: "<<e.what()<<endl,
+         webServer->d_slog->error(Logr::Error, e.what(), msg, "exception", Logging::Loggable("std::exception")));
   }
   catch(...) {
-    g_log<<Logger::Error<<"Unknown exception while serving a connection in main webserver thread"<<endl;
+    SLOG(g_log<<Logger::Error<<"Unknown exception while serving a connection in main webserver thread"<<endl,
+         webServer->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<<Logger::Debug<<req.logprefix<<"Incomplete request" << endl;
+      SLOG(g_log<<Logger::Debug<<req.logprefix<<"Incomplete request" << endl,
+           d_slog->info(Logr::Debug, "Incomplete request"));
       throw HttpBadRequestException();
     }
-
-    g_log<<Logger::Debug<<req.logprefix<<"Handling request \"" << req.url.path << "\"" << endl;
+#ifdef RECURSOR
+    auto log = req.d_slog->withValues("urlpath", Logging::Loggable(req.url.path));
+#endif
+    SLOG(g_log<<Logger::Debug<<req.logprefix<<"Handling request \"" << req.url.path << "\"" << endl,
+         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<<Logger::Debug<<req.logprefix<<"No route found for \"" << req.url.path << "\"" << endl;
+      SLOG(g_log<<Logger::Debug<<req.logprefix<<"No route found for \"" << req.url.path << "\"" << endl,
+           log->info(Logr::Debug, "No route found"));
       throw HttpNotFoundException();
     }
 
+    const string msg = "HTTP ISE Exception";
     try {
       handler(&req, &resp);
-      g_log<<Logger::Debug<<req.logprefix<<"Result for \"" << req.url.path << "\": " << resp.status << ", body length: " << resp.body.size() << endl;
+      SLOG(g_log<<Logger::Debug<<req.logprefix<<"Result for \"" << req.url.path << "\": " << resp.status << ", body length: " << resp.body.size() << endl,
+           log->info(Logr::Debug, "Result", "status", Logging::Loggable(resp.status), "bodyLength", Logging::Loggable(resp.body.size())));
     }
     catch(HttpException&) {
       throw;
     }
     catch(PDNSException &e) {
-      g_log<<Logger::Error<<req.logprefix<<"HTTP ISE for \""<< req.url.path << "\": Exception: " << e.reason << endl;
+      SLOG(g_log<<Logger::Error<<req.logprefix<<"HTTP ISE for \""<< req.url.path << "\": Exception: " << e.reason << endl,
+           log->error(Logr::Error, e.reason, msg, "exception", Logging::Loggable("PDNSException")));
       throw HttpInternalServerErrorException();
     }
     catch(std::exception &e) {
-      g_log<<Logger::Error<<req.logprefix<<"HTTP ISE for \""<< req.url.path << "\": STL Exception: " << e.what() << endl;
+      SLOG(g_log<<Logger::Error<<req.logprefix<<"HTTP ISE for \""<< req.url.path << "\": STL Exception: " << e.what() << endl,
+           log->error(Logr::Error, e.what(), msg, "exception", Logging::Loggable("std::exception")));
       throw HttpInternalServerErrorException();
     }
     catch(...) {
-      g_log<<Logger::Error<<req.logprefix<<"HTTP ISE for \""<< req.url.path << "\": Unknown Exception" << endl;
+      SLOG(g_log<<Logger::Error<<req.logprefix<<"HTTP ISE for \""<< req.url.path << "\": Unknown Exception" << endl,
+           log->info(Logr::Error, msg));
       throw HttpInternalServerErrorException();
     }
   }
   catch(HttpException &e) {
     resp = e.response();
     // TODO rm this logline?
-    g_log<<Logger::Debug<<req.logprefix<<"Error result for \"" << req.url.path << "\": " << resp.status << endl;
+    SLOG(g_log<<Logger::Debug<<req.logprefix<<"Error result for \"" << req.url.path << "\": " << resp.status << endl,
+         d_slog->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<YaHTTP::strstr_map_t::const_iterator>::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<<Logger::Notice<<logprefix<<"Request details:"<<endl;
-
-    bool first = true;
-    for (const auto& r : req.getvars) {
-      if (first) {
-        first = false;
-        g_log<<Logger::Notice<<logprefix<<" GET params:"<<endl;
+#ifdef RECURSOR
+    if (!g_slogStructured) {
+#endif
+      auto logprefix = req.logprefix;
+      g_log<<Logger::Notice<<logprefix<<"Request details:"<<endl;
+
+      bool first = true;
+      for (const auto& r : req.getvars) {
+        if (first) {
+          first = false;
+          g_log<<Logger::Notice<<logprefix<<" GET params:"<<endl;
+        }
+        g_log<<Logger::Notice<<logprefix<<"  "<<r.first<<": "<<r.second<<endl;
       }
-      g_log<<Logger::Notice<<logprefix<<"  "<<r.first<<": "<<r.second<<endl;
-    }
 
-    first = true;
-    for (const auto& r : req.postvars) {
-      if (first) {
-        first = false;
-        g_log<<Logger::Notice<<logprefix<<" POST params:"<<endl;
+      first = true;
+      for (const auto& r : req.postvars) {
+        if (first) {
+          first = false;
+          g_log<<Logger::Notice<<logprefix<<" POST params:"<<endl;
+        }
+        g_log<<Logger::Notice<<logprefix<<"  "<<r.first<<": "<<r.second<<endl;
       }
-      g_log<<Logger::Notice<<logprefix<<"  "<<r.first<<": "<<r.second<<endl;
-    }
 
-    first = true;
-    for (const auto& h : req.headers) {
-      if (first) {
-        first = false;
-        g_log<<Logger::Notice<<logprefix<<" Headers:"<<endl;
+      first = true;
+      for (const auto& h : req.headers) {
+        if (first) {
+          first = false;
+          g_log<<Logger::Notice<<logprefix<<" Headers:"<<endl;
+        }
+        g_log<<Logger::Notice<<logprefix<<"  "<<h.first<<": "<<h.second<<endl;
       }
-      g_log<<Logger::Notice<<logprefix<<"  "<<h.first<<": "<<h.second<<endl;
-    }
 
-    if (req.body.empty()) {
-      g_log<<Logger::Notice<<logprefix<<" No body"<<endl;
-    } else {
-      g_log<<Logger::Notice<<logprefix<<" Full body: "<<endl;
-      g_log<<Logger::Notice<<logprefix<<"  "<<req.body<<endl;
+      if (req.body.empty()) {
+        g_log<<Logger::Notice<<logprefix<<" No body"<<endl;
+      } else {
+        g_log<<Logger::Notice<<logprefix<<" Full body: "<<endl;
+        g_log<<Logger::Notice<<logprefix<<"  "<<req.body<<endl;
+      }
+#ifdef RECURSOR
     }
+    else {
+      req.d_slog->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<<Logger::Notice<<logprefix<<"Response details:"<<endl;
-    bool first = true;
-    for (const auto& h : resp.headers) {
-      if (first) {
-        first = false;
-        g_log<<Logger::Notice<<logprefix<<" Headers:"<<endl;
+#ifdef RECURSOR
+    if (!g_slogStructured) {
+#endif
+      g_log<<Logger::Notice<<logprefix<<"Response details:"<<endl;
+      bool first = true;
+      for (const auto& h : resp.headers) {
+        if (first) {
+          first = false;
+          g_log<<Logger::Notice<<logprefix<<" Headers:"<<endl;
+        }
+        g_log<<Logger::Notice<<logprefix<<"  "<<h.first<<": "<<h.second<<endl;
+      }
+      if (resp.body.empty()) {
+        g_log<<Logger::Notice<<logprefix<<" No body"<<endl;
+      } else {
+        g_log<<Logger::Notice<<logprefix<<" Full body: "<<endl;
+        g_log<<Logger::Notice<<logprefix<<"  "<<resp.body<<endl;
       }
-      g_log<<Logger::Notice<<logprefix<<"  "<<h.first<<": "<<h.second<<endl;
+#ifdef RECURSOR
     }
-    if (resp.body.empty()) {
-      g_log<<Logger::Notice<<logprefix<<" No body"<<endl;
-    } else {
-      g_log<<Logger::Notice<<logprefix<<" Full body: "<<endl;
-      g_log<<Logger::Notice<<logprefix<<"  "<<resp.body<<endl;
+    else {
+      resp.d_slog->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<Socket>& 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<Socket>& client) const {
       yarl.finalize();
     } catch (YaHTTP::ParseError &e) {
       // request stays incomplete
-      g_log<<Logger::Warning<<logprefix<<"Unable to parse request: "<<e.what()<<endl;
+      SLOG(g_log<<Logger::Warning<<logprefix<<"Unable to parse request: "<<e.what()<<endl,
+           d_slog->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<Socket>& client) const {
     client->writenWithTimeout(reply.c_str(), reply.size(), timeout);
   }
   catch(PDNSException &e) {
-    g_log<<Logger::Error<<logprefix<<"HTTP Exception: "<<e.reason<<endl;
+    SLOG(g_log<<Logger::Error<<logprefix<<"HTTP Exception: "<<e.reason<<endl,
+         d_slog->error(Logr::Error, e.reason, "HTTP Exception", "exception", Logging::Loggable("PDNSException")));
   }
   catch(std::exception &e) {
     if(strstr(e.what(), "timeout")==nullptr)
-      g_log<<Logger::Error<<logprefix<<"HTTP STL Exception: "<<e.what()<<endl;
+      SLOG(g_log<<Logger::Error<<logprefix<<"HTTP STL Exception: "<<e.what()<<endl,
+           d_slog->error(Logr::Error, e.what(), "HTTP Exception", "exception", Logging::Loggable("std::exception")));
   }
   catch(...) {
-    g_log<<Logger::Error<<logprefix<<"Unknown exception"<<endl;
+    SLOG(g_log<<Logger::Error<<logprefix<<"Unknown exception"<<endl,
+         d_slog->info(Logr::Error, "HTTP Exception"));
   }
 
   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,
+         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())));
   }
 }
 
@@ -471,10 +547,12 @@ void WebServer::bind()
 {
   try {
     d_server = createServer();
-    g_log<<Logger::Warning<<d_logprefix<<"Listening for HTTP requests on "<<d_server->d_local.toStringWithPort()<<endl;
+    SLOG(g_log<<Logger::Warning<<d_logprefix<<"Listening for HTTP requests on "<<d_server->d_local.toStringWithPort()<<endl,
+         d_slog->info(Logr::Info, "Listening for HTTP requests", "addres", Logging::Loggable(d_server->d_local)));
   }
   catch(NetworkError &e) {
-    g_log<<Logger::Error<<d_logprefix<<"Listening on HTTP socket failed: "<<e.what()<<endl;
+    SLOG(g_log<<Logger::Error<<d_logprefix<<"Listening on HTTP socket failed: "<<e.what()<<endl,
+         d_slog->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<<Logger::Error<<d_logprefix<<"PDNSException while accepting a connection in main webserver thread: "<<e.reason<<endl;
+        SLOG(g_log<<Logger::Error<<d_logprefix<<"PDNSException while accepting a connection in main webserver thread: "<<e.reason<<endl,
+             d_slog->error(Logr::Error, e.reason, acceptmsg, Logging::Loggable("PDNSException")));
       }
       catch(std::exception &e) {
-        g_log<<Logger::Error<<d_logprefix<<"STL Exception while accepting a connection in main webserver thread: "<<e.what()<<endl;
+        SLOG(g_log<<Logger::Error<<d_logprefix<<"STL Exception while accepting a connection in main webserver thread: "<<e.what()<<endl,
+             d_slog->error(Logr::Error, e.what(), acceptmsg, Logging::Loggable("std::exception")));
       }
       catch(...) {
-        g_log<<Logger::Error<<d_logprefix<<"Unknown exception while accepting a connection in main webserver thread"<<endl;
+        SLOG(g_log<<Logger::Error<<d_logprefix<<"Unknown exception while accepting a connection in main webserver thread"<<endl,
+             d_slog->info(Logr::Error, msg));
       }
     }
   }
   catch(PDNSException &e) {
-    g_log<<Logger::Error<<d_logprefix<<"PDNSException in main webserver thread: "<<e.reason<<endl;
+    SLOG(g_log<<Logger::Error<<d_logprefix<<"PDNSException in main webserver thread: "<<e.reason<<endl,
+         d_slog->error(Logr::Error, e.reason, msg, Logging::Loggable("PDNSException")));
   }
   catch(std::exception &e) {
-    g_log<<Logger::Error<<d_logprefix<<"STL Exception in main webserver thread: "<<e.what()<<endl;
+    SLOG(g_log<<Logger::Error<<d_logprefix<<"STL Exception in main webserver thread: "<<e.what()<<endl,
+         d_slog->error(Logr::Error, e.what(), msg, Logging::Loggable("std::exception")));
   }
   catch(...) {
-    g_log<<Logger::Error<<d_logprefix<<"Unknown exception in main webserver thread"<<endl;
+    SLOG(g_log<<Logger::Error<<d_logprefix<<"Unknown exception in main webserver thread"<<endl,
+         d_slog->info(Logr::Error, msg));
   }
   _exit(1);
 }

diff --git a/pdns/webserver.hh b/pdns/webserver.hh
index 16e6df9fbc91757bed87389270bdb83e533ec7e0..3859117517dfb9ecfd524b8544edc64fc298f1fd 100644 (file)
--- 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<Logr::Logger> 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<Logr::Logger> 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<CredentialsHolder>(std::string(apikey), hashPlaintext);
@@ -232,6 +256,10 @@ public:
     return d_loglevel;
   };
 
+#ifdef RECURSOR
+  std::shared_ptr<Logr::Logger> 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 688718b6958bca3111a107adde6f0f34eb29c0d7..7d018010a8659afd3e6bc0ace0e0b548017f5ea9 100644 (file)
--- 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<AsyncWebServer>(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<Socket> 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<Socket> client) const
       g_networkTimeoutMsec / 1000, static_cast<suseconds_t>(g_networkTimeoutMsec) % 1000 * 1000
     };
     std::shared_ptr<TLSCtx> tlsCtx{nullptr};
+    if (d_loglevel > WebServer::LogLevel::None) {
+      client->getRemote(remote);
+    }
     auto handler = std::make_shared<TCPIOHandler>("", false, client->releaseHandle(), timeout, tlsCtx, time(nullptr));
 
     PacketBuffer data;
@@ -1393,11 +1408,8 @@ void AsyncWebServer::serveConnection(std::shared_ptr<Socket> 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<Socket> 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())));
   }
 }