From fc4b550959e6a1a0e06dfdaf25b4218ed1ead81d Mon Sep 17 00:00:00 2001 From: Varun Patil Date: Tue, 26 Nov 2024 20:24:02 +0000 Subject: [PATCH] feat(log): add extensible logger implementation The new logger allows application to set a custom global logging interface that supports log levels and source locations. Signed-off-by: Varun Patil --- include/dct/distributors/dist_gkey.hpp | 13 ++-- include/dct/distributors/dist_sgkey.hpp | 2 +- include/dct/distributors/km_election.hpp | 6 +- include/dct/face/transport.hpp | 14 ++-- include/dct/log.hpp | 87 ++++++++++++++++++++++++ include/dct/schema/certstore.hpp | 13 ++-- include/dct/schema/dct_model.hpp | 22 ++++-- include/dct/schema/validate_pub.hpp | 8 ++- include/dct/shims/mbps.hpp | 28 ++++---- include/dct/shims/ptps.hpp | 21 ++++-- include/dct/sigmgrs/sigmgr_aead.hpp | 5 +- include/dct/sigmgrs/sigmgr_aegis.hpp | 4 +- include/dct/syncps/iblt.hpp | 7 +- include/dct/syncps/syncps.hpp | 57 +++++++++------- 14 files changed, 207 insertions(+), 80 deletions(-) create mode 100644 include/dct/log.hpp diff --git a/include/dct/distributors/dist_gkey.hpp b/include/dct/distributors/dist_gkey.hpp index 1a05e9e..4f8ea9a 100644 --- a/include/dct/distributors/dist_gkey.hpp +++ b/include/dct/distributors/dist_gkey.hpp @@ -234,7 +234,7 @@ 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; } @@ -242,7 +242,7 @@ struct DistGKey { 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::system_clock::now().time_since_epoch()).count(); diff --git a/include/dct/distributors/dist_sgkey.hpp b/include/dct/distributors/dist_sgkey.hpp index 6ac75dc..f91a36d 100644 --- a/include/dct/distributors/dist_sgkey.hpp +++ b/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; } diff --git a/include/dct/distributors/km_election.hpp b/include/dct/distributors/km_election.hpp index aa6be1c..f7c6e8b 100644 --- a/include/dct/distributors/km_election.hpp +++ b/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; } } diff --git a/include/dct/face/transport.hpp b/include/dct/face/transport.hpp index ab138d9..64c8f90 100644 --- a/include/dct/face/transport.hpp +++ b/include/dct/face/transport.hpp @@ -52,6 +52,7 @@ #endif #include +#include #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);; diff --git a/include/dct/log.hpp b/include/dct/log.hpp new file mode 100644 index 0000000..bfef45a --- /dev/null +++ b/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 +#include +#include +#include + +#include + +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(level)], + statement, + basename, + src.line(), + src.column()); + } + }; + + /// Get or set the global DCT logger + inline Logger* global_logger(std::unique_ptr set_to = nullptr) { + static std::unique_ptr logger = std::make_unique(); // 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 [=](fmt::format_string fmt, T&&... args) constexpr -> void { + dct::global_logger()->log(level, src, basename, fmt::format(fmt, std::forward(args)...)); + }; + } +} // namespace dct diff --git a/include/dct/schema/certstore.hpp b/include/dct/schema/certstore.hpp index dc414a2..2721dff 100644 --- a/include/dct/schema/certstore.hpp +++ b/include/dct/schema/certstore.hpp @@ -31,6 +31,7 @@ #include #include "bschema.hpp" #include "dct_cert.hpp" +#include 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,14 +125,14 @@ 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{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{certs_.end(), false}; } return finishAdd(certs_.try_emplace(c.computeTP(), std::move(c))); @@ -139,7 +140,7 @@ struct certStore { 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{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{certs_.end(), false}; } auto it = certs_.try_emplace(c.computeTP(), c); diff --git a/include/dct/schema/dct_model.hpp b/include/dct/schema/dct_model.hpp index 3a3298a..05d0a65 100644 --- a/include/dct/schema/dct_model.hpp +++ b/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 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); diff --git a/include/dct/schema/validate_pub.hpp b/include/dct/schema/validate_pub.hpp index b9a43d9..d116bb4 100644 --- a/include/dct/schema/validate_pub.hpp +++ b/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; } diff --git a/include/dct/shims/mbps.hpp b/include/dct/shims/mbps.hpp index f16a8fe..9900c27 100644 --- a/include/dct/shims/mbps.hpp +++ b/include/dct/shims/mbps.hpp @@ -146,6 +146,7 @@ struct mbps // call start() with lambda to confirm success/failure m_pb.start([this](bool success) { if (!success) throw runtime_error("mbps failed to initialize connection"); + dct::log(L_INFO)("mbps::connect initialize successful"); m_connectCb(); }); } @@ -191,6 +192,7 @@ struct mbps { const auto& p = mbpsPub(pub); try { + dct::log(L_DEBUG)("mbps::receivePub: received {}", p.name()); //all the publication name ftags (in order) set by app or mbps SegCnt k = p.number("sCnt"), n = 1u; std::vector msg{}; //for message body @@ -203,12 +205,12 @@ struct mbps n = 255 & k; //bottom byte k >>= 8; if (k > n || k == 0 || n > MAX_SEGS) { - print("receivePub: msgID {} piece {} > n pieces\n", p.number("msgID"), k, n); + dct::log(L_WARN)("mbps::receivePub: msgID {} piece {} > n pieces\n", p.number("msgID"), k, n); return; } if (m_maxContent.contains(mId)) { if (pubSpace_ - p.name().size() != m_maxContent[mId]) { - dct::print("mbps::receivePub: publication for message {} with name {}\n", mId, p.name()); + dct::log(L_ERROR)("mbps::receivePub: publication for message {} with name {}", mId, p.name()); throw error("mbps::receivePub: can't reassemble message as has name size mismatch"); } } else m_maxContent[mId] = pubSpace_ - p.name().size(); @@ -233,8 +235,7 @@ struct mbps mh(*this, mbpsMsg(p), msg); } catch (const std::exception& e) { - std::cerr << "mbps::receivePub: " << e.what() << std::endl; - exit(1); + dct::log(L_FATAL)("mbps::receivePub: error {}", e.what()); } } @@ -322,7 +323,7 @@ struct mbps return; } if(m_pb.publish(std::move(p)) == 0) - dct::print("doPublish: was unable to publish {}\n", p.name()); + dct::log(L_WARN)("doPublish: was unable to publish {}", p.name()); } MsgID publish(msgParms&& mp, std::span msg = {}, const confHndlr&& ch = nullptr) @@ -356,9 +357,7 @@ struct mbps doPublish(m_pb.pub({}, mp), hasCH); return mId; } catch (const std::exception& e) { - std::cerr << "mbps::publish: " << e.what() << std::endl; - for (auto e : mp) print ("{}/", e.second); - print ("\n"); + dct::log(L_ERROR)("mbps::publish: {}", e.what()); return 0; } } @@ -366,12 +365,13 @@ struct mbps // determine name size in order to determine the space left for content auto contentSp = pubSpace_ - (m_pb.name(mp).size() + 2); // add 2 bytes in case multiple segments if (contentSp < 10) { - dct::print("mbps::publish Publication name only leaves {} bytes for content\n", contentSp); + dct::log(L_ERROR)("mbps::publish Publication name only leaves {} bytes for content", contentSp); return 0; } // determine number of message segments to carry msg: sCnt forces n < 256, n = (size + (contentSp - 1)) / contentSp; + dct::log(L_DEBUG)("mbps::publish sending message as {} segments", n); if(n > MAX_SEGS) throw error("publishMsg: message too large"); auto sCnt = n > 1? n + 256 : 0; mp.back().second = sCnt; //sCnt is last argument on the list @@ -386,9 +386,7 @@ struct mbps mp.back().second = sCnt; //sCnt is last argument on the list } } catch (const std::exception& e) { - std::cerr << "mbps::publish: " << e.what() << std::endl; - for (auto e : mp) print ("{}/", e.second); - print ("\n"); + dct::log(L_ERROR)("mbps::publish: {}", e.what()); if (n>1) endMsgsBatch(); return 0; } @@ -464,7 +462,7 @@ struct mbps mp.emplace_back("sCnt", 0u); // just to get a name size for this message m_maxContent[mId] = pubSpace_ - (m_pb.name(mp).size() + 2); // add 2 bytes in case multiple segments if (m_maxContent[mId] < 10) { - dct::print("mbps::publish Publication name only leaves {} bytes for content\n", m_maxContent[mId]); + dct::log(L_ERROR)("mbps::publish Publication name only leaves {} bytes for content", m_maxContent[mId]); return 0; } @@ -478,9 +476,7 @@ struct mbps m_pacing = true; doSegment(sCnt, mId, paceTm, std::vector(msg.begin(),msg.end()), hasCH); } catch (const std::exception& e) { - std::cerr << "mbps::publish: " << e.what() << std::endl; - for (auto e : mp) print ("{}/", e.second); - print ("\n"); + dct::log(L_ERROR)("mbps::publish: {}", e.what()); return 0; } return mId; diff --git a/include/dct/shims/ptps.hpp b/include/dct/shims/ptps.hpp index fe05466..74b8f78 100644 --- a/include/dct/shims/ptps.hpp +++ b/include/dct/shims/ptps.hpp @@ -83,12 +83,15 @@ struct DCTmodelPT final : DCTmodel { // ensure a publication is *structurally* valid on the outgoing DeftT bool isValidPub(const Publication& pub) { - // if (!certs().contains(pub.signer())) - // print ("DCTmodelPT::isValidPub: this DeftT's cert store does not contain signer of {}\n", pub.name()); + if (!certs().contains(pub.signer())) + dct::log(L_DEBUG)("DCTmodelPT::isValidPub: cert store does not contain signer of {}", pub.name()); + try { const auto& pubval = pv_.at(pub.signer()); return pubval.matchTmplt(bs_, pub.name()); // structurally validate 'pub' - } catch (std::exception&) { print("DCTmodelPT:isValidPub: no pub validator found for signer\n"); } + } catch (std::exception&) { + dct::log(L_WARN)("DCTmodelPT::isValidPub: no pub validator found for signer"); + } return false; } // checking if key/msgs Publication's signer is in cert store of this outgoing DeftT @@ -106,10 +109,13 @@ struct DCTmodelPT final : DCTmodel { const auto& tp = cs_.Chains()[0]; // thumbprint of newest signing cert // returns empty span if capability wasn't found or has bad argument content auto arg = (Cap::getval(c, pubPrefix(), cs_)(tp)).toSv(); - if (arg.empty()) std::runtime_error("DCTmodelPT: no RLY capability or no address in RLY capability cert"); + if (arg.empty()) { + dct::log(L_FATAL)("DCTmodelPT::capArgument: no RLY capability or no address in RLY capability cert"); + std::runtime_error("DCTmodelPT::capArgument: no RLY capability or no address in RLY capability cert"); + } //XXXX hack for working without transport.hpp changes if (!arg.starts_with("tcp:") && !arg.starts_with("udp:") && !arg.starts_with("ff02") && !arg.starts_with("ff01")) arg = ""; - // print ("RLY capability argument is {}\n", arg); + dct::log(L_INFO)("DCTmodelPT::capArgument RLY capability argument is {}", arg); return arg; } @@ -117,7 +123,7 @@ struct DCTmodelPT final : DCTmodel { DCTmodelPT(const certCb& rootCb, const certCb& schemaCb, const chainCb& idChainCb, const pairCb& signIdCb, std::string_view addrLoc, addChnCb&& rcb = nullptr) : - DCTmodel(rootCb, schemaCb, idChainCb, signIdCb, [this,a=addrLoc]{ return capArgument(a);} ), + DCTmodelPT(rootCb, schemaCb, idChainCb, signIdCb, [this,a=addrLoc]{ return capArgument(a);}, std::move(rcb)) {} ptPubSm_{msm_.ref()} { m_tp = cs_.Chains()[0]; // thumbprint of signing cert @@ -300,7 +306,8 @@ struct ptps publish(std::move(p)); return true; } else { - // print("publishValid failed to validate {}\n", p.name()); // this pub isn't in the schema for this DeftT or signing cert hasn't arrived + // this pub isn't in the schema for this DeftT or signing cert hasn't arrived + dct::log(L_WARN)("DCTmodelPT::publishValid failed to validate {}", p.name()); return false; } } diff --git a/include/dct/sigmgrs/sigmgr_aead.hpp b/include/dct/sigmgrs/sigmgr_aead.hpp index 9018bb9..4bd49d9 100644 --- a/include/dct/sigmgrs/sigmgr_aead.hpp +++ b/include/dct/sigmgrs/sigmgr_aead.hpp @@ -61,6 +61,7 @@ #include // for memcpy #include #include "sigmgr.hpp" +#include namespace dct { @@ -147,7 +148,7 @@ struct SigMgrAEAD final : SigMgr { // signature holds nonce followed by computed MAC for this Data auto sig = d.signature().rest(); if (sig.size() != sigSize) { - // print("aead bad sig size {} expected {}\n", sig.size(), sigSize); + dct::log(L_DEBUG)("aead bad sig size {} expected {}", sig.size(), sigSize); return false; } auto content = d.content().rest(); @@ -166,7 +167,7 @@ struct SigMgrAEAD final : SigMgr { } i = (i + 1) % keyListSize(); } while (i != m_decryptIndex); - //print("aead decrypt failed for PDU: {}\n", d.name()); + dct::log(L_DEBUG)("aead decrypt failed for PDU: {}", d.name()); return false; } diff --git a/include/dct/sigmgrs/sigmgr_aegis.hpp b/include/dct/sigmgrs/sigmgr_aegis.hpp index 080e2c3..8a129bc 100644 --- a/include/dct/sigmgrs/sigmgr_aegis.hpp +++ b/include/dct/sigmgrs/sigmgr_aegis.hpp @@ -144,7 +144,7 @@ struct SigMgrAEGIS final : SigMgr { // signature holds nonce followed by computed MAC for this Data auto sig = d.signature().rest(); if (sig.size() != sigSize) { - // print("aead bad sig size {} expected {}\n", sig.size(), sigSize); + dct::log(L_DEBUG)("aead bad sig size {} expected {}", sig.size(), sigSize); return false; } auto content = d.content().rest(); @@ -163,7 +163,7 @@ struct SigMgrAEGIS final : SigMgr { } i = (i + 1) % keyListSize(); } while (i != m_decryptIndex); - print("aead decrypt failed on {}\n", d.name()); + dct::log(L_DEBUG)("aead decrypt failed on {}", d.name()); return false; } diff --git a/include/dct/syncps/iblt.hpp b/include/dct/syncps/iblt.hpp index 157f9de..dc13de1 100644 --- a/include/dct/syncps/iblt.hpp +++ b/include/dct/syncps/iblt.hpp @@ -55,6 +55,7 @@ #include #include "murmurHash3.hpp" +#include namespace dct { @@ -240,8 +241,10 @@ struct IBLT { // extract entry nitems_ += b; //print(" ht[{}] = {} of {}\n", i, b, nitems_); - if (i >= nEntries) print("compressed IBLT too large {} {}\n", i, nEntries); - if (i >= nEntries) throw std::runtime_error("compressed IBLT too large"); + if (i >= nEntries) { + dct::log(L_FATAL)("iblt::rlDecode compressed IBLT too large {} {}", i, nEntries); + throw std::runtime_error("compressed IBLT too large"); + } hashTable_[i].count = b; hashTable_[i].keySum = r[0] | (r[1] << 8) | (r[2] << 16) | (r[3] << 24); hashTable_[i].keyCheck = r[4] | (r[5] << 8) | (r[6] << 16) | (r[7] << 24); diff --git a/include/dct/syncps/syncps.hpp b/include/dct/syncps/syncps.hpp index fec3a58..4891f00 100644 --- a/include/dct/syncps/syncps.hpp +++ b/include/dct/syncps/syncps.hpp @@ -34,6 +34,7 @@ #include #include #include +#include #include "iblt.hpp" namespace dct { @@ -324,7 +325,8 @@ struct SyncPS { } else pubLifetime_ = maxPubLifetime; pubExpirationGB_ = pubLifetime_; - // print ("syncps for {} computes pubSize: {}, infoSize: {}, distDly: {}\n", collName_, maxPubSize_, maxInfoSize_, distDelay_.count()); + dct::log(L_DEBUG)("syncps for {} computes pubSize: {}, infoSize: {}, distDly: {}", + collName_, maxPubSize_, maxInfoSize_, distDelay_); } SyncPS(rName collName, SigMgr& wsig, SigMgr& psig) : SyncPS(defaultFace(), collName, wsig, psig) {} @@ -354,7 +356,7 @@ struct SyncPS { * @brief add a new local or network publication to the 'active' pubs set */ auto addToActive(crData&& p, bool localPub) { - //print("{:%M:%S} addToActive {} {}: {}\n", std::chrono::system_clock::now(), p.name(), p.size(), localPub); + dct::log(L_TRACE)("syncps::addToActive {} {}: {}", p.name(), p.size(), localPub); auto lt = getLifetime_(p); auto hash = localPub? pubs_.addLocal(std::move(p)) : pubs_.addNet(std::move(p)); return finishActivate(hash, lt); @@ -365,7 +367,6 @@ struct SyncPS { */ auto activateEntry(const auto& e) { const auto& p = e.i_; - //print("{:%M:%S} activateEntry {} {}: {}\n", std::chrono::system_clock::now(), p.name(), p.size(), localPub); if (e.fromNet()) if (auto s = subscriptions_.findLM(p.name()); subscriptions_.found(s)) deliver(p, s->second); @@ -381,14 +382,14 @@ struct SyncPS { */ bool addToNoSigner(crData&& p) { auto hash = pubs_.addNoSigner(std::move(p)); - //print("{:%M:%S} addToNoSigner {} {} ^{:x}\n", std::chrono::system_clock::now(), p.name(), p.size(), hash); + dct::log(L_TRACE)("syncps::addToNoSigner {} {} ^{:x}", p.name(), p.size(), hash); if (hash == 0 || noSignerPubs_ > 50) return false; noSignerPubs_++; // Remove a publication that had no signing cert when it arrived if its signer // does not show up after brief delay. Check to make sure it hasn't become active. oneTime(signerHold_ + maxClockSkew, [this, hash]{ if (pubs_.contains(hash) && !(pubs_.at(hash).active())) { - //print("{:%M:%S} addToNoSigner now ignoring ^{:x}\n", std::chrono::system_clock::now(), hash); + dct::log(L_DEBUG)("syncps::addToNoSigner now ignoring ^{:x}", hash); --noSignerPubs_; pubs_.erase(hash); ignorePub(hash); @@ -403,11 +404,11 @@ struct SyncPS { */ void newSigner(const thumbPrint& tp) { if (noSignerPubs_ == 0) return; - //print("{:%M:%S} newSigner called with {} entries\n", std::chrono::system_clock::now(), noSignerPubs_); + dct::log(L_TRACE)("syncps::newSigner called with {} entries", noSignerPubs_); pubs_.forEachNoS([this,tp](auto& e) { const auto& p = e.i_; // reference to pub if (tp == p.signer() && pubSigmgr_.validate(p)) { - //print("syncps::newSigner is activating {}\n", p.name()); + dct::log(L_TRACE)("syncps::newSigner is activating {}", p.name()); e.signer().activate(); --noSignerPubs_; activateEntry(e); @@ -428,7 +429,7 @@ struct SyncPS { PubHash publish(crData&& pub) { if (pub.size() > maxPubSize_) return 0; auto h = addToActive(std::move(pub), true); - //print("{:%M:%S} publish {} {:x} d {} r {}\n", std::chrono::system_clock::now(), pub.name(), h, delivering_, registering_); + dct::log(L_DEBUG)("syncps::publish {} {:x} d {} r {}", pub.name(), h, delivering_, registering_); if (h == 0) return h; // already in actives ++publications_; // if a delivery callback is waiting on this pub, call it @@ -461,9 +462,9 @@ struct SyncPS { auto h = hashPub(pub); if (pubs_.contains(h)) { if ((pubs_.at(h)).fromNet()) { - print("syncps::publish w cb instant cb for {}\n", pub.name()); + dct::log(L_TRACE)("syncps::publish w cb instant cb for {}", pub.name()); cb((pubs_.find(h))->second.i_,true); - } + } return h; // if already in collection and is local assume it has already set cb } h = publish(std::move(pub)); @@ -509,7 +510,7 @@ struct SyncPS { * from some external source. */ auto& subscribe(crPrefix&& topic, SubCb&& cb) { - // print("syncps::subscribe called for {}\n", (rPrefix)topic); + dct::log(L_DEBUG)("syncps::subscribe called for {}", (rPrefix)topic); // add to subscription dispatch table. If subscription is new, // 'cb' will be called with each matching item in the active // publication list. Otherwise subscription will be @@ -631,8 +632,8 @@ struct SyncPS { if (sv.empty()) return false; cAdd.content(sv); if (! pktSigmgr_.sign(cAdd)) return false; + dct::log(L_TRACE)("syncps::shipCAdd sent {}", cAdd.name()); face_.send(std::move(cAdd)); - //print("{:%M:%S} syncps::shipCAdd sent {}\n", std::chrono::system_clock::now(), cAdd.name()); return true; } @@ -843,29 +844,39 @@ struct SyncPS { // For now we skip this pub and try to continue but getting a real cAdd valid() // method needs to happen ASAP. Once it does, this 'if' will go away since a cAdd // will never be passed up to here if any of its Data's are not valid. - //print("doesn't pass basic structure test {}\n", d.name()); + dct::log(L_WARN)("syncps::onCAdd pub {}: doesn't pass basic structure test", d.name()); continue; } auto h = hashPub(d); - if (ignore_.contains(h)) continue; // currently ignoring this pub + if (ignore_.contains(h)) { + dct::log(L_TRACE)("syncps::onCAdd pub {}: currently ignoring", d.name()); + continue; + } // puts hold on pubs others send that I already have in case it is on the pending list if (pubs_.contains(h)) { // && not local origin in case overhear a member resending my pubs? if (ht.time_since_epoch().count()) pubs_.at(h).hold_ = ht; + dct::log(L_TRACE)("syncps::onCAdd pub {}: putting on hold", d.name()); continue; } if (d.size() > maxPubSize_ || isExpired_(d)) { - //print("pub {}: {}\n", isExpired_(d)? "expired":"exceeds maxPubSize", d.name()); + dct::log(L_DEBUG)("syncps::onCAdd pub {}: {}", isExpired_(d) ? "expired" : "exceeds maxPubSize", d.name()); // unwanted pubs have to go in our iblt or we'll keep getting them ignorePub(d); continue; } + if (! pubSigmgr_.validate(d)) { - if (pubSigmgr_.haveSigner(d)) + if (pubSigmgr_.haveSigner(d)) { + dct::log(L_WARN)("syncps::onCAdd pub {}: failed validation (haveSigner)", d.name()); ignorePub(d); // already have this Pub's signing cert - else if ( !addToNoSigner(crData(d))) + } else if ( !addToNoSigner(crData(d))) { + dct::log(L_DEBUG)("syncps::onCAdd pub {}: failed validation (!addToNoSigner)", d.name()); ignorePub(d); // failed to add as inactive without signer + } else { + dct::log(L_DEBUG)("syncps::onCAdd pub {}: failed validation (addToNoSigner)", d.name()); + } continue; } @@ -873,12 +884,12 @@ struct SyncPS { // collection then deliver it to the longest match subscription. auto ph = addToActive(crData(d), false); if (ph == 0) { - // print("addToActive failed: {}\n", d.name()); + dct::log(L_DEBUG)("syncps::addToActive failed: {}", d.name()); continue; } ++ap; if (auto s = subscriptions_.findLM(d.name()); subscriptions_.found(s)) deliver(d, s->second); - // else print("syncps::onCAdd: no subscription for {}\n", d.name()); + else dct::log(L_DEBUG)("syncps::onCAdd: no subscription for {}\n", d.name()); } delivering_ = false; if (ap == 0) { // nothing I need in this cAdd, no change to local cState @@ -918,12 +929,12 @@ struct SyncPS { ignore_.add(h); oneTime(1s, [this, h]{ ignore_.erase(h); - //print("{:%M:%S} ignorePub done ignoring ^{:x}\n", std::chrono::system_clock::now(), h); + dct::log(L_DEBUG)("syncps::ignorePub done ignoring ^{:x}", h); }); } void ignorePub(const rPub& p) { auto h = hashPub(p); - //print("{:%M:%S} ignorePub {} ^{:x}\n", std::chrono::system_clock::now(), p.name(), h); + dct::log(L_DEBUG)("ignorePub {} ^{:x}", p.name(), h); ignorePub(h); } @@ -948,9 +959,9 @@ struct SyncPS { if (auto n = s.name(); n.nBlks() == ncomp) handleCState(n); }, [this](auto rd) { // dCb: cAdd response to any active local cState in collName_ - // print("syncps RST set Cb received cAdd: {}\n", rd.name()); + dct::log(L_TRACE)("syncps RST set Cb received cAdd: {}", rd.name()); if (! pktSigmgr_.validateDecrypt(rd)) { - // print("syncps invalid cAdd: {}\n", rd.name()); + dct::log(L_WARN)("syncps invalid cAdd: {}", rd.name()); // Got an invalid cAdd so ignore the pubs it contains. return; }