feat(log): add extensible logger implementation

include/dct/distributors/dist_gkey.hpp

@@ -234,15 +234,15 @@ struct DistGKey {
         if (m_init) return;
 
         if (! m_keyMaker) {
-            // print("DistGKey::updateSigningKey new SP for member {}\n", pubCert.name() );
+            dct::log(L_TRACE)("DistGKey::updateSigningKey new SP for member {}", pubCert.name() );
              publishMembershipReq();
              return;
         }
         // if keymaker is rekeyed it needs to change epoch
         if (m_kmpri(m_tp) <= 0) std::runtime_error("DistGKey::updateSigningKey keymaker capability change indicates bad signing chain");
         m_kmtp = m_tp;
         ++m_KMepoch;
-        // print("DistGKey::updateSigningKey new SP for keymaker {} epoch = {}\n", pubCert.name(), m_KMepoch);
+        dct::log(L_TRACE)("DistGKey::updateSigningKey new SP for keymaker {}, epoch = {}", pubCert.name(), m_KMepoch);
         makeGKey(); // redo this so gklists are under the new signing cert
     }
 
@@ -268,7 +268,7 @@ struct DistGKey {
 
         const auto& tp = p.signer();    // thumbprint of this GKeyList's signer
         if (!m_certs.contains(tp) || m_kmpri(tp) <= 0) {
-            print("DistGKey:receiveGKeyList ignoring keylist {} signed by expired or unauthorized identity\n", p.name());
+            dct::log(L_WARN)("DistGKey:receiveGKeyList ignoring keylist {} signed by expired or unauthorized identity", p.name());
             return;
         }
         auto n = p.name();
@@ -293,7 +293,7 @@ struct DistGKey {
                 // seem to be restarted keymaker, grab keymaker status and return
                 m_keyMaker = true;
                 m_KMepoch = ++epoch;    // epoch is incremented when KM gets new signing pair
-                // print("DistGKey:receiveGKeyList: received key list from my Id in init set epoch to {}\n", m_KMepoch);
+                dct::log(L_TRACE)("DistGKey:receiveGKeyList: received key list from my Id in init set epoch to {}", m_KMepoch);
                 m_sync.subscribe(m_mrPrefix, [this](const auto& p){ addGroupMem(p); }); // keymakers need the member requests
                 gkeyTimeout();  //create a group key and schedule group key creation with this  epoch and current signing cert
             }
@@ -459,7 +459,8 @@ struct DistGKey {
                 m_keyMaker = elected;
                 m_KMepoch = epoch;
                 if (! elected) return;
-                //print("{} wins election to make {} GKs\n", m_certs[m_tp].name(), m_sync.collName_.last().toSv());
+                dct::log(L_INFO)("DistGKey::setup {} wins election to make {} GKs",
+                         m_certs[m_tp].name(), m_sync.collName_.last().toSv());
                 m_sync.subscribe(m_mrPrefix, [this](const auto& p){ addGroupMem(p); }); // keymakers need the member requests
                 gkeyTimeout();  //create a group key and reschedule group key creation                
         };
@@ -502,7 +503,7 @@ struct DistGKey {
     void makeGKey() {
         m_curKey.resize(aeadKeySz); // crypto_aead_xchacha20poly1305_IETF_KEYBYTES
         crypto_aead_xchacha20poly1305_ietf_keygen(m_curKey.data());
-        //print("{} makes a new {} GK\n", m_certs[m_tp].name(), m_sync.collName_.last().toSv());
+        dct::log(L_DEBUG)("{} makes a new {} GK", m_certs[m_tp].name(), m_sync.collName_.last().toSv());
         //set the key's creation time
         m_curKeyCT = std::chrono::duration_cast<std::chrono::microseconds>(
                         std::chrono::system_clock::now().time_since_epoch()).count();

include/dct/distributors/dist_sgkey.hpp

@@ -289,7 +289,7 @@ struct DistSGKey {
 
         const auto& tp = p.signer();    // thumbprint of this SGKeyRec's signer
         if (!m_certs.contains(tp) || m_kmpri(tp) <= 0) {
-            print("DistSGKey:receiveSGKeyRecords ignoring keylist {} signed by expired or unauthorized identity\n", p.name());
+            dct::log(L_WARN)("DistSGKey:receiveSGKeyRecords ignoring keylist {} signed by expired or unauthorized identity", p.name());
             return;
         }
 

include/dct/distributors/km_election.hpp

@@ -97,7 +97,7 @@ struct kmElection {
         if (priority_ > 0) {
             ++epoch_;
             publishKM("elec");
-            //print("kmElection:electionDone: election {} done\n", epoch_);
+            dct::log(L_TRACE)("kmElection::electionDone: election {} done", epoch_);
         }
         done_(priority_ > 0, epoch_);
     }
@@ -128,8 +128,8 @@ struct kmElection {
 
             if (std::cmp_greater(priority_, pri)) return; // candidate loses
             if (std::cmp_greater(pri, priority_) || tp > ourTP_) priority_ = -priority_; // we lose
-            //dct::print("cand {:02x} pri {}  us {:02x} {}\n", fmt::join(std::span(tp).first(4),""), pri,
-            //      fmt::join(std::span(ourTP_).first(4),""), priority_);
+            dct::log(L_TRACE)("kmElection::handleKMcand {:02x} pri {} us {:02x} {}\n",
+                     fmt::join(std::span(tp).first(4), ""), pri, fmt::join(std::span(ourTP_).first(4), ""), priority_);
         } catch (std::runtime_error& ex) { return; }
     }
 

include/dct/face/transport.hpp

@@ -52,6 +52,7 @@
 #endif
 
 #include <dct/schema/crpacket.hpp>
+#include <dct/log.hpp>
 #include "default-if.hpp"
 #include "default-io-context.hpp"
 
@@ -108,12 +109,15 @@ struct Transport {
      */
     void send(auto&& v) {
         size_t len = v.size() * sizeof(v[0]);
-        if (len > max_pkt_size) throw runtime_error( "send: packet too big");
+        if (len > max_pkt_size) {
+            dct::log(L_ERROR)("Transport::send packet too big, len={}", len);
+            return;
+        }
         send_pkt((const uint8_t*)v.data(), len,
                 [buf = std::move(v)](const boost::system::error_code& ec, size_t) {
                     if (ec.failed() && ec.value() != ECONNREFUSED)
                         //throw runtime_error(dct::format("send failed: {}", ec.message()));
-                        print("send failed: {}", ec.message());
+                        dct::log(L_ERROR)("Transport::send failed: {}", ec.message());
                 });
     }
 };
@@ -144,8 +148,8 @@ struct TransportUdp : Transport {
         sock_.async_receive(asio::buffer(rcvbuf_),
                 [this](boost::system::error_code ec, std::size_t len) {
                     if (ec.failed() && ec.value() != ECONNREFUSED)
-                            throw runtime_error(dct::format("recv failed: {}", ec.message()));
-                    //if (ec.failed()) print("recv failed: {} len {}\n", ec.message(), len);
+                            throw runtime_error(dct::format("TransportUdp::recv failed: {}", ec.message()));
+                    if (ec.failed()) dct::log(L_ERROR)("TransportUdp::recv failed: {} len={}", ec.message(), len);
                     if (len > 0) rcb_(rcvbuf_.data(), len);
                     issueRead();
                 });
@@ -534,7 +538,7 @@ struct TransportTcpP final : TransportTcp {
     void doAccept() {
         acceptor_.async_accept([this](boost::system::error_code ec, tcp::socket socket) {
             if (ec.failed()) {
-                dct::print("tcp accept failed: {}", ec.message());
+                dct::log(L_FATAL)("TransportTcpP::accept failed: {}", ec.message());
                 throw std::runtime_error(dct::format("accept failed: {}", ec.message()));
             }
             startSession(socket);;

include/dct/log.hpp

@@ -0,0 +1,87 @@
+/**
+ * DCT logger stub implementation.
+ *
+ * To define a custom logger, the application must implement dct::Logger
+ * and call global_logger to set the logger implementation.
+ */
+
+#pragma once
+
+#include <chrono>
+#include <memory>
+#include <string>
+#include <source_location>
+
+#include <dct/format.hpp>
+
+namespace {
+    /// Compile-time evalute basename from full file path
+    consteval const char* log_basename_(const char* path) {
+        const char* last = nullptr;
+        for (const char* current = path; *current != '\0'; ++current)
+            if (*current == '/' || *current == '\\') last = current;
+        return last ? last + 1 : path;
+    }
+}
+
+namespace dct
+{
+    enum class log_level_t { L_TRACE, L_DEBUG, L_INFO, L_WARN, L_ERROR, L_FATAL };
+    static const char* log_level_str[] = { "TRACE", "DEBUG", "INFO", "WARN", "ERROR", "FATAL" }; // needs same order
+    using enum log_level_t;
+
+    /// Logger implementation interface
+    class Logger {
+    public:
+        virtual void log(
+            log_level_t level,
+            const std::source_location src,
+            const char* basename,
+            std::string statement
+        ) = 0;
+
+    public:
+        Logger() = default;
+        Logger(const Logger&) = delete;
+        Logger(Logger&&) = delete;
+        Logger& operator=(const Logger&) = delete;
+        Logger& operator=(Logger&&) = delete;
+        virtual ~Logger() = default;
+    };
+
+    /// Default Logger implementation
+    class DefaultLogger : public Logger {
+    public:
+        log_level_t min_level = L_INFO;
+
+        inline void log(
+            log_level_t level,
+            const std::source_location src,
+            const char* basename,
+            std::string statement
+        ) {
+            if (level < min_level) return;
+            fmt::print(stderr, "{} [{}] {} (dct:{}:{}:{})\n",
+                std::chrono::system_clock::now(),
+                log_level_str[static_cast<size_t>(level)],
+                statement,
+                basename,
+                src.line(),
+                src.column());
+        }
+    };
+
+    /// Get or set the global DCT logger
+    inline Logger* global_logger(std::unique_ptr<Logger> set_to = nullptr) {
+        static std::unique_ptr<Logger> logger = std::make_unique<DefaultLogger>(); // singleton
+        if (set_to) logger = std::move(set_to);
+        return logger.get();
+    }
+
+    consteval auto log(log_level_t level, const std::source_location src = std::source_location::current()) {
+        const char* basename = log_basename_(src.file_name());
+        return [=]<typename... T>(fmt::format_string<T...> fmt, T&&... args) constexpr -> void {
+            dct::global_logger()->log(level, src, basename, fmt::format(fmt, std::forward<T>(args)...));
+        };
+    }
+} // namespace dct

include/dct/schema/certstore.hpp

@@ -31,6 +31,7 @@
 #include <vector>
 #include "bschema.hpp"
 #include "dct_cert.hpp"
+#include <dct/log.hpp>
 
 namespace dct {
 
@@ -64,7 +65,7 @@ struct certStore {
     auto removeExpired() {  // remove expired certs
         std::erase_if(certs_, [this,now = std::chrono::system_clock::now()](const auto& i) {
                 if (rCert(i.second).validUntil() > now) return false;
-                // print("removeExpired {} @{:%T}\n", i.second.name(), now);
+                dct::log(L_DEBUG)("certStore::removeExpired {}", i.second.name());
                 const auto& tp = i.first;
                 // remove any msg validation state associated with this cert
                 certRemoveCb_(tp);
@@ -75,7 +76,7 @@ struct certStore {
                     std::erase(chains_, tp);
                     // print(" after remove have {} keys and {} chains\n", key_.size(), chains_.size());
                     if (chains_.size() == 0) {
-                        print("removeExpired @{} removed my only signing cert {}\n", now, i.second.name());
+                        dct::log(L_ERROR)("certStore::removeExpired removed my only signing cert {}", i.second.name());
                     }
                 }
                 return true;
@@ -124,22 +125,22 @@ struct certStore {
     // 'status' true if the element was added and false if it was already there.
     auto add(const dctCert& c) {
         if (! c.valid()) {
-            print("cert {} invalid\n", c.name());
+            dct::log(L_ERROR)("certStore::add (invalid) {}", c.name());
             return std::pair<decltype(certs_)::iterator,bool>{certs_.end(), false};
         }
         return finishAdd(certs_.try_emplace(c.computeTP(), c));
     }
     auto add(dctCert&& c) {
         if (! c.valid()) {
-            print("cert {} invalid\n", c.name());
+            dct::log(L_ERROR)("certStore::add (invalid) {}", c.name());
             return std::pair<decltype(certs_)::iterator,bool>{certs_.end(), false};
         }
         return finishAdd(certs_.try_emplace(c.computeTP(), std::move(c)));
     }
 
     auto add(const dctCert& c, const keyVal& k) {
         if (! c.valid()) {
-            print("cert {} invalid\n", c.name());
+            dct::log(L_ERROR)("certStore::add (invalid) {}", c.name());
             return std::pair<decltype(certs_)::iterator,bool>{certs_.end(), false};
         }
         auto it = finishAdd(certs_.try_emplace(c.computeTP(), c));
@@ -154,7 +155,7 @@ struct certStore {
     // so by passes the addCb_ which is for certs of others arriving through my face
     auto addNewSP(const dctCert& c, const keyVal& k) {
         if (! c.valid()) {
-            print("cert {} invalid\n", c.name());
+            dct::log(L_ERROR)("certStore::addNewSP (invalid) {}", c.name());
             return std::pair<decltype(certs_)::iterator,bool>{certs_.end(), false};
         }
         auto it = certs_.try_emplace(c.computeTP(), c);

include/dct/schema/dct_model.hpp

@@ -40,6 +40,7 @@
 #include "dct/distributors/dist_cert.hpp"
 #include "dct/distributors/dist_gkey.hpp"
 #include "dct/distributors/dist_sgkey.hpp"
+#include "dct/log.hpp"
 
 using namespace std::literals;
 
@@ -112,7 +113,7 @@ struct DCTmodel {
         std::vector<dctCert> pv{};
         for (auto i = b; i != e; ++i) {
             if (certSigMgr().validate(i->second, cert)) pv.emplace_back(std::move(i->second));
-            else print("checkPendingCerts: {} didn't validate with {}\n", i->second.name(), cert.name());
+            else dct::log(L_WARN)("checkPendingCerts: {} didn't validate with {}", i->second.name(), cert.name());
         }
         pending_.erase(tp);
         for (auto p : pv) addCert(p);
@@ -203,11 +204,24 @@ struct DCTmodel {
             auto sc = sp.first;
             cs_.addNewSP(sc, sp.second);   //add this signing pair to cs_ but do not publish
             m_ckd.publishConfCert(sc, [this, sp](const rData& c, bool acked){    //publish with conf cb
-                if (!acked) return;   // unlikely unless became entirely disconnected and cert expired
+                if (!acked) { // unlikely unless became entirely disconnected and cert expired
+                    dct::log(L_WARN)("getNewSP:addKP nobody acked my cert {}", sp.first.name());
+                    return;
+                } else {
+                    dct::log(L_DEBUG)("getNewSP:addKP my cert was acked {}", sp.first.name());
+                }
+
                 auto sc = sp.first;
-                if (sc.computeTP() != c.computeTP())  std::runtime_error("dct_model:getNewSP:addKP confirmed cert does not match passed in cert");
+                if (sc.computeTP() != c.computeTP()) {
+                    dct::log(L_WARN)("getNewSP:addKP confirmed cert does not match passed in cert {}", sp.first.name());
+                }
+
                 // should be no issue with chain since it hasn't changed so may skip this
-                if (validateChain(bs_, cs_, sc) < 0) throw schema_error(format("getNewSP:addKP cert {} signing chain invalid", sc.name()));
+                if (validateChain(bs_, cs_, sc) < 0) {
+                    dct::log(L_FATAL)("getNewSP:addKP cert {} signing chain invalid", sc.name());
+                    return;
+                }
+
                 cs_.insertChain(sc);                // make it a signing chain head
                 // pass new signing pair to sigmgrs and distributors
                 msgSigMgr().updateSigningKey(sp.second, sc);

include/dct/schema/validate_pub.hpp

@@ -141,16 +141,18 @@ struct SigMgrSchema final : SigMgr {
     bool validate(rData data) override final {
         // cryptographically validate 'data'
         if (! pubsm_.get().validate(data)) {
-            print("SigMgrSchema::validate: invalid sig {}\n", data.name());
+            dct::log(L_WARN)("SigMgrSchema::validate: invalid sig {}", data.name());
             return false;
         }
         // structurally validate 'data'
         try {
             const auto& pubval = pv_.at(data.signer()); // can throw when checking pubs from cAdds where don't yet have certs
             auto valid = pubval.matchTmplt(bs_, data.name());
-            if (!valid) print("SigMgrSchema::validate: invalid structure {}\n", data.name());
+            if (!valid) dct::log(L_WARN)("SigMgrSchema::validate: invalid structure {}", data.name());
             return valid;
-        } catch (std::exception& e) { /* print("SigMgrSchema::validate: structure validation err: {}\n", e.what());*/ }
+        } catch (std::exception& e) {
+            dct::log(L_WARN)("SigMgrSchema::validate: structure validation err: {}", e.what());
+        }
         return false;
     }