diff --git a/include/opendht/dht_interface.h b/include/opendht/dht_interface.h index bf8b1102..fd70e87b 100644 --- a/include/opendht/dht_interface.h +++ b/include/opendht/dht_interface.h @@ -234,14 +234,6 @@ public: virtual std::vector getPublicAddress(sa_family_t family = 0) = 0; - virtual void setLogger(const Logger& l) - { - if (logger_) - *logger_ = l; - else - logger_ = std::make_shared(l); - } - virtual void setLogger(const std::shared_ptr& l) { logger_ = l; } /** diff --git a/include/opendht/logger.h b/include/opendht/logger.h index b568fdc9..1f0ab119 100644 --- a/include/opendht/logger.h +++ b/include/opendht/logger.h @@ -9,110 +9,192 @@ #include #include +#include #include +#if __cplusplus >= 202002L +#include +#endif + namespace dht { namespace log { +#if __cplusplus >= 202002L +/** + * Extracts the filename from a full file path at compile time. + */ +consteval std::string_view +getfilename(std::string_view path) +{ + size_t pos = path.size(); + for (size_t i = path.size(); i-- > 0;) { + if (path[i] == '/' || path[i] == '\\') { + pos = i + 1; + break; + } + } + return path.substr(pos); +} + +consteval std::string_view +getfunctionname(std::string_view path) +{ + size_t pos = 0; + size_t end = path.size(); + for (size_t i = 0; i < path.size(); i++) { + if (path[i] == ' ' || path[i] == '\t' || path[i] == ':') { + pos = i + 1; + } else if (path[i] == '(') { + end = i; + break; + } + } + return path.substr(pos, end - pos); +} +#endif + +struct source_loc +{ + std::string_view file; + std::uint_least32_t line; + std::string_view function; + +#if __cplusplus >= 202002L + consteval source_loc(const std::source_location& loc) + : file(getfilename(loc.file_name())) + , line(loc.line()) + , function(getfunctionname(loc.function_name())) + {} +#else + constexpr source_loc() + : file() + , line(0) + , function() + {} +#endif +}; + enum class LogLevel { debug, warning, error }; -using LogMethod = std::function; +using LogMethod = std::function; + +template +struct LogFormat +{ + fmt::format_string fmt; + source_loc loc; + +#if __cplusplus >= 202002L + template + consteval LogFormat(const S& s, const std::source_location& l = std::source_location::current()) + : fmt(s) + , loc(l) + {} +#else + template + constexpr LogFormat(const S& s) + : fmt(s) + , loc() + {} +#endif +}; + +#if __cplusplus < 202002L +template +struct type_identity +{ + typedef _Tp type; +}; +template +using type_identity_t = typename type_identity<_Tp>::type; +#else +using std::type_identity_t; +#endif struct OPENDHT_PUBLIC Logger { Logger() = delete; - Logger(LogMethod&& l) - : logger(std::move(l)) + Logger(LogMethod&& l, std::string tag = "") + : logger_(std::move(l)) + , tag_(std::move(tag)) + , prefix_(tag_.empty() ? "" : fmt::format("[{}] ", tag_)) { - if (!logger) - throw std::invalid_argument {"logger and loggerf must be set"}; + if (!logger_) + throw std::invalid_argument {"logger must be set"}; } - void setFilter(const InfoHash& f) + Logger(const Logger& parent, std::string tag) + : logger_(parent.logger_) + , tag_(std::move(tag)) + , prefix_(fmt::format("{}[{}] ", parent.prefix_, tag_)) + {} + + std::shared_ptr createChild(std::string tag) { - filter_ = f; - filterEnable_ = static_cast(filter_); + auto child = std::make_shared(*this, std::move(tag)); + children_.push_back(child); + return child; } - inline void log0(LogLevel level, fmt::string_view format, fmt::printf_args args) const + + void setFilter(std::string_view tag) { - if (not filterEnable_) - logger(level, fmt::vsprintf(format, args)); + enable_ = tag.empty() or tag_ == tag; + for (auto it = children_.begin(); it != children_.end();) { + if (auto c = it->lock()) { + c->setFilter(enable_ ? std::string_view {} : tag); + ++it; + } else { + it = children_.erase(it); + } + } } - inline void log1(LogLevel level, const InfoHash& f, fmt::string_view format, fmt::printf_args args) const + + void setFilter(const InfoHash& f) { setFilter(f.to_view()); } + + inline void log0(source_loc loc, LogLevel level, fmt::string_view format, fmt::printf_args args) const { - if (not filterEnable_ or f == filter_) - logger(level, fmt::vsprintf(format, args)); - } - inline void log2( - LogLevel level, const InfoHash& f1, const InfoHash& f2, fmt::string_view format, fmt::printf_args args) const - { - if (not filterEnable_ or f1 == filter_ or f2 == filter_) - logger(level, fmt::vsprintf(format, args)); + if (enable_) + logger_(loc, level, prefix_, fmt::vsprintf(format, args)); } template - inline void debug(fmt::format_string format, Args&&... args) const + inline void debug(LogFormat...> format, Args&&... args) const { - logger(LogLevel::debug, fmt::format(format, std::forward(args)...)); + if (enable_) + logger_(format.loc, LogLevel::debug, prefix_, fmt::format(format.fmt, std::forward(args)...)); } template - inline void warn(fmt::format_string format, Args&&... args) const + inline void warn(LogFormat...> format, Args&&... args) const { - logger(LogLevel::warning, fmt::format(format, std::forward(args)...)); + if (enable_) + logger_(format.loc, LogLevel::warning, prefix_, fmt::format(format.fmt, std::forward(args)...)); } template - inline void error(fmt::format_string format, Args&&... args) const + inline void error(LogFormat...> format, Args&&... args) const { - logger(LogLevel::error, fmt::format(format, std::forward(args)...)); + if (enable_) + logger_(format.loc, LogLevel::error, prefix_, fmt::format(format.fmt, std::forward(args)...)); } template - inline void d(fmt::format_string format, T&&... args) const + inline void d(LogFormat...> format, T&&... args) const { - log0(LogLevel::debug, format, fmt::make_printf_args(args...)); + log0(format.loc, LogLevel::debug, format.fmt, fmt::make_printf_args(args...)); } template - inline void d(const InfoHash& f, fmt::format_string format, T&&... args) const + inline void w(LogFormat...> format, T&&... args) const { - log1(LogLevel::debug, f, format, fmt::make_printf_args(args...)); + log0(format.loc, LogLevel::warning, format.fmt, fmt::make_printf_args(args...)); } template - inline void d(const InfoHash& f1, const InfoHash& f2, fmt::format_string format, T&&... args) const + inline void e(LogFormat...> format, T&&... args) const { - log2(LogLevel::debug, f1, f2, format, fmt::make_printf_args(args...)); - } - template - inline void w(fmt::format_string format, T&&... args) const - { - log0(LogLevel::warning, format, fmt::make_printf_args(args...)); - } - template - inline void w(const InfoHash& f, fmt::format_string format, T&&... args) const - { - log1(LogLevel::warning, f, format, fmt::make_printf_args(args...)); - } - template - inline void w(const InfoHash& f1, const InfoHash& f2, fmt::format_string format, T&&... args) const - { - log2(LogLevel::warning, f1, f2, format, fmt::make_printf_args(args...)); - } - template - inline void e(fmt::format_string format, T&&... args) const - { - log0(LogLevel::error, format, fmt::make_printf_args(args...)); - } - template - inline void e(const InfoHash& f, fmt::format_string format, T&&... args) const - { - log1(LogLevel::error, f, format, fmt::make_printf_args(args...)); - } - template - inline void e(const InfoHash& f1, const InfoHash& f2, fmt::format_string format, T&&... args) const - { - log2(LogLevel::error, f1, f2, format, fmt::make_printf_args(args...)); + log0(format.loc, LogLevel::error, format.fmt, fmt::make_printf_args(args...)); } private: - LogMethod logger = {}; - bool filterEnable_ {false}; - InfoHash filter_ {}; + const LogMethod logger_ = {}; + const std::string tag_ {}; + const std::string prefix_ {}; + bool enable_ {true}; + std::vector> children_ {}; }; } // namespace log diff --git a/include/opendht/securedht.h b/include/opendht/securedht.h index ab592da3..774a7a81 100644 --- a/include/opendht/securedht.h +++ b/include/opendht/securedht.h @@ -292,12 +292,6 @@ public: return dht_->pushNotificationReceived(notification); } - void setLogger(const Logger& logger) override - { - DhtInterface::setLogger(logger); - dht_->setLogger(logger); - } - void setLogger(const std::shared_ptr& logger) override { DhtInterface::setLogger(logger); diff --git a/src/dht.cpp b/src/dht.cpp index 5988930e..64be0a52 100644 --- a/src/dht.cpp +++ b/src/dht.cpp @@ -99,7 +99,7 @@ Dht::shutdown(ShutdownCallback cb, bool stop) auto str_donecb = [=](bool, const std::vector>&) { --*remaining; if (logger_) - logger_->w("Shutting down node: %u ops remaining", *remaining); + logger_->warn("Shutting down node: {} ops remaining", *remaining); if (!*remaining && cb) { cb(); } @@ -109,7 +109,7 @@ Dht::shutdown(ShutdownCallback cb, bool stop) *remaining += maintainStorage(str, true, str_donecb); if (logger_) - logger_->w("Shutting down node: after storage, %u ops", *remaining); + logger_->warn("Shutting down node: after storage, {} ops", *remaining); if (!*remaining) { if (cb) @@ -140,7 +140,7 @@ Dht::sendCachedPing(Bucket& b) { if (b.cached) if (logger_) - logger_->d(b.cached->id, "[node %s] Sending ping to cached node", b.cached->toString().c_str()); + logger_->debug("[node {}] Sending ping to cached node", b.cached->toString()); b.sendCachedPing(network_engine); } @@ -274,7 +274,7 @@ Dht::expireSearches() auto b = sr.callbacks.empty() && sr.announce.empty() && sr.listeners.empty() && sr.step_time < t; if (b) { if (logger_) - logger_->d(srp.first, "[search %s] Removing search", srp.first.toString().c_str()); + logger_->debug("[search {}] Removing search", srp.first.to_view()); sr.clear(); return b; } else { @@ -355,12 +355,10 @@ Dht::paginate(std::weak_ptr ws, Sp query, SearchNode* n) auto query_for_vid = std::make_shared(Select {}, Where {}.id(vid)); sn->pagination_queries[query].push_back(query_for_vid); if (logger_) - logger_->d(id, - sn->node->id, - "[search %s] [node %s] Sending %s", - id.toString().c_str(), - sn->node->toString().c_str(), - query_for_vid->toString().c_str()); + logger_->debug("[search {}] [node {}] Sending {}", + id.toString(), + sn->node->toString(), + query_for_vid->toString()); sn->getStatus[query_for_vid] = network_engine.sendGetValues( status.node, id, @@ -370,12 +368,10 @@ Dht::paginate(std::weak_ptr ws, Sp query, SearchNode* n) std::bind(&Dht::searchNodeGetExpired, this, _1, _2, ws, query_for_vid)); } catch (const std::out_of_range&) { if (logger_) - logger_->e(id, - sn->node->id, - "[search %s] [node %s] Received non-id field in response to " - "'SELECT id' request…", - id.toString().c_str(), - sn->node->toString().c_str()); + logger_->error("[search {}] [node {}] Received non-id field in response to " + "'SELECT id' request…", + id.toString(), + sn->node->toString()); } } }; @@ -383,12 +379,7 @@ Dht::paginate(std::weak_ptr ws, Sp query, SearchNode* n) n->pagination_queries[query].push_back(select_q); if (logger_) - logger_->d(sr->id, - n->node->id, - "[search %s] [node %s] Sending %s", - sr->id.toString().c_str(), - n->node->toString().c_str(), - select_q->toString().c_str()); + logger_->debug("[search {}] [node {}] Sending {}", sr->id.to_view(), n->node->toString(), select_q->toString()); n->getStatus[select_q] = network_engine.sendGetValues( n->node, sr->id, *select_q, -1, onSelectDone, std::bind(&Dht::searchNodeGetExpired, this, _1, _2, ws, select_q)); } @@ -485,139 +476,116 @@ Dht::searchSendAnnounceValue(const Sp& sr, unsigned syncLevel) scheduler.time()); }; - auto onSelectDone = - [this, ws, onDone, onExpired]( - const net::Request& req, - net::RequestAnswer&& - answer) mutable { /* on probing done */ - auto sr = ws.lock(); - if (not sr) - return; - const auto& now = scheduler.time(); - sr->insertNode(req.node, scheduler.time(), answer.ntoken); - auto sn = sr->getNode(req.node); - if (not sn) - return; + auto onSelectDone = [this, ws, onDone, onExpired](const net::Request& req, net::RequestAnswer&& answer) mutable { + /* on probing done */ + auto sr = ws.lock(); + if (not sr) + return; + const auto& now = scheduler.time(); + sr->insertNode(req.node, now, answer.ntoken); + auto sn = sr->getNode(req.node); + if (not sn) + return; - if (not sn->isSynced(now)) { - /* Search is now unsynced. Let's call searchStep to sync again. */ - scheduler.edit(sr->nextSearchStep, now); - return; - } - for (auto& a : sr->announce) { - if (sn->getAnnounceTime(a.value->id) > now) - continue; - bool hasValue {false}; - uint16_t seq_no = 0; - try { - const auto& f = std::find_if(answer.fields.cbegin(), - answer.fields.cend(), - [&a](const Sp& i) { - return i->index.at(Value::Field::Id).getInt() - == a.value->id; - }); - if (f != answer.fields.cend() and *f) { - hasValue = true; - seq_no = static_cast( - (*f)->index.at(Value::Field::SeqNum).getInt()); - } - } catch (std::out_of_range&) { - } + if (not sn->isSynced(now)) { + /* Search is now unsynced. Let's call searchStep to sync again. */ + scheduler.edit(sr->nextSearchStep, now); + return; + } + for (auto& a : sr->announce) { + if (sn->getAnnounceTime(a.value->id) > now) + continue; + bool hasValue {false}; + uint16_t seq_no = 0; + try { + const auto& f = std::find_if(answer.fields.cbegin(), + answer.fields.cend(), + [&a](const Sp& i) { + return i->index.at(Value::Field::Id).getInt() == a.value->id; + }); + if (f != answer.fields.cend() and *f) { + hasValue = true; + seq_no = static_cast((*f)->index.at(Value::Field::SeqNum).getInt()); + } + } catch (std::out_of_range&) { + } - auto next_refresh_time = now + getType(a.value->type).expiration; - auto& acked = sn->acked[a.value->id]; - scheduler.cancel(acked.refresh); - /* only put the value if the node doesn't already have it */ - if (not hasValue or seq_no < a.value->seq) { - if (logger_) - logger_->d(sr->id, - sn->node->id, - "[search %s] [node %s] Sending 'put' (vid: %016" PRIx64 ")", - sr->id.toString().c_str(), - sn->node->toString().c_str(), - a.value->id); - auto created = a.permanent ? time_point::max() : a.created; - acked = {network_engine.sendAnnounceValue(sn->node, - sr->id, - a.value, - created, - sn->token, - onDone, - onExpired), - next_refresh_time}; - } else if (hasValue and a.permanent) { - if (logger_) - logger_->w(sr->id, - sn->node->id, - "[search %s] [node %s] Sending 'refresh' (vid: %016" PRIx64 - ")", - sr->id.toString().c_str(), - sn->node->toString().c_str(), - a.value->id); - acked = { - network_engine.sendRefreshValue( - sn->node, - sr->id, - a.value->id, - sn->token, - onDone, - [this, - ws, - node = sn->node, - v = a.value, - onDone, - onExpired, - created = a.permanent ? time_point::max() : a.created, - next_refresh_time](const net::Request& /*req*/, - net::DhtProtocolException&& e) { - if (e.getCode() == net::DhtProtocolException::NOT_FOUND) { - if (logger_) - logger_ - ->e(node->id, - "[node %s] Returned error 404: storage not found", - node->toString().c_str()); - if (auto sr = ws.lock()) { - if (auto sn = sr->getNode(node)) { - sn->acked[v->id] - = {network_engine.sendAnnounceValue(sn->node, - sr->id, - v, - created, - sn->token, - onDone, - onExpired), - next_refresh_time}; - scheduler.edit(sr->nextSearchStep, scheduler.time()); - return true; - } - } - } - return false; - }, - onExpired), - next_refresh_time}; - } else { - if (logger_) - logger_->w(sr->id, - sn->node->id, - "[search %s] [node %s] Already has value (vid: %016" PRIx64 - "). Aborting.", - sr->id.toString().c_str(), - sn->node->toString().c_str(), - a.value->id); - auto ack_req = std::make_shared(net::Request::State::COMPLETED); - ack_req->reply_time = now; - acked = {std::move(ack_req), next_refresh_time}; + auto next_refresh_time = now + getType(a.value->type).expiration; + auto& acked = sn->acked[a.value->id]; + scheduler.cancel(acked.refresh); + /* only put the value if the node doesn't already have it */ + if (not hasValue or seq_no < a.value->seq) { + if (logger_) + logger_->debug("[search {}] [node {}] Sending 'put' (vid: {:016x})", + sr->id.toString(), + sn->node->toString(), + a.value->id); + auto created = a.permanent ? time_point::max() : a.created; + acked = {network_engine + .sendAnnounceValue(sn->node, sr->id, a.value, created, sn->token, onDone, onExpired), + next_refresh_time}; + } else if (hasValue and a.permanent) { + if (logger_) + logger_->warn("[search {}] [node {}] Sending 'refresh' (vid: {:016x})", + sr->id.toString(), + sn->node->toString(), + a.value->id); + acked = {network_engine.sendRefreshValue( + sn->node, + sr->id, + a.value->id, + sn->token, + onDone, + [this, + ws, + node = sn->node, + v = a.value, + onDone, + onExpired, + created = a.permanent ? time_point::max() : a.created, + next_refresh_time](const net::Request& /*req*/, net::DhtProtocolException&& e) { + if (e.getCode() == net::DhtProtocolException::NOT_FOUND) { + if (logger_) + logger_->error("[node {}] Returned error 404: storage not found", + node->toString()); + if (auto sr = ws.lock()) { + if (auto sn = sr->getNode(node)) { + sn->acked[v->id] = {network_engine.sendAnnounceValue(sn->node, + sr->id, + v, + created, + sn->token, + onDone, + onExpired), + next_refresh_time}; + scheduler.edit(sr->nextSearchStep, scheduler.time()); + return true; + } + } + } + return false; + }, + onExpired), + next_refresh_time}; + } else { + if (logger_) + logger_->warn("[search {}] [node {}] Already has value (vid: {:016x}). Aborting.", + sr->id.toString(), + sn->node->toString(), + a.value->id); + auto ack_req = std::make_shared(net::Request::State::COMPLETED); + ack_req->reply_time = now; + acked = {std::move(ack_req), next_refresh_time}; - /* step to clear announces */ - scheduler.edit(sr->nextSearchStep, now); - } - if (a.permanent) { - acked.refresh = scheduler.add(next_refresh_time - REANNOUNCE_MARGIN, - std::bind(&Dht::searchStep, this, ws)); - } - } - }; + /* step to clear announces */ + scheduler.edit(sr->nextSearchStep, now); + } + if (a.permanent) { + acked.refresh = scheduler.add(next_refresh_time - REANNOUNCE_MARGIN, + std::bind(&Dht::searchStep, this, ws)); + } + } + }; static const auto PROBE_QUERY = std::make_shared( Select {}.field(Value::Field::Id).field(Value::Field::SeqNum)); @@ -641,12 +609,10 @@ Dht::searchSendAnnounceValue(const Sp& sr, unsigned syncLevel) sendQuery = true; } else { if (logger_) - logger_->w(sr->id, - n.node->id, - "[search %s] [node %s] Sending 'put' (vid: %016" PRIx64 ")", - sr->id.toString().c_str(), - n.node->toString().c_str(), - a.value->id); + logger_->warn("[search {}] [node {}] Sending 'put' (vid: {:016x})", + sr->id.toString(), + n.node->toString(), + a.value->id); n.acked[a.value->id] = {network_engine.sendAnnounceValue( n.node, sr->id, a.value, a.created, n.token, onDone, onExpired), now + getType(a.value->type).expiration}; @@ -657,12 +623,10 @@ Dht::searchSendAnnounceValue(const Sp& sr, unsigned syncLevel) if (sendQuery) { n.probe_query = PROBE_QUERY; if (logger_) - logger_->d(sr->id, - n.node->id, - "[search %s] [node %s] Sending %s", - sr->id.toString().c_str(), - n.node->toString().c_str(), - n.probe_query->toString().c_str()); + logger_->debug("[search {}] [node {}] Sending {}", + sr->id.toString(), + n.node->toString(), + n.probe_query->toString()); auto req = network_engine.sendGetValues(n.node, sr->id, *PROBE_QUERY, @@ -725,30 +689,26 @@ Dht::searchSynchedNodeListen(const Sp& sr, SearchNode& n) *query, n.token, r->second.socketId, - [this, - ws, - query](const net::Request& req, - net::RequestAnswer&& - answer) mutable { /* on done */ - if (auto sr = ws.lock()) { - scheduler.edit(sr->nextSearchStep, scheduler.time()); - if (auto sn = sr->getNode(req.node)) { - auto job = scheduler.add(sn->getListenTime(query, - getListenExpiration()), - std::bind(&Dht::searchStep, this, ws)); - sn->onListenSynced(query, true, std::move(job)); - } - onListenDone(req.node, answer, sr); - } + [this, ws, query](const net::Request& req, net::RequestAnswer&& answer) mutable { + /* on done */ + if (auto sr = ws.lock()) { + scheduler.edit(sr->nextSearchStep, scheduler.time()); + if (auto sn = sr->getNode(req.node)) { + auto job = scheduler.add(sn->getListenTime(query, getListenExpiration()), + std::bind(&Dht::searchStep, this, ws)); + sn->onListenSynced(query, true, std::move(job)); + } + onListenDone(req.node, answer, sr); + } }, - [this, ws, query](const net::Request& req, bool over) mutable { /* on request expired */ - if (auto sr = ws.lock()) { - scheduler.edit(sr->nextSearchStep, - scheduler.time()); - if (over) - if (auto sn = sr->getNode(req.node)) - sn->listenStatus.erase(query); - } + [this, ws, query](const net::Request& req, bool over) mutable { + /* on request expired */ + if (auto sr = ws.lock()) { + scheduler.edit(sr->nextSearchStep, scheduler.time()); + if (over) + if (auto sn = sr->getNode(req.node)) + sn->listenStatus.erase(query); + } }); // Here the request may have failed and the CachedListenStatus removed r = n.listenStatus.find(query); @@ -853,7 +813,7 @@ Dht::searchStep(std::weak_ptr ws) if (sr->getNumberOfConsecutiveBadNodes() >= std::min(sr->nodes.size(), SEARCH_MAX_BAD_NODES)) { if (logger_) - logger_->w(sr->id, "[search %s IPv%c] Expired", sr->id.toString().c_str(), sr->af == AF_INET ? '4' : '6'); + logger_->warn("[search {} IPv{}] Expired", sr->id.to_view(), sr->af == AF_INET ? '4' : '6'); sr->expire(); if (not public_stable) connectivityChanged(sr->af); @@ -872,10 +832,9 @@ Dht::refill(Dht::Search& sr) if (cached_nodes.empty()) { if (logger_) - logger_->e(sr.id, - "[search %s IPv%c] No nodes from cache while refilling search", - sr.id.toString().c_str(), - (sr.af == AF_INET) ? '4' : '6'); + logger_->error("[search {} IPv{}] No nodes from cache while refilling search", + sr.id.toString(), + (sr.af == AF_INET) ? '4' : '6'); return 0; } @@ -886,11 +845,10 @@ Dht::refill(Dht::Search& sr) ++inserted; } if (logger_) - logger_->d(sr.id, - "[search %s IPv%c] Refilled search with %u nodes from node cache", - sr.id.toString().c_str(), - (sr.af == AF_INET) ? '4' : '6', - inserted); + logger_->debug("[search {} IPv{}] Refilled search with {} nodes from node cache", + sr.id.toString(), + (sr.af == AF_INET) ? '4' : '6', + inserted); return inserted; } @@ -906,7 +864,7 @@ Dht::search(const InfoHash& id, { if (!isRunning(af)) { if (logger_) - logger_->e(id, "[search %s IPv%c] Unsupported protocol", id.toString().c_str(), (af == AF_INET) ? '4' : '6'); + logger_->error("[search {} IPv{}] Unsupported protocol", id.to_view(), (af == AF_INET) ? '4' : '6'); if (dcb) dcb(false, {}); return {}; @@ -934,10 +892,9 @@ Dht::search(const InfoHash& id, } if (not sr) { if (logger_) - logger_->e(id, - "[search %s IPv%c] Maximum number of searches reached!", - id.toString().c_str(), - (af == AF_INET) ? '4' : '6'); + logger_->error("[search {} IPv{}] Maximum number of searches reached!", + id.toString(), + (af == AF_INET) ? '4' : '6'); return {}; } } @@ -952,7 +909,7 @@ Dht::search(const InfoHash& id, sr->nextSearchStep = scheduler.add(time_point::max(), std::bind(&Dht::searchStep, this, std::weak_ptr(sr))); if (logger_) - logger_->w(id, "[search %s IPv%c] New search", id.toString().c_str(), (af == AF_INET) ? '4' : '6'); + logger_->warn("[search {} IPv{}] New search", id.to_view(), (af == AF_INET) ? '4' : '6'); if (search_id == 0) search_id++; } @@ -992,7 +949,7 @@ Dht::listenTo(const InfoHash& id, sa_family_t af, ValueCallback cb, Value::Filte if (!sr) throw DhtException("Unable to create search"); if (logger_) - logger_->w(id, "[search %s IPv%c] Listen", id.to_c_str(), (af == AF_INET) ? '4' : '6'); + logger_->warn("[search {} IPv{}] Listen", id.to_view(), (af == AF_INET) ? '4' : '6'); return sr->listen(cb, std::move(f), q, scheduler); } @@ -1001,7 +958,7 @@ Dht::listen(const InfoHash& id, ValueCallback cb, Value::Filter f, Where where) { if (not id) { if (logger_) - logger_->w(id, "Listen called with invalid key"); + logger_->warn("Listen called with invalid key"); return 0; } scheduler.syncTime(); @@ -1041,11 +998,11 @@ Dht::cancelListen(const InfoHash& id, size_t token) auto it = listeners.find(token); if (it == listeners.end()) { if (logger_) - logger_->w(id, "Listen token not found: %d", token); + logger_->warn("Listen token not found: {}", token); return false; } if (logger_) - logger_->d(id, "cancelListen %s with token %d", id.toString().c_str(), token); + logger_->debug("cancelListen {} with token {}", id.to_view(), token); if (auto tokenlocal = std::get<0>(it->second)) { auto st = store.find(id); if (st != store.end()) @@ -1092,7 +1049,7 @@ Dht::put(const InfoHash& id, Sp val, DoneCallback callback, time_point cr { if (not id or not val) { if (logger_) - logger_->w(id, "Put called with invalid key or value"); + logger_->warn("Put called with invalid key or value"); if (callback) callback(false, {}); return; @@ -1105,7 +1062,7 @@ Dht::put(const InfoHash& id, Sp val, DoneCallback callback, time_point cr storageStore(id, val, created, {}, permanent); if (logger_) - logger_->d(id, "put: adding %s → %s", id.toString().c_str(), val->toString().c_str()); + logger_->debug("put: adding {} → {}", id.to_view(), val->toString()); auto op = std::make_shared(); auto donecb = [callback](const std::vector>& nodes, OpStatus& op) { @@ -1121,7 +1078,7 @@ Dht::put(const InfoHash& id, Sp val, DoneCallback callback, time_point cr val, [=](bool ok4, const std::vector>& nodes) { if (logger_) - logger_->d(id, "Announce done IPv4 %d", ok4); + logger_->debug("Announce done IPv4 {}", ok4); auto& o = *op; o.status4 = {true, ok4}; donecb(nodes, o); @@ -1134,7 +1091,7 @@ Dht::put(const InfoHash& id, Sp val, DoneCallback callback, time_point cr val, [=](bool ok6, const std::vector>& nodes) { if (logger_) - logger_->d(id, "Announce done IPv6 %d", ok6); + logger_->debug("Announce done IPv6 {}", ok6); auto& o = *op; o.status6 = {true, ok6}; donecb(nodes, o); @@ -1179,7 +1136,7 @@ Dht::get(const InfoHash& id, GetCallback getcb, DoneCallback donecb, Value::Filt { if (not id) { if (logger_) - logger_->w(id, "Get called with invalid key"); + logger_->warn("Get called with invalid key"); if (donecb) donecb(false, {}); return; @@ -1247,7 +1204,7 @@ Dht::query(const InfoHash& id, QueryCallback cb, DoneCallback done_cb, Query&& q { if (not id) { if (logger_) - logger_->w(id, "Query called with invalid key"); + logger_->warn("Query called with invalid key"); if (done_cb) done_cb(false, {}); return; @@ -1395,7 +1352,7 @@ Dht::storageChanged(const InfoHash& id, Storage& st, const Sp& v, bool ne if (newValue) { if (not st.local_listeners.empty()) { if (logger_) - logger_->d(id, "[store %s] %lu local listeners", id.toString().c_str(), st.local_listeners.size()); + logger_->debug("[store {}] {} local listeners", id.to_view(), st.local_listeners.size()); std::vector>>> cbs; cbs.reserve(st.local_listeners.size()); for (const auto& l : st.local_listeners) { @@ -1404,10 +1361,7 @@ Dht::storageChanged(const InfoHash& id, Storage& st, const Sp& v, bool ne vals.push_back(v); if (not vals.empty()) { if (logger_) - logger_->d(id, - "[store %s] Sending update local listener with token %lu", - id.toString().c_str(), - l.first); + logger_->debug("[store {}] Sending update local listener with token {}", id.to_view(), l.first); cbs.emplace_back(l.second.get_cb, std::move(vals)); } } @@ -1419,19 +1373,17 @@ Dht::storageChanged(const InfoHash& id, Storage& st, const Sp& v, bool ne if (not st.listeners.empty()) { if (logger_) - logger_->d(id, "[store %s] %lu remote listeners", id.toString().c_str(), st.listeners.size()); + logger_->debug("[store {}] {} remote listeners", id.to_view(), st.listeners.size()); for (const auto& node_listeners : st.listeners) { for (const auto& l : node_listeners.second) { auto f = l.second.query.where.getFilter(); if (f and not f(*v)) continue; if (logger_) - logger_->w(id, - node_listeners.first->id, - "[store %s] [node %s] Sending update", - id.toString().c_str(), - node_listeners.first->toString().c_str()); - std::vector> vals {}; + logger_->debug("[store {}] [node {}] Sending update", + id.to_view(), + node_listeners.first->toString()); + std::vector> vals; vals.push_back(v); Blob ntoken = makeToken(node_listeners.first->getAddr(), false); network_engine.tellListener(node_listeners.first, @@ -1548,14 +1500,14 @@ void Dht::storageRemoved(const InfoHash& id, Storage& st, const std::vector>& values, size_t totalSize) { if (logger_) - logger_->d(id, "[store %s] Discarded %ld values (%ld bytes)", id.toString().c_str(), values.size(), totalSize); + logger_->debug("[store {}] Discarded {} values ({} bytes)", id.to_view(), values.size(), totalSize); total_store_size -= totalSize; total_values -= values.size(); if (not st.listeners.empty()) { if (logger_) - logger_->d(id, "[store %s] %lu remote listeners", id.toString().c_str(), st.listeners.size()); + logger_->debug("[store {}] {} remote listeners", id.to_view(), st.listeners.size()); std::vector ids; ids.reserve(values.size()); @@ -1565,11 +1517,9 @@ Dht::storageRemoved(const InfoHash& id, Storage& st, const std::vector for (const auto& node_listeners : st.listeners) { for (const auto& l : node_listeners.second) { if (logger_) - logger_->w(id, - node_listeners.first->id, - "[store %s] [node %s] Sending expired", - id.toString().c_str(), - node_listeners.first->toString().c_str()); + logger_->warn("[store {}] [node {}] Sending expired", + id.to_view(), + node_listeners.first->toString()); Blob ntoken = makeToken(node_listeners.first->getAddr(), false); network_engine.tellListenerExpired(node_listeners.first, l.first, id, ntoken, ids, l.second.version); } @@ -1589,7 +1539,7 @@ Dht::expireStore() if (i->second.empty() && i->second.listeners.empty() && i->second.local_listeners.empty()) { if (logger_) - logger_->d(i->first, "[store %s] Discarding empty storage", i->first.toString().c_str()); + logger_->debug("[store {}] Discarding empty storage", i->first.to_view()); i = store.erase(i); } else ++i; @@ -1600,7 +1550,7 @@ Dht::expireStore() // find IP using the most storage if (store_quota.empty()) { if (logger_) - logger_->w("No space left: local data consumes all the quota!"); + logger_->warn("No space left: local data consumes all the quota!"); break; } auto largest = store_quota.begin(); @@ -1614,10 +1564,10 @@ Dht::expireStore() auto storage = store.find(exp_value.first); if (storage != store.end()) { if (logger_) - logger_->w("Storage quota full: discarding value from %s at %s %016" PRIx64, - largest->first.toString().c_str(), - exp_value.first.to_c_str(), - exp_value.second); + logger_->warn("Storage quota full: discarding value from {} at {} {:016x}", + largest->first.toString(), + exp_value.first.to_view(), + exp_value.second); if (auto value = storage->second.remove(exp_value.first, exp_value.second)) { storageRemoved(storage->first, storage->second, {value}, value->size()); @@ -1854,7 +1804,7 @@ Dht::dumpTables() const out << getStorageLog() << std::endl; if (logger_) - logger_->d("%s", out.str().c_str()); + logger_->debug("{}", out.str()); } std::string @@ -2072,11 +2022,7 @@ Dht::neighbourhoodMaintenance(RoutingTable& list) auto n = q->randomNode(rd); if (n) { if (logger_) - logger_->d(id, - n->id, - "[node %s] Sending [find %s] for neighborhood maintenance", - n->toString().c_str(), - id.toString().c_str()); + logger_->debug("[node {}] Sending [find {}] for neighborhood maintenance", n->toString(), id.to_view()); /* Since our node-id is the same in both DHTs, it's probably profitable to query both families. */ network_engine.sendFindNode(n, id, network_engine.want()); @@ -2129,11 +2075,7 @@ Dht::bucketMaintenance(RoutingTable& list) } if (logger_) - logger_->d(id, - n->id, - "[node %s] Sending find %s for bucket maintenance", - n->toString().c_str(), - id.toString().c_str()); + logger_->debug("[node {}] Sending find {} for bucket maintenance", n->toString(), id.to_view()); // auto start = scheduler.time(); network_engine.sendFindNode(n, id, want, nullptr, [this, n](const net::Request&, bool over) { if (over) { @@ -2159,11 +2101,10 @@ Dht::dataPersistence(InfoHash id) auto str = store.find(id); if (str != store.end() and now > str->second.maintenance_time) { if (logger_) - logger_->d(id, - "[storage %s] Maintenance (%u values, %u bytes)", - id.toString().c_str(), - str->second.valueCount(), - str->second.totalSize()); + logger_->debug("[storage {}] Maintenance ({} values, {} bytes)", + id.to_view(), + str->second.valueCount(), + str->second.totalSize()); maintainStorage(*str); str->second.maintenance_time = now + MAX_STORAGE_MAINTENANCE_EXPIRE_TIME; scheduler.add(str->second.maintenance_time, std::bind(&Dht::dataPersistence, this, id)); @@ -2198,7 +2139,7 @@ Dht::maintainStorage(decltype(store)::value_type& storage, bool force, const Don if (not want4 and not want6) { if (logger_) - logger_->d(storage.first, "Discarding storage values %s", storage.first.toString().c_str()); + logger_->debug("Discarding storage values {}", storage.first.to_view()); auto diff = storage.second.clear(); total_store_size += diff.size_diff; total_values += diff.values_diff; @@ -2216,7 +2157,7 @@ Dht::periodic(const uint8_t* buf, size_t buflen, SockAddr from, const time_point network_engine.processMessage(buf, buflen, std::move(from)); } catch (const std::exception& e) { if (logger_) - logger_->w("Unable to process message: %s", e.what()); + logger_->warn("Unable to process message: {}", e.what()); } } return scheduler.run(); @@ -2259,7 +2200,7 @@ Dht::bootstrap() if (dht4.status != NodeStatus::Disconnected || dht6.status != NodeStatus::Disconnected) return; if (logger_) - logger_->d(myid, "Bootstraping"); + logger_->debug("[{}] Bootstraping", myid.to_view()); for (const auto& boootstrap : bootstrap_nodes) { try { auto ips = network_engine.getSocket()->resolve(boootstrap.first, boootstrap.second); @@ -2270,11 +2211,11 @@ Dht::bootstrap() } } catch (const std::exception& e) { if (logger_) - logger_->e(myid, - "Unable to resolve %s:%s: %s", - boootstrap.first.c_str(), - boootstrap.second.c_str(), - e.what()); + logger_->error("[{}] Unable to resolve {}:{}: {}", + myid.to_view(), + boootstrap.first, + boootstrap.second, + e.what()); } } scheduler.cancel(bootstrapJob); @@ -2305,12 +2246,12 @@ Dht::confirmNodes() if (dht4.searches.empty() and dht4.status == NodeStatus::Connected) { if (logger_) - logger_->d(myid, "[confirm nodes] Initial IPv4 'get' for my id (%s)", myid.toString().c_str()); + logger_->debug("[confirm nodes] Initial IPv4 'get' for my id ({})", myid.to_view()); search(myid, AF_INET); } if (dht6.searches.empty() and dht6.status == NodeStatus::Connected) { if (logger_) - logger_->d(myid, "[confirm nodes] Initial IPv6 'get' for my id (%s)", myid.toString().c_str()); + logger_->debug("[confirm nodes] Initial IPv6 'get' for my id ({})", myid.to_view()); search(myid, AF_INET6); } @@ -2386,7 +2327,7 @@ Dht::importValues(const std::vector& import) tmp_val.msgpack_unpack(valel.via.array.ptr[1]); } catch (const std::exception&) { if (logger_) - logger_->e(value.first, "Error reading value at %s", value.first.toString().c_str()); + logger_->error("Error reading value at {}", value.first.to_view()); continue; } val_time = std::min(val_time, now); @@ -2394,7 +2335,7 @@ Dht::importValues(const std::vector& import) } } catch (const std::exception&) { if (logger_) - logger_->e(value.first, "Error reading values at %s", value.first.toString().c_str()); + logger_->error("Error reading values at {}", value.first.to_view()); continue; } } @@ -2473,7 +2414,7 @@ Dht::onError(Sp req, net::DhtProtocolException e) const auto& node = req->node; if (e.getCode() == net::DhtProtocolException::UNAUTHORIZED) { if (logger_) - logger_->e(node->id, "[node %s] Token flush", node->toString().c_str()); + logger_->error("[node {}] Token flush", node->toString()); node->authError(); for (auto& srp : searches(node->getFamily())) { auto& sr = srp.second; @@ -2489,7 +2430,7 @@ Dht::onError(Sp req, net::DhtProtocolException e) } } else if (e.getCode() == net::DhtProtocolException::NOT_FOUND) { if (logger_) - logger_->e(node->id, "[node %s] Returned error 404: storage not found", node->toString().c_str()); + logger_->error("[node {}] Returned error 404: storage not found", node->toString()); node->cancelRequest(req); } } @@ -2525,7 +2466,7 @@ Dht::onGetValues(Sp node, const InfoHash& hash, want_t, const Query& query { if (not hash) { if (logger_) - logger_->w("[node %s] Eek! Got get_values with no info_hash", node->toString().c_str()); + logger_->warn("[node {}] Eek! Got get_values with no info_hash", node->toString()); throw net::DhtProtocolException {net::DhtProtocolException::NON_AUTHORITATIVE_INFORMATION, net::DhtProtocolException::GET_NO_INFOHASH}; } @@ -2538,7 +2479,7 @@ Dht::onGetValues(Sp node, const InfoHash& hash, want_t, const Query& query if (st != store.end() && not st->second.empty()) { answer.values = st->second.get(query.where.getFilter()); if (logger_) - logger_->d(hash, "[node %s] Sending %u values", node->toString().c_str(), answer.values.size()); + logger_->debug("[node {}] Sending {} values", node->toString(), answer.values.size()); } return answer; } @@ -2548,7 +2489,7 @@ Dht::onGetValuesDone(const Sp& node, net::RequestAnswer& a, Sp& sr { if (not sr) { if (logger_) - logger_->w("[search unknown] Got reply to 'get'. Ignoring."); + logger_->warn("[search unknown] Got reply to 'get'. Ignoring."); return; } @@ -2559,12 +2500,10 @@ Dht::onGetValuesDone(const Sp& node, net::RequestAnswer& a, Sp& sr if (not a.ntoken.empty()) { if (not a.values.empty() or not a.fields.empty()) { if (logger_) - logger_->d(sr->id, - node->id, - "[search %s] [node %s] Found %u values", - sr->id.toString().c_str(), - node->toString().c_str(), - a.values.size()); + logger_->debug("[search {}] [node {}] Found {} values", + sr->id.to_view(), + node->toString(), + a.values.size()); for (auto& getp : sr->callbacks) { /* call all callbacks for this search */ auto& get = getp.second; if (not(get.get_cb or get.query_cb) @@ -2604,16 +2543,14 @@ Dht::onGetValuesDone(const Sp& node, net::RequestAnswer& a, Sp& sr l.first(l.second, false);*/ } else if (not a.expired_values.empty()) { if (logger_) - logger_->w(sr->id, - node->id, - "[search %s] [node %s] %u expired values", - sr->id.toString().c_str(), - node->toString().c_str(), - a.expired_values.size()); + logger_->warn("[search {}] [node {}] {} expired values", + sr->id.toString(), + node->toString(), + a.expired_values.size()); } } else { if (logger_) - logger_->w(sr->id, "[node %s] No token provided. Ignoring response content.", node->toString().c_str()); + logger_->warn("[node {}] No token provided. Ignoring response content.", node->toString()); network_engine.blacklistNode(node); } @@ -2630,17 +2567,13 @@ Dht::onListen(Sp node, const InfoHash& hash, const Blob& token, size_t soc { if (not hash) { if (logger_) - logger_->w(node->id, "[node %s] Listen with no info_hash", node->toString().c_str()); + logger_->warn("[node {}] Listen with no info_hash", node->toString()); throw net::DhtProtocolException {net::DhtProtocolException::NON_AUTHORITATIVE_INFORMATION, net::DhtProtocolException::LISTEN_NO_INFOHASH}; } if (not tokenMatch(token, node->getAddr())) { if (logger_) - logger_->w(hash, - node->id, - "[node %s] Incorrect token %s for 'listen'", - node->toString().c_str(), - hash.toString().c_str()); + logger_->warn("[node {}] Incorrect token {} for 'listen'", node->toString(), hash.toString()); throw net::DhtProtocolException {net::DhtProtocolException::UNAUTHORIZED, net::DhtProtocolException::LISTEN_WRONG_TOKEN}; } @@ -2673,17 +2606,13 @@ Dht::onAnnounce(Sp n, auto& node = *n; if (not hash) { if (logger_) - logger_->w(node.id, "Put with no info_hash"); + logger_->warn("Put with no info_hash"); throw net::DhtProtocolException {net::DhtProtocolException::NON_AUTHORITATIVE_INFORMATION, net::DhtProtocolException::PUT_NO_INFOHASH}; } if (!tokenMatch(token, node.getAddr())) { if (logger_) - logger_->w(hash, - node.id, - "[node %s] Incorrect token %s for 'put'", - node.toString().c_str(), - hash.toString().c_str()); + logger_->warn("[node {}] Incorrect token {} for 'put'", node.toString(), hash.toString()); throw net::DhtProtocolException {net::DhtProtocolException::UNAUTHORIZED, net::DhtProtocolException::PUT_WRONG_TOKEN}; } @@ -2693,10 +2622,7 @@ Dht::onAnnounce(Sp n, auto closest_nodes = buckets(node.getFamily()).findClosestNodes(hash, scheduler.time(), SEARCH_NODES); if (closest_nodes.size() >= TARGET_NODES and hash.xorCmp(closest_nodes.back()->id, myid) < 0) { if (logger_) - logger_->w(hash, - node.id, - "[node %s] Announce too far from the target. Dropping value.", - node.toString().c_str()); + logger_->warn("[node {}] Announce too far from the target. Dropping value.", node.toString()); return {}; } } @@ -2705,7 +2631,7 @@ Dht::onAnnounce(Sp n, for (const auto& v : values) { if (v->id == Value::INVALID_ID) { if (logger_) - logger_->w(hash, node.id, "[value %s] Incorrect value id", hash.toString().c_str()); + logger_->warn("[value {}] Incorrect value id", hash.to_view()); throw net::DhtProtocolException {net::DhtProtocolException::NON_AUTHORITATIVE_INFORMATION, net::DhtProtocolException::PUT_INVALID_ID}; } @@ -2715,29 +2641,21 @@ Dht::onAnnounce(Sp n, if (*lv == *vc) { storageRefresh(hash, v->id); if (logger_) - logger_->d(hash, - node.id, - "[store %s] [node %s] Refreshed value %016" PRIx64, - hash.toString().c_str(), - node.toString().c_str(), - v->id); + logger_->debug("[store {}] [node {}] Refreshed value {:016x}", + hash.toString(), + node.toString(), + v->id); } else { const auto& type = getType(lv->type); if (type.editPolicy(hash, lv, vc, node.id, node.getAddr())) { if (logger_) - logger_->d(hash, - node.id, - "[store %s] Editing %s", - hash.toString().c_str(), - vc->toString().c_str()); + logger_->debug("[store {}] Editing {}", hash.toString(), vc->toString()); storageStore(hash, vc, created, node.getAddr()); } else { if (logger_) - logger_->d(hash, - node.id, - "[store %s] Rejecting edition of %s because of storage policy", - hash.toString().c_str(), - vc->toString().c_str()); + logger_->debug("[store {}] Rejecting edition of {} because of storage policy", + hash.toString(), + vc->toString()); } } } else { @@ -2750,11 +2668,7 @@ Dht::onAnnounce(Sp n, storageStore(hash, vc, created, node.getAddr()); } else { if (logger_) - logger_->d(hash, - node.id, - "[store %s] Rejecting storage of %s", - hash.toString().c_str(), - vc->toString().c_str()); + logger_->debug("[store {}] Rejecting storage of {}", hash.toString(), vc->toString()); } } } @@ -2768,28 +2682,15 @@ Dht::onRefresh(Sp node, const InfoHash& hash, const Blob& token, const Val if (not tokenMatch(token, node->getAddr())) { if (logger_) - logger_->w(hash, - node->id, - "[node %s] Incorrect token %s for 'put'", - node->toString().c_str(), - hash.toString().c_str()); + logger_->warn("[node {}] Incorrect token {} for 'put'", node->toString(), hash.toString()); throw DhtProtocolException {DhtProtocolException::UNAUTHORIZED, DhtProtocolException::PUT_WRONG_TOKEN}; } if (storageRefresh(hash, vid)) { if (logger_) - logger_->d(hash, - node->id, - "[store %s] [node %s] Refreshed value %016" PRIx64, - hash.toString().c_str(), - node->toString().c_str(), - vid); + logger_->debug("[store {}] [node {}] Refreshed value {:016x}", hash.toString(), node->toString(), vid); } else { if (logger_) - logger_->d(hash, - node->id, - "[store %s] [node %s] Got refresh for unknown value", - hash.toString().c_str(), - node->toString().c_str()); + logger_->debug("[store {}] [node {}] Got refresh for unknown value", hash.toString(), node->toString()); throw DhtProtocolException {DhtProtocolException::NOT_FOUND, DhtProtocolException::STORAGE_NOT_FOUND}; } return {}; @@ -2806,16 +2707,14 @@ Dht::storageRefresh(const InfoHash& id, Value::Id vid) auto& st = s->second; if (not st.listeners.empty()) { if (logger_) - logger_->d(id, "[store %s] %lu remote listeners", id.toString().c_str(), st.listeners.size()); + logger_->debug("[store {}] {} remote listeners", id.to_view(), st.listeners.size()); std::vector ids = {vid}; for (const auto& node_listeners : st.listeners) { for (const auto& l : node_listeners.second) { if (logger_) - logger_->w(id, - node_listeners.first->id, - "[store %s] [node %s] Sending refresh", - id.toString().c_str(), - node_listeners.first->toString().c_str()); + logger_->warn("[store {}] [node {}] Sending refresh", + id.toString(), + node_listeners.first->toString()); Blob ntoken = makeToken(node_listeners.first->getAddr(), false); network_engine .tellListenerRefreshed(node_listeners.first, l.first, id, ntoken, ids, l.second.version); @@ -2840,11 +2739,7 @@ void Dht::onAnnounceDone(const Sp& node, net::RequestAnswer& answer, Sp& sr) { if (logger_) - logger_->d(sr->id, - node->id, - "[search %s] [node %s] Got reply to put!", - sr->id.toString().c_str(), - node->toString().c_str()); + logger_->debug("[search {}] [node {}] Got reply to put!", sr->id.toString(), node->toString()); searchSendGetValues(sr); sr->checkAnnounced(answer.vid); } @@ -2874,7 +2769,7 @@ void Dht::loadState(const std::string& path) { if (logger_) - logger_->d("Importing state from %s", path.c_str()); + logger_->debug("Importing state from {}", path); try { // Import nodes from binary file msgpack::unpacker pac; @@ -2895,7 +2790,7 @@ Dht::loadState(const std::string& path) if (pac.next(oh)) { auto state = oh.get().as(); if (logger_) - logger_->d("Importing %zu nodes", state.nodes.size()); + logger_->debug("Importing {} nodes", state.nodes.size()); if (state.id) myid = state.id; std::vector> tmpNodes; @@ -2906,7 +2801,7 @@ Dht::loadState(const std::string& path) } } catch (const std::exception& e) { if (logger_) - logger_->w("Error importing state from %s: %s", path.c_str(), e.what()); + logger_->warn("Error importing state from {}: {}", path, e.what()); } } diff --git a/src/dht_proxy_client.cpp b/src/dht_proxy_client.cpp index 285f0905..323f8f1d 100644 --- a/src/dht_proxy_client.cpp +++ b/src/dht_proxy_client.cpp @@ -127,25 +127,25 @@ DhtProxyClient::DhtProxyClient(std::shared_ptr serverC jsonBuilder_["indentation"] = ""; if (logger_) { if (serverCertificate_) - logger_->d("[proxy:client] using ca certificate for ssl:\n%s", - serverCertificate_->toString(false /*chain*/).c_str()); + logger_->debug("[proxy:client] using ca certificate for ssl:\n{}", + serverCertificate_->toString(false /*chain*/)); if (clientIdentity_.first and clientIdentity_.second) - logger_->d("[proxy:client] using client certificate for ssl:\n%s", - clientIdentity_.second->toString(false /*chain*/).c_str()); + logger_->debug("[proxy:client] using client certificate for ssl:\n{}", + clientIdentity_.second->toString(false /*chain*/)); } // run http client httpClientThread_ = std::thread([this]() { try { if (logger_) - logger_->d("[proxy:client] starting io_context"); + logger_->debug("[proxy:client] starting io_context"); // Ensures the httpContext_ won't run out of work auto work = asio::make_work_guard(httpContext_); httpContext_.run(); if (logger_) - logger_->d("[proxy:client] http client io_context stopped"); + logger_->debug("[proxy:client] http client io_context stopped"); } catch (const std::exception& ex) { if (logger_) - logger_->e("[proxy:client] run error: %s", ex.what()); + logger_->error("[proxy:client] run error: {}", ex.what()); } }); if (!proxyUrl_.empty()) @@ -159,7 +159,7 @@ DhtProxyClient::startProxy() return; if (logger_) - logger_->d("[proxy:client] start proxy with %s", proxyUrl_.c_str()); + logger_->debug("[proxy:client] start proxy with {}", proxyUrl_); nextProxyConfirmationTimer_ = std::make_unique(httpContext_, std::chrono::steady_clock::now()); nextProxyConfirmationTimer_->async_wait(std::bind(&DhtProxyClient::handleProxyConfirm, this, std::placeholders::_1)); @@ -176,7 +176,7 @@ DhtProxyClient::handleProxyConfirm(const asio::error_code& ec) return; else if (ec) { if (logger_) - logger_->e("[proxy:client] confirm error: %s", ec.message().c_str()); + logger_->error("[proxy:client] confirm error: {}", ec.message()); return; } if (proxyUrl_.empty()) @@ -241,7 +241,7 @@ DhtProxyClient::cancelAllListeners() { std::lock_guard lock(searchLock_); if (logger_) - logger_->d("[proxy:client] [listeners] [%zu searches] cancel all", searches_.size()); + logger_->debug("[proxy:client] [listeners] [{} searches] cancel all", searches_.size()); for (auto& s : searches_) { s.second.ops.cancelAll([&](size_t token) { auto l = s.second.listeners.find(token); @@ -317,7 +317,7 @@ void DhtProxyClient::get(const InfoHash& key, GetCallback cb, DoneCallback donecb, Value::Filter&& f, Where&& w) { if (logger_) - logger_->d("[proxy:client] [get] [search %s]", key.to_c_str()); + logger_->debug("[proxy:client] [get] [search {}]", key.to_view()); if (isDestroying_) { if (donecb) @@ -368,14 +368,14 @@ DhtProxyClient::get(const InfoHash& key, GetCallback cb, DoneCallback donecb, Va } } catch (const std::exception& e) { if (logger_) - logger_->e("[proxy:client] [get %s] body parsing error: %s", key.to_c_str(), e.what()); + logger_->error("[proxy:client] [get {}] body parsing error: {}", key.to_view(), e.what()); opstate->ok.store(false); } }); request->add_on_done_callback([this, reqid, opstate, donecb, key](const http::Response& response) { if (response.status_code != 200) { if (logger_) - logger_->e("[proxy:client] [get %s] failed with code=%i", key.to_c_str(), response.status_code); + logger_->error("[proxy:client] [get {}] failed with code={}", key.to_view(), response.status_code); opstate->ok.store(false); if (not response.aborted and response.status_code == 0) opFailed(); @@ -402,7 +402,7 @@ DhtProxyClient::get(const InfoHash& key, GetCallback cb, DoneCallback donecb, Va request->send(); } catch (const std::exception& e) { if (logger_) - logger_->e("[proxy:client] [get %s] error: %s", key.to_c_str(), e.what()); + logger_->error("[proxy:client] [get {}] error: {}", key.to_view(), e.what()); } } @@ -415,7 +415,7 @@ DhtProxyClient::put(const InfoHash& key, Sp val, DoneCallback cb, time_po return; } if (logger_) - logger_->d("[proxy:client] [put] [search %s]", key.to_c_str()); + logger_->debug("[proxy:client] [put] [search {}]", key.to_view()); std::shared_ptr ok; if (permanent) { @@ -459,11 +459,11 @@ DhtProxyClient::handleRefreshPut(const asio::error_code& ec, InfoHash key, Value return; else if (ec) { if (logger_) - logger_->e("[proxy:client] [put] [refresh %s] %s", key.toString().c_str(), ec.message().c_str()); + logger_->error("[proxy:client] [put] [refresh {}] {}", key.to_view(), ec.message()); return; } if (logger_) - logger_->d("[proxy:client] [put] [refresh %s]", key.to_c_str()); + logger_->debug("[proxy:client] [put] [refresh {}]", key.to_view()); std::lock_guard lock(searchLock_); auto search = searches_.find(key); if (search != searches_.end()) { @@ -623,7 +623,7 @@ DhtProxyClient::cancelPut(const InfoHash& key, const Value::Id& id) if (search == searches_.end()) return false; if (logger_) - logger_->d("[proxy:client] [put] [search %s] cancel", key.to_c_str()); + logger_->debug("[proxy:client] [put] [search {}] cancel", key.to_view()); return search->second.puts.erase(id) > 0; } @@ -637,7 +637,7 @@ void DhtProxyClient::getProxyInfos() { if (logger_) - logger_->d("[proxy:client] [info] requesting proxy server node information"); + logger_->debug("[proxy:client] [info] requesting proxy server node information"); auto infoState = std::make_shared(); { std::lock_guard l(lockCurrentProxyInfos_); @@ -650,7 +650,7 @@ DhtProxyClient::getProxyInfos() statusIpv6_ = NodeStatus::Connecting; } if (logger_) - logger_->d("[proxy:client] [status] sending request"); + logger_->debug("[proxy:client] [status] sending request"); auto resolver = std::make_shared(httpContext_, proxyUrl_, logger_); queryProxyInfo(infoState, resolver, AF_INET); @@ -663,7 +663,7 @@ void DhtProxyClient::queryProxyInfo(const Sp& infoState, const Sp& resolver, sa_family_t family) { if (logger_) - logger_->d("[proxy:client] [status] query ipv%i info", family == AF_INET ? 4 : 6); + logger_->debug("[proxy:client] [status] query ipv{} info", family == AF_INET ? 4 : 6); try { auto request = std::make_shared(httpContext_, resolver, family); if (serverCertificate_) @@ -676,9 +676,9 @@ DhtProxyClient::queryProxyInfo(const Sp& infoState, const Spe("[proxy:client] [status] ipv%i failed with code=%i", - family == AF_INET ? 4 : 6, - response.status_code); + logger_->error("[proxy:client] [status] ipv{} failed with code={}", + family == AF_INET ? 4 : 6, + response.status_code); // pass along the failures if ((family == AF_INET and infoState->ipv4 == 0) or (family == AF_INET6 and infoState->ipv6 == 0)) onProxyInfos(Json::Value {}, family); @@ -715,7 +715,7 @@ DhtProxyClient::queryProxyInfo(const Sp& infoState, const Spsend(); } catch (const std::exception& e) { if (logger_) - logger_->e("[proxy:client] [status] error sending request: %s", e.what()); + logger_->error("[proxy:client] [status] error sending request: {}", e.what()); } } @@ -732,7 +732,7 @@ DhtProxyClient::onProxyInfos(const Json::Value& proxyInfos, const sa_family_t fa auto& localAddress = family == AF_INET ? localAddrv4_ : localAddrv6_; if (not proxyInfos.isMember("node_id")) { if (logger_) - logger_->e("[proxy:client] [info] request failed for %s", family == AF_INET ? "ipv4" : "ipv6"); + logger_->error("[proxy:client] [info] request failed for {}", family == AF_INET ? "ipv4" : "ipv6"); status = NodeStatus::Disconnected; if (pubAddress) { pubAddress = {}; @@ -778,7 +778,7 @@ DhtProxyClient::onProxyInfos(const Json::Value& proxyInfos, const sa_family_t fa } catch (const std::exception& e) { if (logger_) - logger_->e("[proxy:client] [info] error processing: %s", e.what()); + logger_->error("[proxy:client] [info] error processing: {}", e.what()); } } auto newStatus = std::max(statusIpv4_, statusIpv6_); @@ -839,7 +839,7 @@ size_t DhtProxyClient::listen(const InfoHash& key, ValueCallback cb, Value::Filter filter, Where where) { if (logger_) - logger_->d("[proxy:client] [listen] [search %s]", key.to_c_str()); + logger_->debug("[proxy:client] [listen] [search {}]", key.to_view()); if (isDestroying_) return 0; @@ -852,13 +852,13 @@ DhtProxyClient::listen(const InfoHash& key, ValueCallback cb, Value::Filter filt auto search = searches_.find(key); if (search == searches_.end()) { if (logger_) - logger_->e("[proxy:client] [listen] [search %s] search not found", key.to_c_str()); + logger_->error("[proxy:client] [listen] [search {}] search not found", key.to_view()); return 0; } if (logger_) - logger_->d("[proxy:client] [listen] [search %s] sending %s", - key.to_c_str(), - deviceKey_.empty() ? "listen" : "subscribe"); + logger_->debug("[proxy:client] [listen] [search {}] sending {}", + key.to_view(), + deviceKey_.empty() ? "listen" : "subscribe"); // Add listener auto token = ++listenerToken_; auto l = search->second.listeners.find(token); @@ -930,7 +930,7 @@ DhtProxyClient::handleResubscribe(const asio::error_code& ec, return; else if (ec) { if (logger_) - logger_->e("[proxy:client] [resubscribe %s] %s", key.toString().c_str(), ec.message().c_str()); + logger_->error("[proxy:client] [resubscribe {}] {}", key.to_view(), ec.message()); return; } if (opstate->stop) @@ -943,7 +943,7 @@ DhtProxyClient::handleResubscribe(const asio::error_code& ec, resubscribe(key, token, l->second); } else { if (logger_) - logger_->e("[proxy:client] [resubscribe %s] token not found", key.toString().c_str()); + logger_->error("[proxy:client] [resubscribe {}] token not found", key.to_view()); } } } @@ -952,7 +952,7 @@ bool DhtProxyClient::cancelListen(const InfoHash& key, size_t gtoken) { if (logger_) - logger_->d(key, "[proxy:client] [search %s] cancel listen %zu", key.to_c_str(), gtoken); + logger_->debug("[proxy:client] [search {}] cancel listen {}", key.to_view(), gtoken); std::lock_guard lock(searchLock_); // find the listener in cache @@ -979,11 +979,11 @@ DhtProxyClient::handleExpireListener(const asio::error_code& ec, const InfoHash& return; else if (ec) { if (logger_) - logger_->e("[proxy:client] [listen %s] error in cancel: %s", key.toString().c_str(), ec.message().c_str()); + logger_->error("[proxy:client] [listen {}] error in cancel: {}", key.to_view(), ec.message()); return; } if (logger_) - logger_->d("[proxy:client] [listen %s] expire listener", key.toString().c_str()); + logger_->debug("[proxy:client] [listen {}] expire listener", key.to_view()); std::lock_guard lock(searchLock_); auto search = searches_.find(key); @@ -1014,9 +1014,9 @@ DhtProxyClient::handleExpireListener(const asio::error_code& ec, const InfoHash& request->add_on_done_callback([this, reqid, key](const http::Response& response) { if (response.status_code != 200) { if (logger_) - logger_->e("[proxy:client] [unsubscribe %s] failed with code=%i", - key.to_c_str(), - response.status_code); + logger_->error("[proxy:client] [unsubscribe {}] failed with code={}", + key.to_view(), + response.status_code); if (not response.aborted and response.status_code == 0) opFailed(); } @@ -1032,7 +1032,7 @@ DhtProxyClient::handleExpireListener(const asio::error_code& ec, const InfoHash& request->send(); } catch (const std::exception& e) { if (logger_) - logger_->e("[proxy:client] [unsubscribe %s] failed: %s", key.to_c_str(), e.what()); + logger_->error("[proxy:client] [unsubscribe {}] failed: {}", key.to_view(), e.what()); } } else { // stop the request @@ -1043,9 +1043,9 @@ DhtProxyClient::handleExpireListener(const asio::error_code& ec, const InfoHash& } search->second.listeners.erase(it); if (logger_) - logger_->d("[proxy:client] [listen:cancel] [search %s] %zu listener remaining", - key.to_c_str(), - search->second.listeners.size()); + logger_->debug("[proxy:client] [listen:cancel] [search {}] {} listener remaining", + key.to_view(), + search->second.listeners.size()); }); if (next != time_point::max()) { search->second.opExpirationTimer->expires_at(next); @@ -1065,7 +1065,7 @@ DhtProxyClient::sendListen(const restinio::http_request_header_t& header, ListenMethod method) { if (logger_) - logger_->e("[proxy:client] [listen] sendListen: %d", (int) method); + logger_->error("[proxy:client] [listen] sendListen: {}", (int) method); try { auto request = buildRequest(); listener.request = request; @@ -1115,16 +1115,16 @@ DhtProxyClient::sendListen(const restinio::http_request_header_t& header, } } catch (const std::exception& e) { if (logger_) - logger_->e("[proxy:client] [listen] request #%i error in parsing: %s", reqid, e.what()); + logger_->error("[proxy:client] [listen] request #{} error in parsing: {}", reqid, e.what()); opstate->ok.store(false); } }); request->add_on_done_callback([this, opstate, reqid](const http::Response& response) { if (response.status_code != 200) { if (logger_) - logger_->e("[proxy:client] [listen] send request #%i failed with code=%i", - reqid, - response.status_code); + logger_->error("[proxy:client] [listen] send request #{} failed with code={}", + reqid, + response.status_code); opstate->ok.store(false); if (not response.aborted and response.status_code == 0) opFailed(); @@ -1147,7 +1147,7 @@ DhtProxyClient::sendListen(const restinio::http_request_header_t& header, request->send(); } catch (const std::exception& e) { if (logger_) - logger_->e("[proxy:client] [listen] request failed: %s", e.what()); + logger_->error("[proxy:client] [listen] request failed: {}", e.what()); } } @@ -1157,7 +1157,7 @@ DhtProxyClient::opFailed() if (isDestroying_) return; if (logger_) - logger_->e("[proxy:client] proxy request failed"); + logger_->error("[proxy:client] proxy request failed"); { std::lock_guard l(lockCurrentProxyInfos_); statusIpv4_ = NodeStatus::Disconnected; @@ -1212,7 +1212,7 @@ DhtProxyClient::restartListeners(const asio::error_code& ec) } if (not deviceKey_.empty()) { if (logger_) - logger_->d("[proxy:client] [listeners] resubscribe due to a connectivity change"); + logger_->debug("[proxy:client] [listeners] resubscribe due to a connectivity change"); // Connectivity changed, refresh all subscribe for (auto& search : searches_) for (auto& listener : search.second.listeners) @@ -1221,7 +1221,7 @@ DhtProxyClient::restartListeners(const asio::error_code& ec) return; } if (logger_) - logger_->d("[proxy:client] [listeners] restarting listeners"); + logger_->debug("[proxy:client] [listeners] restarting listeners"); for (auto& search : searches_) { for (auto& l : search.second.listeners) { auto& listener = l.second; @@ -1267,7 +1267,7 @@ DhtProxyClient::pushNotificationReceived([[maybe_unused]] const std::mapsecond != pushSessionId_) { if (logger_) - logger_->d("[proxy:client] [push] ignoring push for other session"); + logger_->debug("[proxy:client] [push] ignoring push for other session"); return PushNotificationResult::IgnoredWrongSession; } std::lock_guard lock(searchLock_); @@ -1308,7 +1308,7 @@ DhtProxyClient::pushNotificationReceived([[maybe_unused]] const std::mapstop) continue; if (logger_) - logger_->d("[proxy:client] [push] [search %s] received", key.to_c_str()); + logger_->debug("[proxy:client] [push] [search {}] received", key); auto token = list.first; auto opstate = list.second.opstate; if (expired == notification.end()) { @@ -1356,7 +1356,7 @@ DhtProxyClient::pushNotificationReceived([[maybe_unused]] const std::mape("[proxy:client] [push] receive error: %s", e.what()); + logger_->error("[proxy:client] [push] receive error: {}", e.what()); ret = PushNotificationResult::Error; } if (launchLoop) @@ -1374,7 +1374,7 @@ DhtProxyClient::resubscribe([[maybe_unused]] const InfoHash& key, if (deviceKey_.empty()) return; if (logger_) - logger_->d("[proxy:client] [resubscribe] [search %s]", key.to_c_str()); + logger_->debug("[proxy:client] [resubscribe] [search {}]", key); auto opstate = listener.opstate; listener.request.reset(); // This will update ok to false @@ -1433,7 +1433,7 @@ DhtProxyClient::setPushNotificationToken([[maybe_unused]] const std::string& tok deviceKey_ = token; if (statusIpv4_ == NodeStatus::Connected || statusIpv6_ == NodeStatus::Connected) { if (logger_) - logger_->d("[proxy:client] [push] token changed, resubscribing"); + logger_->debug("[proxy:client] [push] token changed, resubscribing"); for (auto& search : searches_) { for (auto& listener : search.second.listeners) { resubscribe(search.first, listener.first, listener.second); diff --git a/src/dht_proxy_server.cpp b/src/dht_proxy_server.cpp index 9cd12bd6..421b0386 100644 --- a/src/dht_proxy_server.cpp +++ b/src/dht_proxy_server.cpp @@ -72,21 +72,21 @@ public: void info(Builder&& msg_builder) { if (m_logger) - m_logger->d("[proxy:server] %s", msg_builder().c_str()); + m_logger->debug("[proxy:server] {}", msg_builder()); } template void warn(Builder&& msg_builder) { if (m_logger) - m_logger->w("[proxy:server] %s", msg_builder().c_str()); + m_logger->warn("[proxy:server] {}", msg_builder()); } template void error(Builder&& msg_builder) { if (m_logger) - m_logger->e("[proxy:server] %s", msg_builder().c_str()); + m_logger->error("[proxy:server] {}", msg_builder()); } private: @@ -182,7 +182,9 @@ DhtProxyServer::onConnectionClosed(restinio::connection_id_t id) dht_->cancelListen(it->second.hash, std::move(it->second.token)); listeners_.erase(it); if (logger_) - logger_->d("[proxy:server] [connection:%li] listener cancelled, %li still connected", id, listeners_.size()); + logger_->debug("[proxy:server] [connection:{}] listener cancelled, {} still connected", + id, + listeners_.size()); } } @@ -322,7 +324,7 @@ DhtProxyServer::DhtProxyServer(const std::shared_ptr& dht, if (ec) throw std::runtime_error("Error setting certificate chain: " + ec.message()); if (logger_) - logger_->d("[proxy:server] using certificate chain for ssl:\n%s", certchain.c_str()); + logger_->debug("[proxy:server] using certificate chain for ssl:\n{}", certchain); // build http server auto settings = restinio::run_on_this_thread_settings_t(); addServerSettings(settings); @@ -362,15 +364,12 @@ DhtProxyServer::DhtProxyServer(const std::shared_ptr& dht, std::streamsize size = stateFile.tellg(); stateFile.seekg(0, std::ios::beg); if (logger_) - logger_->d("Loading proxy state from %.*s (%td bytes)", - (int) persistPath_.size(), - persistPath_.c_str(), - size); + logger_->debug("[proxy:server] Loading proxy state from {} ({} bytes)", persistPath_, size); loadState(stateFile, size); } } catch (const std::exception& e) { if (logger_) - logger_->e("Error loading state from file: %s", e.what()); + logger_->error("[proxy:server] Error loading state from file: {}", e.what()); } } } @@ -412,7 +411,7 @@ DhtProxyServer::loadState(Is& is, size_t size) std::lock_guard lock(lockSearchPuts_); puts_ = puts->as(); if (logger_) - logger_->d("Loading %zu persistent puts", puts_.size()); + logger_->debug("[proxy:server] Loading {} persistent puts", puts_.size()); for (auto& put : puts_) { for (auto& pput : put.second.puts) { pput.second.expireTimer = std::make_unique(io_context(), @@ -456,14 +455,14 @@ DhtProxyServer::loadState(Is& is, size_t size) } } else { if (logger_) - logger_->d("No persistent puts in state"); + logger_->debug("No persistent puts in state"); } #ifdef OPENDHT_PUSH_NOTIFICATIONS if (auto pushListeners = findMapValue(oh.get(), "pushListeners"sv)) { std::lock_guard lock(lockListener_); pushListeners_ = pushListeners->as(); if (logger_) - logger_->d("Loading %zu push listeners", pushListeners_.size()); + logger_->debug("[proxy:server] Loading {} push listeners", pushListeners_.size()); for (auto& pushListener : pushListeners_) { for (auto& listeners : pushListener.second.listeners) { for (auto& listener : listeners.second) { @@ -523,12 +522,12 @@ DhtProxyServer::loadState(Is& is, size_t size) } } else { if (logger_) - logger_->d("No push listeners in state"); + logger_->debug("[proxy:server] No push listeners in state"); } #endif } if (logger_) - logger_->d("loading ended"); + logger_->debug("[proxy:server] loading ended"); } } @@ -542,7 +541,7 @@ DhtProxyServer::~DhtProxyServer() { if (not persistPath_.empty()) { if (logger_) - logger_->d("Saving proxy state to %.*s", (int) persistPath_.size(), persistPath_.c_str()); + logger_->debug("[proxy:server] Saving proxy state to {}", persistPath_); std::ofstream stateFile(persistPath_, std::ios::binary); saveState(stateFile); } @@ -568,12 +567,12 @@ DhtProxyServer::~DhtProxyServer() #endif } if (logger_) - logger_->d("[proxy:server] closing http server"); + logger_->debug("[proxy:server] closing http server"); ioContext_->stop(); if (serverThread_.joinable()) serverThread_.join(); if (logger_) - logger_->d("[proxy:server] http server closed"); + logger_->debug("[proxy:server] http server closed"); } template @@ -647,7 +646,7 @@ DhtProxyServer::updateStats() nodeInfo_ = newInfo; if (logger_) { auto str = Json::writeString(jsonBuilder_, newInfo->toJson()); - logger_->d("[proxy:server] [stats] %s", str.c_str()); + logger_->debug("[proxy:server] [stats] {}", str); } }); } @@ -929,10 +928,7 @@ DhtProxyServer::subscribe(restinio::request_handle_t request, restinio::router:: auto sessionId = root["session_id"].asString(); if (logger_) - logger_->d("[proxy:server] [subscribe %s] [client %s] [session %s]", - infoHash.toString().c_str(), - clientId.c_str(), - sessionId.c_str()); + logger_->debug("[proxy:server] [subscribe {}] [client {}] [session {}]", infoHash, clientId, sessionId); // Insert new or return existing push listeners of a token std::lock_guard lock(lockListener_); @@ -992,9 +988,7 @@ DhtProxyServer::subscribe(restinio::request_handle_t request, restinio::router:: // Send response if (not newListener) { if (logger_) - logger_->d("[proxy:server] [subscribe %s] found [client %s]", - infoHash.toString().c_str(), - listener.clientId.c_str()); + logger_->debug("[proxy:server] [subscribe {}] found [client {}]", infoHash, listener.clientId); // Send response header auto response = std::make_shared( initHttpResponse(request->create_response())); @@ -1019,7 +1013,7 @@ DhtProxyServer::subscribe(restinio::request_handle_t request, restinio::router:: // =========== No existing listener for an infoHash ============ // Add listen on dht if (logger_) - logger_->d("[proxy:server] [subscribe %s] new", infoHash.toString().c_str()); + logger_->debug("[proxy:server] [subscribe {}] new", infoHash); listener.internalToken = dht_->listen(infoHash, [this, infoHash, @@ -1058,7 +1052,7 @@ DhtProxyServer::unsubscribe(restinio::request_handle_t request, restinio::router infoHash = InfoHash::get(params["hash"]); if (logger_) - logger_->d("[proxy:server] [unsubscribe %s]", infoHash.toString().c_str()); + logger_->debug("[proxy:server] [unsubscribe {}]", infoHash); try { std::string err; @@ -1095,10 +1089,10 @@ DhtProxyServer::handleNotifyPushListenExpire(const asio::error_code& ec, return; else if (ec) { if (logger_) - logger_->e("[proxy:server] [subscribe] error sending put refresh: %s", ec.message().c_str()); + logger_->error("[proxy:server] [subscribe] error sending put refresh: {}", ec.message()); } if (logger_) - logger_->d("[proxy:server] [subscribe] sending refresh to %s token", pushToken.c_str()); + logger_->debug("[proxy:server] [subscribe] sending refresh to {} token", pushToken); sendPushNotification(pushToken, jsonProvider(), type, false, topic); } @@ -1112,10 +1106,10 @@ DhtProxyServer::handleCancelPushListen(const asio::error_code& ec, return; else if (ec) { if (logger_) - logger_->e("[proxy:server] [listen:push %s] error cancel: %s", key.toString().c_str(), ec.message().c_str()); + logger_->error("[proxy:server] [listen:push {}] error cancel: {}", key, ec.message()); } if (logger_) - logger_->d("[proxy:server] [listen:push %s] cancelled for %s", key.toString().c_str(), clientId.c_str()); + logger_->debug("[proxy:server] [listen:push {}] cancelled for {}", key, clientId); std::lock_guard lock(lockListener_); auto pushListener = pushListeners_.find(pushToken); @@ -1182,13 +1176,13 @@ DhtProxyServer::handlePushListen(const InfoHash& infoHash, minPriority = std::min(minPriority, v->priority); if (logger_) - logger_->d("[proxy:server] [listen %s] [client %s] [session %s] [expired %i] [priority %i] [values %zu]", - infoHash.toString().c_str(), - clientId.c_str(), - sessionCtx->sessionId.c_str(), - expired, - minPriority, - values.size()); + logger_->debug("[proxy:server] [listen {}] [client {}] [session {}] [expired {}] [priority {}] [values {}]", + infoHash, + clientId, + sessionCtx->sessionId, + expired, + minPriority, + values.size()); sendPushNotification(pushToken, std::move(json), type, !expired and minPriority == 0, topic); @@ -1251,7 +1245,7 @@ DhtProxyServer::sendPushNotification( request->set_body(std::string(encrypted.begin(), encrypted.end())); } catch (const std::exception& e) { if (logger_) - logger_->e("[proxy:server] [notification] encryption failed: %s", e.what()); + logger_->error("[proxy:server] [notification] encryption failed: {}", e.what()); return; } } else { @@ -1307,7 +1301,7 @@ DhtProxyServer::sendPushNotification( request->add_on_state_change_callback([this, reqid](http::Request::State state, const http::Response& response) { if (state == http::Request::State::DONE) { if (logger_ and response.status_code != 200) - logger_->e("[proxy:server] [notification] push failed: %i", response.status_code); + logger_->error("[proxy:server] [notification] push failed: {}", response.status_code); std::lock_guard l(requestLock_); requests_.erase(reqid); } @@ -1334,7 +1328,7 @@ DhtProxyServer::sendPushNotification( } } catch (const std::exception& e) { if (logger_) - logger_->e("[proxy:server] [notification] error send push: %s", e.what()); + logger_->error("[proxy:server] [notification] error send push: {}", e.what()); if (reqid) { std::lock_guard l(requestLock_); requests_.erase(reqid); @@ -1351,10 +1345,10 @@ DhtProxyServer::handleCancelPermamentPut(const asio::error_code& ec, const InfoH return; else if (ec) { if (logger_) - logger_->e("[proxy:server] [put:permament] error sending put refresh: %s", ec.message().c_str()); + logger_->error("[proxy:server] [put:permament] error sending put refresh: {}", ec.message()); } if (logger_) - logger_->d("[proxy:server] [put %s] cancel permament put %i", key.toString().c_str(), vid); + logger_->debug("[proxy:server] [put {}] cancel permament put {}", key, vid); std::lock_guard lock(lockSearchPuts_); auto sPuts = puts_.find(key); if (sPuts == puts_.end()) @@ -1398,10 +1392,10 @@ DhtProxyServer::put(restinio::request_handle_t request, restinio::router::route_ auto value = std::make_shared(root); bool permanent = root.isMember("permanent"); if (logger_) - logger_->d("[proxy:server] [put %s] %s %s", - infoHash.toString().c_str(), - value->toString().c_str(), - (permanent ? "permanent" : "")); + logger_->debug("[proxy:server] [put {}] {} {}", + infoHash, + value->toString(), + (permanent ? "permanent" : "")); if (permanent) { std::string pushToken, clientId, sessionId, platform, topic; auto& pVal = root["permanent"]; @@ -1525,7 +1519,7 @@ DhtProxyServer::put(restinio::request_handle_t request, restinio::router::route_ } } catch (const std::exception& e) { if (logger_) - logger_->d("[proxy:server] error in put: %s", e.what()); + logger_->error("[proxy:server] error in put: {}", e.what()); return serverError(*request); } } @@ -1575,7 +1569,7 @@ DhtProxyServer::putSigned(restinio::request_handle_t request, restinio::router:: } } catch (const std::exception& e) { if (logger_) - logger_->d("[proxy:server] error in putSigned: %s", e.what()); + logger_->error("[proxy:server] error in putSigned: {}", e.what()); return serverError(*request); } } @@ -1627,7 +1621,7 @@ DhtProxyServer::putEncrypted(restinio::request_handle_t request, restinio::route } } catch (const std::exception& e) { if (logger_) - logger_->d("[proxy:server] error in put: %s", e.what()); + logger_->error("[proxy:server] error in put: {}", e.what()); return serverError(*request); } } diff --git a/src/http.cpp b/src/http.cpp index c7f72cdd..79521d10 100644 --- a/src/http.cpp +++ b/src/http.cpp @@ -1546,10 +1546,10 @@ Request::handle_response(const asio::error_code& ec, size_t /* n_bytes */) enum llhttp_errno ret = llhttp_execute(parser_.get(), request.c_str(), request.size()); if (ret != HPE_OK && ret != HPE_PAUSED) { if (logger_) - logger_->e("Error parsing HTTP: %zu %s %d", - (int) ret, - llhttp_errno_name(ret), - llhttp_get_error_reason(parser_.get())); + logger_->error("Error parsing HTTP: {} {} {}", + (int) ret, + llhttp_errno_name(ret), + llhttp_get_error_reason(parser_.get())); terminate(asio::error::basic_errors::broken_pipe); return; } @@ -1589,14 +1589,14 @@ Request::onHeadersComplete() auto location_it = response_.headers.find(restinio::field_to_string(restinio::http_field_t::location)); if (location_it == response_.headers.end()) { if (logger_) - logger_->e("[http:client] [request:%i] got redirect without location", id_); + logger_->error("[http:client] [request:{}] got redirect without location", id_); terminate(asio::error::connection_aborted); } if (follow_redirect and num_redirect < MAX_REDIRECTS) { auto newUrl = getRelativePath(get_url(), location_it->second); if (logger_) - logger_->w("[http:client] [request:%i] redirect to %s", id_, newUrl.c_str()); + logger_->warn("[http:client] [request:{}] redirect to {}", id_, newUrl); auto next = std::make_shared(ctx_, newUrl, logger_); next->set_method(header_.method()); next->headers_ = std::move(headers_); @@ -1608,7 +1608,7 @@ Request::onHeadersComplete() next->send(); } else { if (logger_) - logger_->e("[http:client] [request:%i] got redirect without location", id_); + logger_->error("[http:client] [request:{}] got redirect without location", id_); terminate(asio::error::connection_aborted); } } else { diff --git a/src/log.cpp b/src/log.cpp index e81ae846..f7b5976b 100644 --- a/src/log.cpp +++ b/src/log.cpp @@ -49,27 +49,36 @@ constexpr const Color::Modifier def(Color::FG_DEFAULT); constexpr const Color::Modifier red(Color::FG_RED); constexpr const Color::Modifier yellow(Color::FG_YELLOW); +using namespace std::chrono; +using log_precision = microseconds; +constexpr auto den = log_precision::period::den; + /** * Print va_list to std::ostream (used for logging). */ void -printfLog(std::ostream& s, const std::string& message) +printfLog(std::ostream& s, source_loc loc, std::string_view prefix, const std::string& message) { - using namespace std::chrono; - using log_precision = microseconds; auto num = duration_cast(steady_clock::now().time_since_epoch()).count(); - constexpr auto den = log_precision::period::den; - fmt::print(s, "[{:06d}.{:06d}] ", num / den, num % den); + if (!loc.file.empty()) + fmt::print(s, + "[{:06d}.{:06d} {:>20}:{:<5} {:<24}] {}", + num / den, + num % den, + loc.file, + loc.line, + loc.function, + prefix); + else + fmt::print(s, "[{:06d}.{:06d}] {}", num / den, num % den, prefix); s << message << std::endl; } + void -printLog(std::ostream& s, fmt::string_view format, fmt::format_args args) +printLog(std::ostream& s, source_loc loc, std::string_view prefix, fmt::string_view format, fmt::format_args args) { - using namespace std::chrono; - using log_precision = microseconds; auto num = duration_cast(steady_clock::now().time_since_epoch()).count(); - constexpr auto den = log_precision::period::den; - fmt::print(s, "[{:06d}.{:06d}] ", num / den, num % den); + fmt::print(s, "[{:06d}.{:06d}] {}", num / den, num % den, prefix); fmt::vprint(s, format, args); s << std::endl; } @@ -77,12 +86,12 @@ printLog(std::ostream& s, fmt::string_view format, fmt::format_args args) std::shared_ptr getStdLogger() { - return std::make_shared([](LogLevel level, std::string&& message) { + return std::make_shared([](source_loc loc, LogLevel level, std::string_view prefix, std::string&& message) { if (level == LogLevel::error) std::cerr << red; else if (level == LogLevel::warning) std::cerr << yellow; - printfLog(std::cerr, message); + printfLog(std::cerr, loc, prefix, message); std::cerr << def; }); } @@ -93,7 +102,9 @@ getFileLogger(const std::string& path) auto logfile = std::make_shared(); logfile->open(path, std::ios::out); return std::make_shared( - [logfile](LogLevel /*level*/, std::string&& message) { printfLog(*logfile, message); }); + [logfile](source_loc loc, LogLevel /*level*/, std::string_view prefix, std::string&& message) { + printfLog(*logfile, loc, prefix, message); + }); } #ifndef _WIN32 @@ -129,7 +140,14 @@ getSyslogLogger(const char* name) opened_logfile = logfile; } return std::make_shared( - [logfile](LogLevel level, std::string&& message) { syslog(syslogLevel(level), "%s", message.c_str()); }); + [logfile](source_loc loc, LogLevel level, std::string_view prefix, std::string&& message) { + syslog(syslogLevel(level), + "%.*s%.*s", + (int) prefix.size(), + prefix.data(), + (int) message.size(), + message.c_str()); + }); #else return getStdLogger(); #endif diff --git a/src/network_engine.cpp b/src/network_engine.cpp index 2bba40f7..27e87787 100644 --- a/src/network_engine.cpp +++ b/src/network_engine.cpp @@ -129,7 +129,7 @@ NetworkEngine::tellListener(const Sp& node, } } catch (const std::overflow_error& e) { if (logger_) - logger_->e("Unable to send value: buffer not large enough."); + logger_->error("Unable to send value: buffer not large enough."); } } @@ -162,7 +162,7 @@ NetworkEngine::tellListenerRefreshed(const Sp& n, pk.pack(KEY_REQ_REFRESHED); pk.pack(values); if (logger_) - logger_->d(n->id, "[node %s] sending %zu refreshed values", n->toString().c_str(), values.size()); + logger_->debug("[node {}] sending {} refreshed values", n->toString(), values.size()); } pk.pack(KEY_Y); @@ -233,7 +233,7 @@ NetworkEngine::tellListenerExpired(const Sp& n, pk.pack(KEY_REQ_EXPIRED); pk.pack(values); if (logger_) - logger_->d(n->id, "[node %s] sending %zu expired values", n->toString().c_str(), values.size()); + logger_->debug("[node {}] sending {} expired values", n->toString(), values.size()); } pk.pack(KEY_Y); @@ -433,13 +433,13 @@ NetworkEngine::processMessage(const uint8_t* buf, size_t buflen, SockAddr f) auto from = f.getMappedIPv4(); if (isMartian(from)) { if (logger_) - logger_->w("Received packet from martian node %s", from.toString().c_str()); + logger_->warn("Received packet from martian node {}", from.toString()); return; } if (isNodeBlacklisted(from)) { if (logger_) - logger_->w("Received packet from blacklisted node %s", from.toString().c_str()); + logger_->warn("Received packet from blacklisted node {}", from.toString()); return; } @@ -449,7 +449,7 @@ NetworkEngine::processMessage(const uint8_t* buf, size_t buflen, SockAddr f) msg->msgpack_unpack(msg_res.get()); } catch (const std::exception& e) { if (logger_) - logger_->w("Unable to parse message of size %lu: %s", buflen, e.what()); + logger_->warn("Unable to parse message of size {}: {}", buflen, e.what()); // if (logger_) // logger_->DBG.logPrintable(buf, buflen); return; @@ -457,7 +457,7 @@ NetworkEngine::processMessage(const uint8_t* buf, size_t buflen, SockAddr f) if (msg->network != config.network) { if (logger_) - logger_->d("Received message from other config.network %u", msg->network); + logger_->debug("Received message from other config.network {}", msg->network); return; } @@ -469,13 +469,13 @@ NetworkEngine::processMessage(const uint8_t* buf, size_t buflen, SockAddr f) if (pmsg_it == partial_messages.end()) { if (logIncoming_) if (logger_) - logger_->d("Unable to find partial message"); + logger_->debug("Unable to find partial message"); rateLimit(from); return; } if (!pmsg_it->second.from.equals(from)) { if (logger_) - logger_->d("Received partial message data from unexpected IP address"); + logger_->debug("Received partial message data from unexpected IP address"); rateLimit(from); return; } @@ -499,7 +499,7 @@ NetworkEngine::processMessage(const uint8_t* buf, size_t buflen, SockAddr f) if (msg->id == myid or not msg->id) { if (logger_) - logger_->d("Received message from self"); + logger_->debug("Received message from self"); return; } @@ -507,7 +507,7 @@ NetworkEngine::processMessage(const uint8_t* buf, size_t buflen, SockAddr f) /* Rate limit requests. */ if (!rateLimit(from)) { if (logger_) - logger_->w("Dropping request due to rate limiting"); + logger_->warn("Dropping request due to rate limiting"); return; } } @@ -530,7 +530,7 @@ NetworkEngine::processMessage(const uint8_t* buf, size_t buflen, SockAddr f) scheduler.add(now + RX_MAX_PACKET_TIME, std::bind(&NetworkEngine::maintainRxBuffer, this, k)); scheduler.add(now + RX_TIMEOUT, std::bind(&NetworkEngine::maintainRxBuffer, this, k)); } else if (logger_) - logger_->e("Partial message with given TID %u already exists", k); + logger_->error("Partial message with given TID {} already exists", k); } } @@ -551,7 +551,7 @@ NetworkEngine::process(std::unique_ptr&& msg, const SockAddr& fro rsocket->on_receive(node, std::move(*msg)); } catch (const DhtProtocolException& e) { if (logger_) - logger_->w("Unable to deserialize nodes %s", e.what()); + logger_->warn("Unable to deserialize nodes {}", e.what()); } } else if (msg->type == MessageType::Error or msg->type == MessageType::Reply) { auto rsocket = node->getSocket(msg->tid); @@ -569,10 +569,7 @@ NetworkEngine::process(std::unique_ptr&& msg, const SockAddr& fro if (not node->isClient()) onNewNode(node, 1); if (logger_) - logger_->d(node->id, - "[node %s] Unable to find transaction with id %u", - node->toString().c_str(), - msg->tid); + logger_->debug("[node {}] Unable to find transaction with id {}", node->toString(), msg->tid); return; } } @@ -585,9 +582,7 @@ NetworkEngine::process(std::unique_ptr&& msg, const SockAddr& fro if (req and (req->cancelled() or req->expired() or req->completed())) { if (logger_) - logger_->w(node->id, - "[node %s] response to expired, cancelled or completed request", - node->toString().c_str()); + logger_->warn("[node {}] response to expired, cancelled or completed request", node->toString()); return; } @@ -604,11 +599,10 @@ NetworkEngine::process(std::unique_ptr&& msg, const SockAddr& fro } else { if (logIncoming_) if (logger_) - logger_->w(msg->id, - "[node %s %s] received unknown error message %u", - msg->id.toString().c_str(), - from.toString().c_str(), - msg->error_code); + logger_->warn("[node {} {}] received unknown error message {}", + msg->id.toString(), + from.toString(), + msg->error_code); } break; } @@ -625,7 +619,7 @@ NetworkEngine::process(std::unique_ptr&& msg, const SockAddr& fro r.setDone(std::move(*msg)); } catch (const DhtProtocolException& e) { if (logger_) - logger_->w("Unable to deserialize nodes %s", e.what()); + logger_->warn("Unable to deserialize nodes {}", e.what()); } break; } else { /* request socket data */ @@ -634,7 +628,7 @@ NetworkEngine::process(std::unique_ptr&& msg, const SockAddr& fro rsocket->on_receive(node, std::move(*msg)); } catch (const DhtProtocolException& e) { if (logger_) - logger_->w("Unable to deserialize nodes %s", e.what()); + logger_->warn("Unable to deserialize nodes {}", e.what()); } } break; @@ -651,13 +645,13 @@ NetworkEngine::process(std::unique_ptr&& msg, const SockAddr& fro ++in_stats.ping; if (logIncoming_) if (logger_) - logger_->d(node->id, "[node %s] sending pong", node->toString().c_str()); + logger_->debug("[node {}] sending pong", node->toString()); onPing(node); sendPong(from, msg->tid); break; case MessageType::FindNode: { // if (logger_) - // logger_->d(msg->target, node->id, "[node %s] got 'find' request for %s (%d)", + // logger_->d("[node %s] got 'find' request for %s (%d)", // node->toString().c_str(), msg->target.toString().c_str(), msg->want); ++in_stats.find; RequestAnswer answer = onFindNode(node, msg->target, msg->want); @@ -667,7 +661,7 @@ NetworkEngine::process(std::unique_ptr&& msg, const SockAddr& fro } case MessageType::GetValues: { // if (logger_) - // logger_->d(msg->info_hash, node->id, "[node %s] got 'get' request for %s", + // logger_->d("[node %s] got 'get' request for %s", // node->toString().c_str(), msg->info_hash.toString().c_str()); ++in_stats.get; RequestAnswer answer = onGetValues(node, msg->info_hash, msg->want, msg->query); @@ -677,11 +671,7 @@ NetworkEngine::process(std::unique_ptr&& msg, const SockAddr& fro } case MessageType::AnnounceValue: { if (logIncoming_ and logger_) - logger_->d(msg->info_hash, - node->id, - "[node %s] got 'put' request for %s", - node->toString().c_str(), - msg->info_hash.toString().c_str()); + logger_->debug("[node {}] got 'put' request for {}", node->toString(), msg->info_hash.toString()); ++in_stats.put; onAnnounce(node, msg->info_hash, msg->token, msg->values, msg->created); @@ -695,22 +685,16 @@ NetworkEngine::process(std::unique_ptr&& msg, const SockAddr& fro } case MessageType::Refresh: if (logIncoming_ and logger_) - logger_->d(msg->info_hash, - node->id, - "[node %s] got 'refresh' request for %s", - node->toString().c_str(), - msg->info_hash.toString().c_str()); + logger_->debug("[node {}] got 'refresh' request for {}", + node->toString(), + msg->info_hash.toString()); onRefresh(node, msg->info_hash, msg->token, msg->value_id); /* Same note as above in MessageType::AnnounceValue applies. */ sendValueAnnounced(from, msg->tid, msg->value_id); break; case MessageType::Listen: { if (logIncoming_ and logger_) - logger_->d(msg->info_hash, - node->id, - "[node %s] got 'listen' request for %s", - node->toString().c_str(), - msg->info_hash.toString().c_str()); + logger_->debug("[node {}] got 'listen' request for {}", node->toString(), msg->info_hash.toString()); ++in_stats.listen; RequestAnswer answer = onListen(node, msg->info_hash, msg->token, msg->socket_id, std::move(msg->query), msg->version); @@ -720,20 +704,14 @@ NetworkEngine::process(std::unique_ptr&& msg, const SockAddr& fro } case MessageType::UpdateValue: { if (logIncoming_ and logger_) - logger_->d(msg->info_hash, - node->id, - "[node %s] got 'update' request for %s", - node->toString().c_str(), - msg->info_hash.toString().c_str()); + logger_->debug("[node {}] got 'update' request for {}", node->toString(), msg->info_hash.toString()); ++in_stats.updateValue; if (auto rsocket = node->getSocket(msg->socket_id)) rsocket->on_receive(node, std::move(*msg)); else if (logger_) - logger_->e(msg->info_hash, - node->id, - "[node %s] 'update' request without socket for %s", - node->toString().c_str(), - msg->info_hash.toString().c_str()); + logger_->error("[node {}] 'update' request without socket for {}", + node->toString(), + msg->info_hash.toString()); sendListenConfirmation(from, msg->tid); break; } @@ -802,9 +780,9 @@ NetworkEngine::sendPing(const Sp& node, RequestCb&& on_done, RequestExpire tid, node, Blob(buffer.data(), buffer.data() + buffer.size()), - [=](const Request& req_status, ParsedMessage&&) { + [this, on_done = std::move(on_done)](const Request& req_status, ParsedMessage&&) { if (logger_) - logger_->d(req_status.node->id, "[node %s] got pong.", req_status.node->toString().c_str()); + logger_->debug("[node {}] got pong.", req_status.node->toString()); if (on_done) { on_done(req_status, {}); } @@ -1381,18 +1359,18 @@ NetworkEngine::sendAnnounceValue(const Sp& n, tid, n, Blob(buffer.data(), buffer.data() + buffer.size()), - [=](const Request& req_status, ParsedMessage&& msg) { /* on done */ - if (msg.value_id == Value::INVALID_ID) { - if (logger_) - logger_->d(infohash, - "Unknown search or announce!"); - } else { - if (on_done) { - RequestAnswer answer {}; - answer.vid = msg.value_id; - on_done(req_status, std::move(answer)); - } - } + [this, on_done = std::move(on_done)](const Request& req_status, ParsedMessage&& msg) { + /* on done */ + if (msg.value_id == Value::INVALID_ID) { + if (logger_) + logger_->debug("[node {}] Unknown search or announce!", req_status.node->toString()); + } else { + if (on_done) { + RequestAnswer answer {}; + answer.vid = msg.value_id; + on_done(req_status, std::move(answer)); + } + } }, std::move(on_expired)); req->parts = std::move(v); @@ -1537,18 +1515,18 @@ NetworkEngine::sendRefreshValue(const Sp& n, tid, n, Blob(buffer.data(), buffer.data() + buffer.size()), - [=](const Request& req_status, ParsedMessage&& msg) { /* on done */ - if (msg.value_id == Value::INVALID_ID) { - if (logger_) - logger_->d(infohash, - "Unknown search or announce!"); - } else { - if (on_done) { - RequestAnswer answer {}; - answer.vid = msg.value_id; - on_done(req_status, std::move(answer)); - } - } + [this, on_done = std::move(on_done)](const Request& req_status, ParsedMessage&& msg) { + /* on done */ + if (msg.value_id == Value::INVALID_ID) { + if (logger_) + logger_->debug("[node {}] Unknown search or announce!", req_status.node->toString()); + } else { + if (on_done) { + RequestAnswer answer {}; + answer.vid = msg.value_id; + on_done(req_status, std::move(answer)); + } + } }, std::move(on_error), std::move(on_expired)); @@ -1635,7 +1613,7 @@ NetworkEngine::maintainRxBuffer(Tid tid) const auto& now = scheduler.time(); if (msg->second.start + RX_MAX_PACKET_TIME < now || msg->second.last_part + RX_TIMEOUT < now) { if (logger_) - logger_->w("Dropping expired partial message from %s", msg->second.from.toString().c_str()); + logger_->warn("Dropping expired partial message from {}", msg->second.from.toString()); partial_messages.erase(msg); } } diff --git a/src/node.cpp b/src/node.cpp index c6b37636..af80d0ca 100644 --- a/src/node.cpp +++ b/src/node.cpp @@ -147,9 +147,7 @@ Node::closeSocket(Tid id) std::string Node::toString() const { - std::ostringstream ss; - ss << (*this); - return ss.str(); + return fmt::format("{} {:<21}", id, addr.toString()); } std::ostream& diff --git a/src/peer_discovery.cpp b/src/peer_discovery.cpp index 87181f8d..39f72e1b 100644 --- a/src/peer_discovery.cpp +++ b/src/peer_discovery.cpp @@ -147,7 +147,7 @@ PeerDiscovery::DomainPeerDiscovery::loopListener() return; if (error) { if (logger_) - logger_->e("Error receiving message: %s", error.message().c_str()); + logger_->error("Error receiving message: {}", error.message()); } try { auto rcv = msgpack::unpack(receiveBuf_.data(), bytes); @@ -180,7 +180,7 @@ PeerDiscovery::DomainPeerDiscovery::loopListener() } } catch (const std::exception& e) { if (logger_) - logger_->e("Error receiving packet: %s", e.what()); + logger_->error("Error receiving packet: {}", e.what()); } loopListener(); }); @@ -200,9 +200,9 @@ PeerDiscovery::DomainPeerDiscovery::query(const asio::ip::udp::endpoint& peer) peer, [logger = logger_, peer](const asio::error_code& ec, size_t) { if (ec and (ec != asio::error::operation_aborted) and logger) - logger->w("Error sending packet to: %s with err: %s", - peer.address().to_string().c_str(), - ec.message().c_str()); + logger->warn("Error sending packet to: {} with err: {}", + peer.address().to_string(), + ec.message()); }); } @@ -217,9 +217,9 @@ PeerDiscovery::DomainPeerDiscovery::publish(const asio::ip::udp::endpoint& peer) peer, [logger = logger_, peer](const asio::error_code& ec, size_t) { if (ec and (ec != asio::error::operation_aborted) and logger) - logger->w("Error sending packet to: %s with err: %s", - peer.address().to_string().c_str(), - ec.message().c_str()); + logger->warn("Error sending packet to: {} with err: {}", + peer.address().to_string(), + ec.message()); }); } @@ -310,7 +310,7 @@ PeerDiscovery::DomainPeerDiscovery::reDiscover() sockFd_.set_option(asio::ip::multicast::join_group(sockAddrSend_.address()), ec); if (ec and logger_) - logger_->w("Unable to multicast on %s: %s", sockAddrSend_.address().to_string().c_str(), ec.message().c_str()); + logger_->warn("Unable to multicast on {}: {}", sockAddrSend_.address().to_string(), ec.message()); query(sockAddrSend_); } @@ -322,7 +322,7 @@ PeerDiscovery::DomainPeerDiscovery::connectivityChanged() publish(sockAddrSend_); }); if (logger_) - logger_->d("PeerDiscovery: connectivity changed"); + logger_->debug("PeerDiscovery: connectivity changed"); if (peerDiscovery_period == PeerDiscovery_PERIOD_MAX) { peerDiscovery_period = PeerDiscovery_PERIOD; diff --git a/src/securedht.cpp b/src/securedht.cpp index e14ea6fc..ea730485 100644 --- a/src/securedht.cpp +++ b/src/securedht.cpp @@ -51,7 +51,7 @@ SecureDht::SecureDht(std::unique_ptr dht, iacb = std::move(iacb) ](bool ok) { if (logger_) - logger_->d("SecureDht: certificate announcement %s", ok ? "succeeded" : "failed"); + logger_->debug("SecureDht: certificate announcement {}", ok ? "succeeded" : "failed"); completedState->second = completedState->second and ok; if (--completedState->first == 0) iacb(completedState->second); @@ -175,7 +175,7 @@ SecureDht::registerCertificate(const InfoHash& node, const Blob& data) return crt; } else { if (logger_) - logger_->w("Certificate {} for node {} does not match node id !", h.toString(), node.toString()); + logger_->warn("Certificate {} for node {} does not match node id !", h.toString(), node.toString()); return nullptr; } } @@ -196,7 +196,7 @@ SecureDht::registerCertificate(const PkId& node, const Blob& data) return crt; } else { if (logger_) - logger_->w("Certificate {} for node {} does not match node id !", h.toString(), node.toString()); + logger_->warn("Certificate {} for node {} does not match node id !", h.toString(), node.toString()); return nullptr; } } @@ -216,7 +216,7 @@ SecureDht::findCertificate(const InfoHash& node, const std::function b = getCertificate(node); if (b && *b) { if (logger_) - logger_->d("Using certificate from cache for %s", node.to_c_str()); + logger_->debug("Using certificate from cache for {}", node.toString()); if (cb) cb(b); return; @@ -225,7 +225,7 @@ SecureDht::findCertificate(const InfoHash& node, const std::functiond("Registering certificate from local store for %s", node.to_c_str()); + logger_->debug("Registering certificate from local store for {}", node.toString()); nodesCertificates_.emplace(node, res.front()); nodesCertificatesLong_.emplace(res.front()->getLongId(), res.front()); if (cb) @@ -242,7 +242,7 @@ SecureDht::findCertificate(const InfoHash& node, const std::functiondata)) { *found = true; if (logger_) - logger_->d(node, "Found certificate for %s", node.to_c_str()); + logger_->debug("Found certificate for {}", node.toString()); if (cb) cb(cert); return false; @@ -263,7 +263,7 @@ SecureDht::findPublicKey(const InfoHash& node, const std::functiond(node, "Found public key from cache for %s", node.to_c_str()); + logger_->debug("Found public key from cache for {}", node.toString()); if (cb) cb(pk); return; @@ -383,7 +383,7 @@ SecureDht::checkValue(const Sp& v) } } catch (const std::exception& e) { if (logger_) - logger_->w("Could not decrypt value %s : %s", v->toString().c_str(), e.what()); + logger_->warn("Could not decrypt value {} : {}", v->toString(), e.what()); } } // Check signed values @@ -396,7 +396,7 @@ SecureDht::checkValue(const Sp& v) } return v; } else if (logger_) - logger_->w("Signature verification failed for %s", v->toString().c_str()); + logger_->warn("Signature verification failed for {}", v->toString()); } // Forward normal values else { @@ -484,14 +484,15 @@ SecureDht::putSigned(const InfoHash& hash, Sp val, DoneCallback callback, hash, [val, this](const std::vector>& vals) { if (logger_) - logger_->d("Found online previous value being announced."); + logger_->debug("Found online previous value being announced."); for (const auto& v : vals) { if (!v->isSigned()) { if (logger_) - logger_->e("Existing non-signed value seems to exists at this location."); + logger_->error("Existing non-signed value seems to exists at this location."); } else if (not v->owner or v->owner->getId() != getId()) { if (logger_) - logger_->e("Existing signed value belonging to someone else seems to exists at this location."); + logger_->error( + "Existing signed value belonging to someone else seems to exists at this location."); } else if (val->seq <= v->seq) val->seq = v->seq + 1; } @@ -522,12 +523,12 @@ SecureDht::putEncrypted(const InfoHash& hash, const InfoHash& to, Sp val, return; } if (logger_) - logger_->w("Encrypting data for PK: %s", pk->getId().toString().c_str()); + logger_->warn("Encrypting data for PK: {}", pk->getId().toString()); try { dht_->put(hash, encrypt(*val, *pk), callback, time_point::max(), permanent); } catch (const std::exception& e) { if (logger_) - logger_->e("Error putting encrypted data: %s", e.what()); + logger_->error("Error putting encrypted data: {}", e.what()); if (callback) callback(false, {}); } @@ -556,7 +557,7 @@ SecureDht::putEncrypted(const InfoHash& hash, const PkId& to, Sp val, Don dht_->put(hash, encrypt(*val, *pk), callback, time_point::max(), permanent); } catch (const std::exception& e) { if (logger_) - logger_->e("Error putting encrypted data: %s", e.what()); + logger_->error("Error putting encrypted data: {}", e.what()); if (callback) callback(false, {}); } @@ -578,7 +579,7 @@ SecureDht::putEncrypted( dht_->put(hash, encrypt(*val, pk), callback, time_point::max(), permanent); } catch (const std::exception& e) { if (logger_) - logger_->e("Error putting encrypted data: %s", e.what()); + logger_->error("Error putting encrypted data: {}", e.what()); if (callback) callback(false, {}); }