dnsdist: Structured logging for KVS

Signed-off-by: Remi Gacogne <remi.gacogne@powerdns.com>

diff --git a/pdns/dnsdistdist/dnsdist-kvs.cc b/pdns/dnsdistdist/dnsdist-kvs.cc
index e8084566dc480bc77ee3fa8fa6968d7d7ea44305..ca54675c78e8e0674ed87e74ae700b6c7a3f59a5 100644 (file)
--- a/pdns/dnsdistdist/dnsdist-kvs.cc
+++ b/pdns/dnsdistdist/dnsdist-kvs.cc
@@ -81,6 +81,10 @@ std::vector<std::string> KeyValueLookupKeySuffix::getKeys(const DNSName& qname)
 }
 
 #ifdef HAVE_LMDB
+std::shared_ptr<const Logr::Logger> LMDBKVStore::getLogger() const
+{
+  return dnsdist::logging::getTopLogger()->withName("lmdb-key-value-store")->withValues("lmdb.filename", Logging::Loggable(d_fname), "lmdb.database", Logging::Loggable(d_dbName));
+}
 
 bool LMDBKVStore::getValue(const std::string& key, std::string& value)
 {
@@ -97,7 +101,8 @@ bool LMDBKVStore::getValue(const std::string& key, std::string& value)
     }
   }
   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());
+    VERBOSESLOG(infolog("Error while looking up key '%s' from LMDB file '%s', database '%s': %s", key, d_fname, d_dbName, e.what()),
+                getLogger()->error(Logr::Info, e.what(), "Error while looking up key", "lmdb.key", Logging::Loggable(key)));
   }
   return false;
 }
@@ -116,7 +121,8 @@ bool LMDBKVStore::keyExists(const std::string& key)
     }
   }
   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());
+    VERBOSESLOG(infolog("Error while looking up key '%s' from LMDB file '%s', database '%s': %s", key, d_fname, d_dbName, e.what()),
+                getLogger()->error(Logr::Info, e.what(), "Error while looking up key", "lmdb.key", Logging::Loggable(key)));
   }
   return false;
 }
@@ -164,7 +170,8 @@ bool LMDBKVStore::getRangeValue(const std::string& key, std::string& value)
     }
   }
   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());
+    VERBOSESLOG(infolog("Error while looking up a range from LMDB file '%s', database '%s': %s", d_fname, d_dbName, e.what()),
+                getLogger()->error(Logr::Info, e.what(), "Error while looking up a range", "lmdb.key", Logging::Loggable(key)));
   }
   return false;
 }
@@ -172,6 +179,10 @@ bool LMDBKVStore::getRangeValue(const std::string& key, std::string& value)
 #endif /* HAVE_LMDB */
 
 #ifdef HAVE_CDB
+std::shared_ptr<const Logr::Logger> CDBKVStore::getLogger() const
+{
+  return dnsdist::logging::getTopLogger()->withName("cdb-key-value-store")->withValues("cdb.filename", Logging::Loggable(d_fname));
+}
 
 CDBKVStore::CDBKVStore(const std::string& fname, time_t refreshDelay): d_fname(fname), d_refreshDelay(refreshDelay)
 {
@@ -200,12 +211,14 @@ bool CDBKVStore::reload(const struct stat& st)
 
 bool CDBKVStore::reload()
 {
-  struct stat st;
+  struct stat st{};
   if (stat(d_fname.c_str(), &st) == 0) {
     return reload(st);
   }
   else {
-    warnlog("Error while retrieving the last modification time of CDB database '%s': %s", d_fname, stringerror());
+    int savederrno = errno;
+    SLOG(warnlog("Error while retrieving the last modification time of CDB database '%s': %s", d_fname, stringerror(savederrno)),
+         getLogger()->error(Logr::Warning, savederrno, "Error while retrieving the last modification time of the database"));
     return false;
   }
 }
@@ -218,14 +231,16 @@ void CDBKVStore::refreshDBIfNeeded(time_t now)
   }
 
   try {
-    struct stat st;
+    struct stat st{};
     if (stat(d_fname.c_str(), &st) == 0) {
       if (st.st_mtime > d_mtime) {
         reload(st);
       }
     }
     else {
-      warnlog("Error while retrieving the last modification time of CDB database '%s': %s", d_fname, stringerror());
+      int savederrno = errno;
+      SLOG(warnlog("Error while retrieving the last modification time of CDB database '%s': %s", d_fname, stringerror(savederrno)),
+           getLogger()->error(Logr::Warning, savederrno, "Error while retrieving the last modification time of the database"));
     }
     d_nextCheck = now + d_refreshDelay;
     d_refreshing.clear();
@@ -253,7 +268,8 @@ bool CDBKVStore::getValue(const std::string& key, std::string& value)
     }
   }
   catch (const std::exception& e) {
-    vinfolog("Error while looking up key '%s' from CDB file '%s': %s", key, d_fname, e.what());
+    VERBOSESLOG(infolog("Error while looking up key '%s' from CDB file '%s': %s", key, d_fname, e.what()),
+                getLogger()->error(Logr::Info, e.what(), "Error while looking up a key", "cdb.key", Logging::Loggable(key)));
   }
   return false;
 }
@@ -277,7 +293,8 @@ bool CDBKVStore::keyExists(const std::string& key)
     }
   }
   catch (const std::exception& e) {
-    vinfolog("Error while looking up key '%s' from CDB file '%s': %s", key, d_fname, e.what());
+    VERBOSESLOG(infolog("Error while looking up key '%s' from CDB file '%s': %s", key, d_fname, e.what()),
+                getLogger()->error(Logr::Info, e.what(), "Error while looking up a key", "cdb.key", Logging::Loggable(key)));
   }
   return false;
 }

diff --git a/pdns/dnsdistdist/dnsdist-kvs.hh b/pdns/dnsdistdist/dnsdist-kvs.hh
index ad8c11c3a3d24a03b6f201016cef50b4c6052cb3..42a9052577db8cc9a4b70494a1c4026fedb36ab9 100644 (file)
--- a/pdns/dnsdistdist/dnsdist-kvs.hh
+++ b/pdns/dnsdistdist/dnsdist-kvs.hh
@@ -21,7 +21,9 @@
  */
 #pragma once
 
+#include <memory>
 #include "dnsdist.hh"
+#include "logr.hh"
 
 class KeyValueLookupKey
 {
@@ -186,6 +188,8 @@ public:
   bool getRangeValue(const std::string& key, std::string& value) override;
 
 private:
+  std::shared_ptr<const Logr::Logger> getLogger() const;
+
   std::shared_ptr<MDBEnv> d_env;
   MDBDbi d_dbi;
   std::string d_fname;
@@ -209,6 +213,7 @@ public:
   bool reload() override;
 
 private:
+  std::shared_ptr<const Logr::Logger> getLogger() const;
   void refreshDBIfNeeded(time_t now);
   bool reload(const struct stat& st);