mirror
/
transmission
mirror of https://github.com/transmission/transmission
1
0
Fork 0
Code Issues Releases Wiki Activity

refactor: remove deep logging (#2749) 

* refactor: remove "deep logging"
This commit is contained in:
Charles Kerr 2022-03-09 23:51:14 -06:00 committed by GitHub
parent 1bafbd18ac
commit af339a15ed
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
32 changed files with 554 additions and 597 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

37
daemon/daemon.cc
View File

@ -265,9 +265,28 @@ static auto onFileAdded(tr_watchdir_t dir, char const* name, void* vsession)
return TR_WATCHDIR_ACCEPT;
}
static char const* levelName(tr_log_level level)
{
switch (level)
{
case TR_LOG_CRITICAL:
return "CRIT ";
case TR_LOG_ERROR:
return "ERR ";
case TR_LOG_WARN:
return "WARN ";
case TR_LOG_DEBUG:
return "DEBUG";
case TR_LOG_TRACE:
return "TRACE";
default:
return "INFO ";
}
}
static void printMessage(
tr_sys_file_t file,
[[maybe_unused]] int level,
tr_log_level level,
std::string_view name,
std::string_view message,
std::string_view filename,
@ -280,7 +299,7 @@ static void printMessage(
{
auto timestr = std::array<char, 64>{};
tr_logGetTimeStr(std::data(timestr), std::size(timestr));
tr_sys_file_write_line(file, tr_strvJoin("["sv, std::data(timestr), "] "sv, out), nullptr);
tr_sys_file_write_line(file, tr_strvJoin("["sv, std::data(timestr), "] "sv, levelName(level), " "sv, out), nullptr);
}
#ifdef HAVE_SYSLOG
@ -292,16 +311,24 @@ static void printMessage(
/* figure out the syslog priority */
switch (level)
{
case TR_LOG_CRITICAL:
priority = LOG_CRIT;
break;
case TR_LOG_ERROR:
priority = LOG_ERR;
break;
case TR_LOG_DEBUG:
priority = LOG_DEBUG;
case TR_LOG_WARN:
priority = LOG_WARNING;
break;
case TR_LOG_INFO:
priority = LOG_INFO;
break;
default:
priority = LOG_INFO;
priority = LOG_DEBUG;
break;
}

2
gtk/MessageLogWindow.cc
View File

@ -71,7 +71,7 @@ private:
Glib::RefPtr<Gtk::ListStore> store_;
Glib::RefPtr<Gtk::TreeModelFilter> filter_;
Glib::RefPtr<Gtk::TreeModelSort> sort_;
tr_log_level maxLevel_ = TR_LOG_SILENT;
tr_log_level maxLevel_ = TR_LOG_OFF;
bool isPaused_ = false;
sigc::connection refresh_tag_;
};

4
libtransmission/announcer-common.h
View File

@ -236,8 +236,8 @@ void tr_tracker_udp_announce(
void tr_tracker_udp_start_shutdown(tr_session* session);
void tr_announcerParseHttpAnnounceResponse(tr_announce_response& response, std::string_view msg);
void tr_announcerParseHttpAnnounceResponse(tr_announce_response& response, std::string_view msg, char const* log_name);
void tr_announcerParseHttpScrapeResponse(tr_scrape_response& response, std::string_view msg);
void tr_announcerParseHttpScrapeResponse(tr_scrape_response& response, std::string_view msg, char const* log_name);
tr_interned_string tr_announcerGetKey(tr_url_parsed_t const& parsed);

26
libtransmission/announcer-http.cc
View File

@ -31,7 +31,7 @@
#include "web-utils.h"
#include "web.h"
#define dbgmsg(name, ...) tr_logAddDeepNamed(name, __VA_ARGS__)
#define logtrace(name, ...) tr_logAddMessage(__FILE__, __LINE__, TR_LOG_TRACE, name, __VA_ARGS__)
using namespace std::literals;
@ -148,7 +148,7 @@ static void verboseLog(std::string_view description, tr_direction direction, std
static auto constexpr MaxBencDepth = 8;
void tr_announcerParseHttpAnnounceResponse(tr_announce_response& response, std::string_view benc)
void tr_announcerParseHttpAnnounceResponse(tr_announce_response& response, std::string_view benc, char const* log_name)
{
verboseLog("Announce response:", TR_DOWN, benc);
@ -271,7 +271,7 @@ void tr_announcerParseHttpAnnounceResponse(tr_announce_response& response, std::
transmission::benc::parse(benc, stack, handler, nullptr, &error);
if (error != nullptr)
{
tr_logAddError("%s", error->message);
tr_logAddMessage(__FILE__, __LINE__, TR_LOG_WARN, log_name, "%s (%d)", error->message, error->code);
tr_error_clear(&error);
}
}
@ -292,7 +292,7 @@ static void onAnnounceDone(tr_web::FetchResponse const& web_response)
tr_announce_response* const response = &data->response;
response->did_connect = did_connect;
response->did_timeout = did_timeout;
dbgmsg(data->log_name, "Got announce response");
logtrace(data->log_name, "Got announce response");
if (status != HTTP_OK)
{
@ -301,17 +301,17 @@ static void onAnnounceDone(tr_web::FetchResponse const& web_response)
}
else
{
tr_announcerParseHttpAnnounceResponse(*response, body);
tr_announcerParseHttpAnnounceResponse(*response, body, data->log_name);
}
if (!std::empty(response->pex6))
{
dbgmsg(data->log_name, "got a peers6 length of %zu", std::size(response->pex6));
logtrace(data->log_name, "got a peers6 length of %zu", std::size(response->pex6));
}
if (!std::empty(response->pex))
{
dbgmsg(data->log_name, "got a peers length of %zu", std::size(response->pex));
logtrace(data->log_name, "got a peers length of %zu", std::size(response->pex));
}
if (data->response_func != nullptr)
@ -335,7 +335,7 @@ void tr_tracker_http_announce(
tr_strlcpy(d->log_name, request->log_name, sizeof(d->log_name));
auto const url = announce_url_new(session, request);
dbgmsg(request->log_name, "Sending announce to libcurl: \"%" TR_PRIsv "\"", TR_PRIsv_ARG(url));
logtrace(request->log_name, "Sending announce to libcurl: \"%" TR_PRIsv "\"", TR_PRIsv_ARG(url));
auto options = tr_web::FetchOptions{ url, onAnnounceDone, d };
options.timeout_secs = 90L;
@ -350,7 +350,7 @@ void tr_tracker_http_announce(
*****
****/
void tr_announcerParseHttpScrapeResponse(tr_scrape_response& response, std::string_view benc)
void tr_announcerParseHttpScrapeResponse(tr_scrape_response& response, std::string_view benc, char const* log_name)
{
verboseLog("Scrape response:", TR_DOWN, benc);
@ -443,7 +443,7 @@ void tr_announcerParseHttpScrapeResponse(tr_scrape_response& response, std::stri
transmission::benc::parse(benc, stack, handler, nullptr, &error);
if (error != nullptr)
{
tr_logAddError("%s", error->message);
tr_logAddMessage(__FILE__, __LINE__, TR_LOG_WARN, log_name, "%s (%d)", error->message, error->code);
tr_error_clear(&error);
}
}
@ -466,7 +466,7 @@ static void onScrapeDone(tr_web::FetchResponse const& web_response)
response.did_timeout = did_timeout;
auto const scrape_url_sv = response.scrape_url.sv();
dbgmsg(data->log_name, "Got scrape response for \"%" TR_PRIsv "\"", TR_PRIsv_ARG(scrape_url_sv));
logtrace(data->log_name, "Got scrape response for \"%" TR_PRIsv "\"", TR_PRIsv_ARG(scrape_url_sv));
if (status != HTTP_OK)
{
@ -475,7 +475,7 @@ static void onScrapeDone(tr_web::FetchResponse const& web_response)
}
else
{
tr_announcerParseHttpScrapeResponse(response, body);
tr_announcerParseHttpScrapeResponse(response, body, data->log_name);
}
if (data->response_func != nullptr)
@ -528,7 +528,7 @@ void tr_tracker_http_scrape(
tr_strlcpy(d->log_name, request->log_name, sizeof(d->log_name));
auto const url = scrape_url_new(request);
dbgmsg(request->log_name, "Sending scrape to libcurl: \"%" TR_PRIsv "\"", TR_PRIsv_ARG(url));
logtrace(request->log_name, "Sending scrape to libcurl: \"%" TR_PRIsv "\"", TR_PRIsv_ARG(url));
auto options = tr_web::FetchOptions{ url, onScrapeDone, d };
options.timeout_secs = 30L;

36
libtransmission/announcer-udp.cc
View File

@ -28,7 +28,9 @@
#include "tr-udp.h"
#include "utils.h"
#define dbgmsg(key, ...) tr_logAddDeepNamed(key.c_str(), __VA_ARGS__)
#define logwarn(interned, ...) tr_logAddNamed(TR_LOG_WARN, (interned).c_str(), __VA_ARGS__)
#define logdbg(interned, ...) tr_logAddNamed(TR_LOG_DEBUG, (interned).c_str(), __VA_ARGS__)
#define logtrace(interned, ...) tr_logAddNamed(TR_LOG_TRACE, (interned).c_str(), __VA_ARGS__)
using namespace std::literals;
@ -461,12 +463,12 @@ static void tau_tracker_on_dns(int errcode, struct evutil_addrinfo* addr, void*
if (errcode != 0)
{
auto const errmsg = tr_strvJoin("DNS Lookup failed: "sv, evutil_gai_strerror(errcode));
dbgmsg(tracker->key, "%s", errmsg.c_str());
logwarn(tracker->key, "%s", errmsg.c_str());
tracker->failAll(false, false, errmsg.c_str());
}
else
{
dbgmsg(tracker->key, "DNS lookup succeeded");
logdbg(tracker->key, "DNS lookup succeeded");
tracker->addr = addr;
tau_tracker_upkeep(tracker);
}
@ -475,7 +477,7 @@ static void tau_tracker_on_dns(int errcode, struct evutil_addrinfo* addr, void*
static void tau_tracker_send_request(struct tau_tracker* tracker, void const* payload, size_t payload_len)
{
struct evbuffer* buf = evbuffer_new();
dbgmsg(tracker->key, "sending request w/connection id %" PRIu64 "\n", tracker->connection_id);
logdbg(tracker->key, "sending request w/connection id %" PRIu64 "\n", tracker->connection_id);
evbuffer_add_hton_64(buf, tracker->connection_id);
evbuffer_add_reference(buf, payload, payload_len, nullptr, nullptr);
(void)tau_sendto(tracker->session, tracker->addr, tracker->port, evbuffer_pullup(buf, -1), evbuffer_get_length(buf));
@ -497,7 +499,7 @@ static void tau_tracker_send_requests(tau_tracker* tracker, std::list<T>& reqs)
continue;
}
dbgmsg(tracker->key, "sending req %p", (void*)&req);
logdbg(tracker->key, "sending req %p", (void*)&req);
req.sent_at = now;
tau_tracker_send_request(tracker, std::data(req.payload), std::size(req.payload));
@ -534,7 +536,7 @@ static void on_tracker_connection_response(struct tau_tracker* tracker, tau_acti
{
tracker->connection_id = evbuffer_read_ntoh_64(buf);
tracker->connection_expiration_time = now + TauConnectionTtlSecs;
dbgmsg(tracker->key, "Got a new connection ID from tracker: %" PRIu64, tracker->connection_id);
logdbg(tracker->key, "Got a new connection ID from tracker: %" PRIu64, tracker->connection_id);
}
else
{
@ -544,7 +546,7 @@ static void on_tracker_connection_response(struct tau_tracker* tracker, tau_acti
std::string_view{ reinterpret_cast<char const*>(evbuffer_pullup(buf, -1)), buflen } :
std::string_view{ _("Connection failed") };
dbgmsg(tracker->key, "%" TR_PRIsv, TR_PRIsv_ARG(errmsg));
logdbg(tracker->key, "%" TR_PRIsv, TR_PRIsv_ARG(errmsg));
tracker->failAll(true, false, errmsg);
}
@ -568,7 +570,7 @@ static void tau_tracker_timeout_reqs(struct tau_tracker* tracker)
auto& req = *it;
if (cancel_all || req.created_at + TauRequestTtl < now)
{
dbgmsg(tracker->key, "timeout announce req %p", (void*)&req);
logtrace(tracker->key, "timeout announce req %p", (void*)&req);
req.fail(false, true, "");
it = reqs.erase(it);
}
@ -586,7 +588,7 @@ static void tau_tracker_timeout_reqs(struct tau_tracker* tracker)
auto& req = *it;
if (cancel_all || req.created_at + TauRequestTtl < now)
{
dbgmsg(tracker->key, "timeout scrape req %p", &req);
logtrace(tracker->key, "timeout scrape req %p", &req);
req.fail(false, true, "");
it = reqs.erase(it);
}
@ -606,7 +608,7 @@ static void tau_tracker_upkeep_ex(struct tau_tracker* tracker, bool timeout_reqs
/* if the address info is too old, expire it */
if (tracker->addr != nullptr && (closing || tracker->addr_expiration_time <= now))
{
dbgmsg(tracker->host, "Expiring old DNS result");
logtrace(tracker->host, "Expiring old DNS result");
evutil_freeaddrinfo(tracker->addr);
tracker->addr = nullptr;
tracker->addr_expiration_time = 0;
@ -632,7 +634,7 @@ static void tau_tracker_upkeep_ex(struct tau_tracker* tracker, bool timeout_reqs
hints.ai_family = AF_UNSPEC;
hints.ai_socktype = SOCK_DGRAM;
hints.ai_protocol = IPPROTO_UDP;
dbgmsg(tracker->host, "Trying a new DNS lookup");
logtrace(tracker->host, "Trying a new DNS lookup");
tracker->dns_request = evdns_getaddrinfo(
tracker->session->evdns_base,
tr_strlower(tracker->host.sv()).c_str(),
@ -643,7 +645,7 @@ static void tau_tracker_upkeep_ex(struct tau_tracker* tracker, bool timeout_reqs
return;
}
dbgmsg(
logtrace(
tracker->key,
"addr %p -- connected %d (%zu %zu) -- connecting_at %zu",
(void*)tracker->addr,
@ -658,7 +660,7 @@ static void tau_tracker_upkeep_ex(struct tau_tracker* tracker, bool timeout_reqs
struct evbuffer* buf = evbuffer_new();
tracker->connecting_at = now;
tracker->connection_transaction_id = tau_transaction_new();
dbgmsg(tracker->key, "Trying to connect. Transaction ID is %u", tracker->connection_transaction_id);
logtrace(tracker->key, "Trying to connect. Transaction ID is %u", tracker->connection_transaction_id);
evbuffer_add_hton_64(buf, 0x41727101980LL);
evbuffer_add_hton_32(buf, TAU_ACTION_CONNECT);
evbuffer_add_hton_32(buf, tracker->connection_transaction_id);
@ -739,7 +741,7 @@ static tau_tracker* tau_session_get_tracker(tr_announcer_udp* tau, tr_interned_s
// we don't have it -- build a new one
tau->trackers.emplace_back(tau->session, key, tr_interned_string(parsed->host), parsed->port);
auto* const tracker = &tau->trackers.back();
dbgmsg(tracker->key, "New tau_tracker created");
logtrace(tracker->key, "New tau_tracker created");
return tracker;
}
@ -834,7 +836,7 @@ bool tau_handle_message(tr_session* session, uint8_t const* msg, size_t msglen)
// is it a connection response?
if (tracker.connecting_at != 0 && transaction_id == tracker.connection_transaction_id)
{
dbgmsg(tracker.key, "%" PRIu32 " is my connection request!", transaction_id);
logtrace(tracker.key, "%" PRIu32 " is my connection request!", transaction_id);
on_tracker_connection_response(&tracker, action_id, buf);
evbuffer_free(buf);
return true;
@ -849,7 +851,7 @@ bool tau_handle_message(tr_session* session, uint8_t const* msg, size_t msglen)
[&transaction_id](auto const& req) { return req.transaction_id == transaction_id; });
if (it != std::end(reqs))
{
dbgmsg(tracker.key, "%" PRIu32 " is an announce request!", transaction_id);
logtrace(tracker.key, "%" PRIu32 " is an announce request!", transaction_id);
auto req = *it;
it = reqs.erase(it);
req.onResponse(action_id, buf);
@ -867,7 +869,7 @@ bool tau_handle_message(tr_session* session, uint8_t const* msg, size_t msglen)
[&transaction_id](auto const& req) { return req.transaction_id == transaction_id; });
if (it != std::end(reqs))
{
dbgmsg(tracker.key, "%" PRIu32 " is a scrape request!", transaction_id);
logtrace(tracker.key, "%" PRIu32 " is a scrape request!", transaction_id);
auto req = *it;
it = reqs.erase(it);
req.onResponse(action_id, buf);

71
libtransmission/announcer.cc
View File

@ -38,17 +38,22 @@
using namespace std::literals;
#define dbgmsg(tier, ...) \
#define logimpl(tier, level, ...) \
do \
{ \
if (tr_logGetDeepEnabled()) \
if (tr_logLevelIsActive(level)) \
{ \
auto name = std::array<char, 128>{}; \
auto name = std::array<char, 512>{}; \
tier->buildLogName(std::data(name), std::size(name)); \
tr_logAddDeep(__FILE__, __LINE__, std::data(name), __VA_ARGS__); \
tr_logAddMessage(__FILE__, __LINE__, level, std::data(name), __VA_ARGS__); \
} \
} while (0)
#define logerr(io, ...) logimpl(io, TR_LOG_ERROR, __VA_ARGS__)
#define logwarn(io, ...) logimpl(io, TR_LOG_WARN, __VA_ARGS__)
#define logdbg(io, ...) logimpl(io, TR_LOG_DEBUG, __VA_ARGS__)
#define logtrace(io, ...) logimpl(io, TR_LOG_TRACE, __VA_ARGS__)
/* unless the tracker says otherwise, rescrape this frequently */
static auto constexpr DefaultScrapeIntervalSec = int{ 60 * 30 };
/* unless the tracker says otherwise, this is the announce interval */
@ -653,7 +658,7 @@ static void publishPeerCounts(tr_tier* tier, int seeders, int leechers)
e.messageType = TR_TRACKER_COUNTS;
e.seeders = seeders;
e.leechers = leechers;
dbgmsg(tier, "peer counts: %d seeders, %d leechers.", seeders, leechers);
logdbg(tier, "peer counts: %d seeders, %d leechers.", seeders, leechers);
(*tier->tor->torrent_announcer->callback)(tier->tor, &e, nullptr);
}
@ -668,7 +673,7 @@ static void publishPeersPex(tr_tier* tier, int seeders, int leechers, std::vecto
e.seeders = seeders;
e.leechers = leechers;
e.pex = pex;
dbgmsg(
logdbg(
tier,
"tracker knows of %d seeders and %d leechers and gave a list of %zu peers.",
seeders,
@ -720,24 +725,26 @@ time_t tr_announcerNextManualAnnounce(tr_torrent const* tor)
return ret;
}
static void dbgmsg_tier_announce_queue(tr_tier const* tier)
static void logtrace_tier_announce_queue(tr_tier const* tier)
{
if (tr_logGetDeepEnabled())
if (!tr_logLevelIsActive(TR_LOG_TRACE))
{
auto name = std::array<char, 128>{};
tier->buildLogName(std::data(name), std::size(name));
auto* const buf = evbuffer_new();
for (size_t i = 0, n = std::size(tier->announce_events); i < n; ++i)
{
tr_announce_event const e = tier->announce_events[i];
char const* str = tr_announce_event_get_string(e);
evbuffer_add_printf(buf, "[%zu:%s]", i, str);
}
auto const message = evbuffer_free_to_str(buf);
tr_logAddDeep(__FILE__, __LINE__, std::data(name), "announce queue is %" TR_PRIsv, TR_PRIsv_ARG(message));
return;
}
auto name = std::array<char, 512>{};
tier->buildLogName(std::data(name), std::size(name));
auto* const buf = evbuffer_new();
for (size_t i = 0, n = std::size(tier->announce_events); i < n; ++i)
{
tr_announce_event const e = tier->announce_events[i];
char const* str = tr_announce_event_get_string(e);
evbuffer_add_printf(buf, "[%zu:%s]", i, str);
}
auto const message = evbuffer_free_to_str(buf);
tr_logAddMessage(__FILE__, __LINE__, TR_LOG_TRACE, std::data(name), "%s", message.c_str());
}
// higher priorities go to the front of the announce queue
@ -767,8 +774,8 @@ static void tier_announce_event_push(tr_tier* tier, tr_announce_event e, time_t
{
TR_ASSERT(tier != nullptr);
dbgmsg_tier_announce_queue(tier);
dbgmsg(tier, "queued \"%s\"", tr_announce_event_get_string(e));
logtrace_tier_announce_queue(tier);
logtrace(tier, "queued \"%s\"", tr_announce_event_get_string(e));
auto& events = tier->announce_events;
if (!std::empty(events))
@ -797,8 +804,8 @@ static void tier_announce_event_push(tr_tier* tier, tr_announce_event e, time_t
tier->announceAt = announceAt;
tier_update_announce_priority(tier);
dbgmsg_tier_announce_queue(tier);
dbgmsg(tier, "announcing in %d seconds", (int)difftime(announceAt, tr_time()));
logtrace_tier_announce_queue(tier);
logtrace(tier, "announcing in %d seconds", (int)difftime(announceAt, tr_time()));
}
static auto tier_announce_event_pull(tr_tier* tier)
@ -957,14 +964,14 @@ static void on_announce_error(tr_tier* tier, char const* err, tr_announce_event
auto const* const host_cstr = current_tracker->host.c_str();
if (isUnregistered(err))
{
dbgmsg(tier, "Tracker '%s' announce error: %s", host_cstr, err);
logerr(tier, "Tracker '%s' announce error: %s", host_cstr, err);
tr_logAddTorInfo(tier->tor, "Tracker '%s' announce error: %s", host_cstr, err);
}
else
{
/* schedule a reannounce */
int const interval = current_tracker->getRetryInterval();
dbgmsg(tier, "Tracker '%s' announce error: %s (Retrying in %d seconds)", host_cstr, err, interval);
logwarn(tier, "Tracker '%s' announce error: %s (Retrying in %d seconds)", host_cstr, err, interval);
tr_logAddTorInfo(tier->tor, "Tracker '%s' announce error: %s (Retrying in %d seconds)", host_cstr, err, interval);
tier_announce_event_push(tier, e, tr_time() + interval);
}
@ -981,7 +988,7 @@ static void on_announce_done(tr_announce_response const* response, void* vdata)
if (tier != nullptr)
{
dbgmsg(
logtrace(
tier,
"Got announce response: "
"connected:%d "
@ -1082,7 +1089,7 @@ static void on_announce_done(tr_announce_response const* response, void* vdata)
if (auto const& warning = response->warning; !std::empty(warning))
{
tier->last_announce_str = warning;
dbgmsg(tier, "tracker gave \"%s\"", warning.c_str());
logtrace(tier, "tracker gave \"%s\"", warning.c_str());
publishWarning(tier, warning);
}
else
@ -1149,7 +1156,7 @@ static void on_announce_done(tr_announce_response const* response, void* vdata)
{
/* the queue is empty, so enqueue a perodic update */
int const i = tier->announceIntervalSec;
dbgmsg(tier, "Sending periodic reannounce in %d seconds", i);
logtrace(tier, "Sending periodic reannounce in %d seconds", i);
tier_announce_event_push(tier, TR_ANNOUNCE_EVENT_NONE, now + i);
}
}
@ -1254,7 +1261,7 @@ static void on_scrape_error(tr_session const* /*session*/, tr_tier* tier, char c
// schedule a rescrape
auto const interval = current_tracker->getRetryInterval();
auto const* const host_cstr = current_tracker->host.c_str();
dbgmsg(tier, "Tracker '%s' scrape error: %s (Retrying in %zu seconds)", host_cstr, errmsg, (size_t)interval);
logtrace(tier, "Tracker '%s' scrape error: %s (Retrying in %zu seconds)", host_cstr, errmsg, (size_t)interval);
tr_logAddTorInfo(tier->tor, "Tracker '%s' error: %s (Retrying in %zu seconds)", host_cstr, errmsg, (size_t)interval);
tier->lastScrapeSucceeded = false;
tier->scheduleNextScrape(interval);
@ -1318,7 +1325,7 @@ static void on_scrape_done(tr_scrape_response const* response, void* vsession)
auto const scrape_url_sv = response->scrape_url.sv();
dbgmsg(
logtrace(
tier,
"scraped url:%" TR_PRIsv
" -- "

6
libtransmission/bandwidth.cc
View File

@ -14,7 +14,7 @@
#include "tr-assert.h"
#include "utils.h"
#define dbgmsg(...) tr_logAddDeepNamed(nullptr, __VA_ARGS__)
#define logtrace(...) tr_logAddMessage(__FILE__, __LINE__, TR_LOG_TRACE, nullptr, __VA_ARGS__)
/***
****
@ -166,7 +166,7 @@ void Bandwidth::phaseOne(std::vector<tr_peerIo*>& peerArray, tr_direction dir)
* peers from starving the others. Loop through the peers, giving each a
* small chunk of bandwidth. Keep looping until we run out of bandwidth
* and/or peers that can use it */
dbgmsg("%lu peers to go round-robin for %s", peerArray.size(), dir == TR_UP ? "upload" : "download");
logtrace("%lu peers to go round-robin for %s", peerArray.size(), dir == TR_UP ? "upload" : "download");
size_t n = peerArray.size();
while (n > 0)
@ -180,7 +180,7 @@ void Bandwidth::phaseOne(std::vector<tr_peerIo*>& peerArray, tr_direction dir)
int const bytes_used = tr_peerIoFlush(peerArray[i], dir, increment);
dbgmsg("peer #%d of %zu used %d bytes in this pass", i, n, bytes_used);
logtrace("peer #%d of %zu used %d bytes in this pass", i, n, bytes_used);
if (bytes_used != int(increment))
{

4
libtransmission/cache.cc
View File

@ -20,7 +20,7 @@
static char constexpr MyName[] = "Cache";
#define dbgmsg(...) tr_logAddDeepNamed(MyName, __VA_ARGS__)
#define logtrace(...) tr_logAddMessage(__FILE__, __LINE__, TR_LOG_TRACE, nullptr, __VA_ARGS__)
/****
*****
@ -409,7 +409,7 @@ int tr_cacheFlushFile(tr_cache* cache, tr_torrent* torrent, tr_file_index_t i)
auto const [begin, end] = tr_torGetFileBlockSpan(torrent, i);
int pos = findBlockPos(cache, torrent, torrent->blockLoc(begin));
dbgmsg("flushing file %d from cache to disk: blocks [%zu...%zu)", (int)i, (size_t)begin, (size_t)end);
logtrace("flushing file %d from cache to disk: blocks [%zu...%zu)", (int)i, (size_t)begin, (size_t)end);
/* flush out all the blocks in that file */
int err = 0;

35
libtransmission/fdlimit.cc
View File

@ -21,7 +21,10 @@
#include "tr-assert.h"
#include "utils.h" // tr_time()
#define dbgmsg(...) tr_logAddDeepNamed(nullptr, __VA_ARGS__)
#define logerr(...) tr_logAddNamed(TR_LOG_ERROR, nullptr, __VA_ARGS__)
#define logwarn(...) tr_logAddNamed(TR_LOG_WARN, nullptr, __VA_ARGS__)
#define logdbg(...) tr_logAddNamed(TR_LOG_DEBUG, nullptr, __VA_ARGS__)
#define logtrace(...) tr_logAddNamed(TR_LOG_TRACE, nullptr, __VA_ARGS__)
/***
****
@ -43,7 +46,7 @@ static bool preallocate_file_sparse(tr_sys_file_t fd, uint64_t length, tr_error*
return true;
}
dbgmsg("Preallocating (sparse, normal) failed (%d): %s", my_error->code, my_error->message);
logdbg("Preallocating (sparse, normal) failed (%d): %s", my_error->code, my_error->message);
if (!TR_ERROR_IS_ENOSPC(my_error->code))
{
@ -57,7 +60,7 @@ static bool preallocate_file_sparse(tr_sys_file_t fd, uint64_t length, tr_error*
return true;
}
dbgmsg("Preallocating (sparse, fallback) failed (%d): %s", my_error->code, my_error->message);
logdbg("Preallocating (sparse, fallback) failed (%d): %s", my_error->code, my_error->message);
}
tr_error_propagate(error, &my_error);
@ -78,7 +81,7 @@ static bool preallocate_file_full(tr_sys_file_t fd, uint64_t length, tr_error**
return true;
}
dbgmsg("Preallocating (full, normal) failed (%d): %s", my_error->code, my_error->message);
logdbg("Preallocating (full, normal) failed (%d): %s", my_error->code, my_error->message);
if (!TR_ERROR_IS_ENOSPC(my_error->code))
{
@ -101,7 +104,7 @@ static bool preallocate_file_full(tr_sys_file_t fd, uint64_t length, tr_error**
return true;
}
dbgmsg("Preallocating (full, fallback) failed (%d): %s", my_error->code, my_error->message);
logdbg("Preallocating (full, fallback) failed (%d): %s", my_error->code, my_error->message);
}
tr_error_propagate(error, &my_error);
@ -168,13 +171,13 @@ static int cached_file_open(
if (dir == nullptr)
{
tr_logAddError(_("Couldn't get directory for \"%1$s\": %2$s"), filename, error->message);
logerr(_("Couldn't get directory for \"%1$s\": %2$s"), filename, error->message);
goto FAIL;
}
if (!tr_sys_dir_create(dir, TR_SYS_DIR_CREATE_PARENTS, 0777, &error))
{
tr_logAddError(_("Couldn't create \"%1$s\": %2$s"), dir, error->message);
logerr(_("Couldn't create \"%1$s\": %2$s"), dir, error->message);
tr_free(dir);
goto FAIL;
}
@ -195,7 +198,7 @@ static int cached_file_open(
if (fd == TR_BAD_SYS_FILE)
{
tr_logAddError(_("Couldn't open \"%1$s\": %2$s"), filename, error->message);
logerr(_("Couldn't open \"%1$s\": %2$s"), filename, error->message);
goto FAIL;
}
@ -219,7 +222,7 @@ static int cached_file_open(
if (!success)
{
tr_logAddError(
logwarn(
_("Couldn't preallocate file \"%1$s\" (%2$s, size: %3$" PRIu64 "): %4$s"),
filename,
type,
@ -228,7 +231,7 @@ static int cached_file_open(
goto FAIL;
}
tr_logAddDebug(_("Preallocated file \"%1$s\" (%2$s, size: %3$" PRIu64 ")"), filename, type, file_size);
logdbg(_("Preallocated file \"%1$s\" (%2$s, size: %3$" PRIu64 ")"), filename, type, file_size);
}
/* If the file already exists and it's too large, truncate it.
@ -239,7 +242,7 @@ static int cached_file_open(
*/
if (resize_needed && !tr_sys_file_truncate(fd, file_size, &error))
{
tr_logAddError(_("Couldn't truncate \"%1$s\": %2$s"), filename, error->message);
logwarn(_("Couldn't truncate \"%1$s\": %2$s"), filename, error->message);
goto FAIL;
}
@ -479,11 +482,11 @@ tr_sys_file_t tr_fdFileCheckout(
return TR_BAD_SYS_FILE;
}
dbgmsg("opened '%s' writable %c", filename, writable ? 'y' : 'n');
logtrace("opened '%s' writable %c", filename, writable ? 'y' : 'n');
o->is_writable = writable;
}
dbgmsg("checking out '%s'", filename);
logtrace("checking out '%s'", filename);
o->torrent_id = torrent_id;
o->file_index = i;
o->used_at = tr_time();
@ -511,7 +514,7 @@ tr_socket_t tr_fdSocketCreate(tr_session* session, int domain, int type)
if ((s == TR_BAD_SOCKET) && (sockerrno != EAFNOSUPPORT))
{
tr_logAddError(_("Couldn't create socket: %s"), tr_net_strerror(sockerrno).c_str());
logwarn(_("Couldn't create socket: %s"), tr_net_strerror(sockerrno).c_str());
}
}
@ -533,7 +536,7 @@ tr_socket_t tr_fdSocketCreate(tr_session* session, int domain, int type)
if (getsockopt(s, SOL_SOCKET, SO_SNDBUF, reinterpret_cast<char*>(&i), &size) != -1)
{
tr_logAddDebug("SO_SNDBUF size is %d", i);
logtrace("SO_SNDBUF size is %d", i);
}
i = 0;
@ -541,7 +544,7 @@ tr_socket_t tr_fdSocketCreate(tr_session* session, int domain, int type)
if (getsockopt(s, SOL_SOCKET, SO_RCVBUF, reinterpret_cast<char*>(&i), &size) != -1)
{
tr_logAddDebug("SO_RCVBUF size is %d", i);
logtrace("SO_RCVBUF size is %d", i);
}
buf_logged = true;

103
libtransmission/handshake.cc
View File

@ -4,6 +4,7 @@
// License text can be found in the licenses/ folder.
#include <algorithm>
#include <array>
#include <cerrno>
#include <cstring>
#include <string_view>
@ -130,14 +131,14 @@ struct tr_handshake
***
**/
#define dbgmsg(handshake, ...) \
#define logtrace(handshake, ...) \
do \
{ \
if (tr_logGetDeepEnabled()) \
if (tr_logLevelIsActive(TR_LOG_TRACE)) \
{ \
char addrstr[TR_ADDRSTRLEN]; \
tr_peerIoGetAddrStr(handshake->io, addrstr, sizeof(addrstr)); \
tr_logAddDeep(__FILE__, __LINE__, addrstr, __VA_ARGS__); \
auto addrstr = std::array<char, TR_ADDRSTRLEN>{}; \
tr_peerIoGetAddrStr(handshake->io, std::data(addrstr), std::size(addrstr)); \
tr_logAddMessage(__FILE__, __LINE__, TR_LOG_TRACE, std::data(addrstr), __VA_ARGS__); \
} \
} while (0)
@ -163,7 +164,7 @@ static char const* getStateName(handshake_state_t const state)
static void setState(tr_handshake* handshake, handshake_state_t state)
{
dbgmsg(handshake, "setting to state [%s]", getStateName(state));
logtrace(handshake, "setting to state [%s]", getStateName(state));
handshake->state = state;
}
@ -222,7 +223,7 @@ static handshake_parse_err_t parseHandshake(tr_handshake* handshake, struct evbu
uint8_t name[HANDSHAKE_NAME_LEN];
uint8_t reserved[HANDSHAKE_FLAGS_LEN];
dbgmsg(handshake, "payload: need %d, got %zu", HANDSHAKE_SIZE, evbuffer_get_length(inbuf));
logtrace(handshake, "payload: need %d, got %zu", HANDSHAKE_SIZE, evbuffer_get_length(inbuf));
if (evbuffer_get_length(inbuf) < HANDSHAKE_SIZE)
{
@ -245,7 +246,7 @@ static handshake_parse_err_t parseHandshake(tr_handshake* handshake, struct evbu
tr_peerIoReadBytes(handshake->io, inbuf, std::data(hash), std::size(hash));
if (auto const torrent_hash = tr_peerIoGetTorrentHash(handshake->io); !torrent_hash || *torrent_hash != hash)
{
dbgmsg(handshake, "peer returned the wrong hash. wtf?");
logtrace(handshake, "peer returned the wrong hash. wtf?");
return HANDSHAKE_BAD_TORRENT;
}
@ -255,11 +256,11 @@ static handshake_parse_err_t parseHandshake(tr_handshake* handshake, struct evbu
handshake->peer_id = peer_id;
/* peer id */
dbgmsg(handshake, "peer-id is [%" TR_PRIsv "]", TR_PRIsv_ARG(peer_id));
logtrace(handshake, "peer-id is [%" TR_PRIsv "]", TR_PRIsv_ARG(peer_id));
if (auto* const tor = handshake->session->torrents().get(hash); peer_id == tr_torrentGetPeerId(tor))
{
dbgmsg(handshake, "streuth! we've connected to ourselves.");
logtrace(handshake, "streuth! we've connected to ourselves.");
return HANDSHAKE_PEER_IS_SELF;
}
@ -383,7 +384,7 @@ static ReadState readYb(tr_handshake* handshake, struct evbuffer* inbuf)
}
}
dbgmsg(handshake, "got an %s handshake", (isEncrypted ? "encrypted" : "plain"));
logtrace(handshake, "got an %s handshake", (isEncrypted ? "encrypted" : "plain"));
tr_peerIoSetEncryption(handshake->io, isEncrypted ? PEER_ENCRYPTION_RC4 : PEER_ENCRYPTION_NONE);
@ -412,7 +413,7 @@ static ReadState readYb(tr_handshake* handshake, struct evbuffer* inbuf)
auto const req1 = computeRequestHash(handshake, "req1"sv);
if (!req1)
{
dbgmsg(handshake, "error while computing req1 hash after Yb");
logtrace(handshake, "error while computing req1 hash after Yb");
return tr_handshakeDone(handshake, false);
}
evbuffer_add(outbuf, std::data(*req1), std::size(*req1));
@ -424,7 +425,7 @@ static ReadState readYb(tr_handshake* handshake, struct evbuffer* inbuf)
auto const req3 = computeRequestHash(handshake, "req3"sv);
if (!req2 || !req3)
{
dbgmsg(handshake, "error while computing req2/req3 hash after Yb");
logtrace(handshake, "error while computing req2/req3 hash after Yb");
return tr_handshakeDone(handshake, false);
}
@ -490,7 +491,7 @@ static ReadState readVC(tr_handshake* handshake, struct evbuffer* inbuf)
{
if (evbuffer_get_length(inbuf) < VC_LENGTH)
{
dbgmsg(handshake, "not enough bytes... returning read_more");
logtrace(handshake, "not enough bytes... returning read_more");
return READ_LATER;
}
@ -506,7 +507,7 @@ static ReadState readVC(tr_handshake* handshake, struct evbuffer* inbuf)
evbuffer_drain(inbuf, 1);
}
dbgmsg(handshake, "got it!");
logtrace(handshake, "got it!");
evbuffer_drain(inbuf, key_len);
setState(handshake, AWAITING_CRYPTO_SELECT);
return READ_NOW;
@ -524,21 +525,21 @@ static ReadState readCryptoSelect(tr_handshake* handshake, struct evbuffer* inbu
uint32_t crypto_select = 0;
tr_peerIoReadUint32(handshake->io, inbuf, &crypto_select);
handshake->crypto_select = crypto_select;
dbgmsg(handshake, "crypto select is %d", (int)crypto_select);
logtrace(handshake, "crypto select is %d", (int)crypto_select);
if ((crypto_select & getCryptoProvide(handshake)) == 0)
{
dbgmsg(handshake, "peer selected an encryption option we didn't offer");
logtrace(handshake, "peer selected an encryption option we didn't offer");
return tr_handshakeDone(handshake, false);
}
uint16_t pad_d_len = 0;
tr_peerIoReadUint16(handshake->io, inbuf, &pad_d_len);
dbgmsg(handshake, "pad_d_len is %d", (int)pad_d_len);
logtrace(handshake, "pad_d_len is %d", (int)pad_d_len);
if (pad_d_len > 512)
{
dbgmsg(handshake, "encryption handshake: pad_d_len is too long");
logtrace(handshake, "encryption handshake: pad_d_len is too long");
return tr_handshakeDone(handshake, false);
}
@ -552,7 +553,7 @@ static ReadState readPadD(tr_handshake* handshake, struct evbuffer* inbuf)
{
size_t const needlen = handshake->pad_d_len;
dbgmsg(handshake, "pad d: need %zu, got %zu", needlen, evbuffer_get_length(inbuf));
logtrace(handshake, "pad d: need %zu, got %zu", needlen, evbuffer_get_length(inbuf));
if (evbuffer_get_length(inbuf) < needlen)
{
@ -575,7 +576,7 @@ static ReadState readPadD(tr_handshake* handshake, struct evbuffer* inbuf)
static ReadState readHandshake(tr_handshake* handshake, struct evbuffer* inbuf)
{
dbgmsg(handshake, "payload: need %d, got %zu", INCOMING_HANDSHAKE_LEN, evbuffer_get_length(inbuf));
logtrace(handshake, "payload: need %d, got %zu", INCOMING_HANDSHAKE_LEN, evbuffer_get_length(inbuf));
if (evbuffer_get_length(inbuf) < INCOMING_HANDSHAKE_LEN)
{
@ -592,7 +593,7 @@ static ReadState readHandshake(tr_handshake* handshake, struct evbuffer* inbuf)
if (handshake->encryptionMode == TR_ENCRYPTION_REQUIRED)
{
dbgmsg(handshake, "peer is unencrypted, and we're disallowing that");
logtrace(handshake, "peer is unencrypted, and we're disallowing that");
return tr_handshakeDone(handshake, false);
}
}
@ -602,7 +603,7 @@ static ReadState readHandshake(tr_handshake* handshake, struct evbuffer* inbuf)
if (tr_peerIoIsIncoming(handshake->io))
{
dbgmsg(handshake, "I think peer is sending us an encrypted handshake...");
logtrace(handshake, "I think peer is sending us an encrypted handshake...");
setState(handshake, AWAITING_YA);
return READ_NOW;
}
@ -611,7 +612,7 @@ static ReadState readHandshake(tr_handshake* handshake, struct evbuffer* inbuf)
if (pstrlen != 19)
{
dbgmsg(handshake, "I think peer has sent us a corrupt handshake...");
logtrace(handshake, "I think peer has sent us a corrupt handshake...");
return tr_handshakeDone(handshake, false);
}
}
@ -649,7 +650,7 @@ static ReadState readHandshake(tr_handshake* handshake, struct evbuffer* inbuf)
{
if (!handshake->session->torrents().contains(hash))
{
dbgmsg(handshake, "peer is trying to connect to us for a torrent we don't have.");
logtrace(handshake, "peer is trying to connect to us for a torrent we don't have.");
return tr_handshakeDone(handshake, false);
}
@ -660,7 +661,7 @@ static ReadState readHandshake(tr_handshake* handshake, struct evbuffer* inbuf)
auto const torrent_hash = tr_peerIoGetTorrentHash(handshake->io);
if (!torrent_hash || *torrent_hash != hash)
{
dbgmsg(handshake, "peer returned the wrong hash. wtf?");
logtrace(handshake, "peer returned the wrong hash. wtf?");
return tr_handshakeDone(handshake, false);
}
}
@ -699,7 +700,7 @@ static ReadState readPeerId(tr_handshake* handshake, struct evbuffer* inbuf)
char client[128] = {};
tr_clientForId(client, sizeof(client), peer_id);
dbgmsg(handshake, "peer-id is [%s] ... isIncoming is %d", client, tr_peerIoIsIncoming(handshake->io));
logtrace(handshake, "peer-id is [%s] ... isIncoming is %d", client, tr_peerIoIsIncoming(handshake->io));
// if we've somehow connected to ourselves, don't keep the connection
auto const hash = tr_peerIoGetTorrentHash(handshake->io);
@ -711,7 +712,7 @@ static ReadState readPeerId(tr_handshake* handshake, struct evbuffer* inbuf)
static ReadState readYa(tr_handshake* handshake, struct evbuffer* inbuf)
{
dbgmsg(handshake, "in readYa... need %d, have %zu", KEY_LEN, evbuffer_get_length(inbuf));
logtrace(handshake, "in readYa... need %d, have %zu", KEY_LEN, evbuffer_get_length(inbuf));
if (evbuffer_get_length(inbuf) < KEY_LEN)
{
@ -730,13 +731,13 @@ static ReadState readYa(tr_handshake* handshake, struct evbuffer* inbuf)
auto req1 = computeRequestHash(handshake, "req1"sv);
if (!req1)
{
dbgmsg(handshake, "error while computing req1 hash after Ya");
logtrace(handshake, "error while computing req1 hash after Ya");
return tr_handshakeDone(handshake, false);
}
handshake->myReq1 = *req1;
/* send our public key to the peer */
dbgmsg(handshake, "sending B->A: Diffie Hellman Yb, PadB");
logtrace(handshake, "sending B->A: Diffie Hellman Yb, PadB");
uint8_t outbuf[KEY_LEN + PadB_MAXLEN];
uint8_t* walk = outbuf;
int len = 0;
@ -763,7 +764,7 @@ static ReadState readPadA(tr_handshake* handshake, struct evbuffer* inbuf)
if (ptr.pos != -1) /* match */
{
evbuffer_drain(inbuf, ptr.pos);
dbgmsg(handshake, "found it... looking setting to awaiting_crypto_provide");
logtrace(handshake, "found it... looking setting to awaiting_crypto_provide");
setState(handshake, AWAITING_CRYPTO_PROVIDE);
return READ_NOW;
}
@ -798,14 +799,14 @@ static ReadState readCryptoProvide(tr_handshake* handshake, struct evbuffer* inb
/* This next piece is HASH('req2', SKEY) xor HASH('req3', S) ...
* we can get the first half of that (the obufscatedTorrentHash)
* by building the latter and xor'ing it with what the peer sent us */
dbgmsg(handshake, "reading obfuscated torrent hash...");
logtrace(handshake, "reading obfuscated torrent hash...");
auto req2 = tr_sha1_digest_t{};
evbuffer_remove(inbuf, std::data(req2), std::size(req2));
auto const req3 = computeRequestHash(handshake, "req3"sv);
if (!req3)
{
dbgmsg(handshake, "error while computing req3 hash after req2");
logtrace(handshake, "error while computing req3 hash after req2");
return tr_handshakeDone(handshake, false);
}
@ -819,18 +820,18 @@ static ReadState readCryptoProvide(tr_handshake* handshake, struct evbuffer* inb
{
bool const clientIsSeed = tor->isDone();
bool const peerIsSeed = tr_peerMgrPeerIsSeed(tor, tr_peerIoGetAddress(handshake->io, nullptr));
dbgmsg(handshake, "got INCOMING connection's encrypted handshake for torrent [%s]", tr_torrentName(tor));
logtrace(handshake, "got INCOMING connection's encrypted handshake for torrent [%s]", tr_torrentName(tor));
tr_peerIoSetTorrentHash(handshake->io, tor->infoHash());
if (clientIsSeed && peerIsSeed)
{
dbgmsg(handshake, "another seed tried to reconnect to us!");
logtrace(handshake, "another seed tried to reconnect to us!");
return tr_handshakeDone(handshake, false);
}
}
else
{
dbgmsg(handshake, "can't find that torrent...");
logtrace(handshake, "can't find that torrent...");
return tr_handshakeDone(handshake, false);
}
@ -842,10 +843,10 @@ static ReadState readCryptoProvide(tr_handshake* handshake, struct evbuffer* inb
tr_peerIoReadUint32(handshake->io, inbuf, &crypto_provide);
handshake->crypto_provide = crypto_provide;
dbgmsg(handshake, "crypto_provide is %d", (int)crypto_provide);
logtrace(handshake, "crypto_provide is %d", (int)crypto_provide);
tr_peerIoReadUint16(handshake->io, inbuf, &padc_len);
dbgmsg(handshake, "padc is %d", (int)padc_len);
logtrace(handshake, "padc is %d", (int)padc_len);
handshake->pad_c_len = padc_len;
setState(handshake, AWAITING_PAD_C);
return READ_NOW;
@ -867,7 +868,7 @@ static ReadState readPadC(tr_handshake* handshake, struct evbuffer* inbuf)
/* read ia_len */
tr_peerIoReadUint16(handshake->io, inbuf, &ia_len);
dbgmsg(handshake, "ia_len is %d", (int)ia_len);
logtrace(handshake, "ia_len is %d", (int)ia_len);
handshake->ia_len = ia_len;
setState(handshake, AWAITING_IA);
return READ_NOW;
@ -877,7 +878,7 @@ static ReadState readIA(tr_handshake* handshake, struct evbuffer const* inbuf)
{
size_t const needlen = handshake->ia_len;
dbgmsg(handshake, "reading IA... have %zu, need %zu", evbuffer_get_length(inbuf), needlen);
logtrace(handshake, "reading IA... have %zu, need %zu", evbuffer_get_length(inbuf), needlen);
if (evbuffer_get_length(inbuf) < needlen)
{
@ -896,7 +897,7 @@ static ReadState readIA(tr_handshake* handshake, struct evbuffer const* inbuf)
uint8_t vc[VC_LENGTH];
memset(vc, 0, VC_LENGTH);
evbuffer_add(outbuf, vc, VC_LENGTH);
dbgmsg(handshake, "sending vc");
logtrace(handshake, "sending vc");
}
/* send crypto_select */
@ -904,17 +905,17 @@ static ReadState readIA(tr_handshake* handshake, struct evbuffer const* inbuf)
if (crypto_select != 0)
{
dbgmsg(handshake, "selecting crypto mode '%d'", (int)crypto_select);
logtrace(handshake, "selecting crypto mode '%d'", (int)crypto_select);
evbuffer_add_uint32(outbuf, crypto_select);
}
else
{
dbgmsg(handshake, "peer didn't offer an encryption mode we like.");
logtrace(handshake, "peer didn't offer an encryption mode we like.");
evbuffer_free(outbuf);
return tr_handshakeDone(handshake, false);
}
dbgmsg(handshake, "sending pad d");
logtrace(handshake, "sending pad d");
/* ENCRYPT(VC, crypto_provide, len(PadD), PadD
* PadD is reserved for future extensions to the handshake...
@ -931,7 +932,7 @@ static ReadState readIA(tr_handshake* handshake, struct evbuffer const* inbuf)
tr_peerIoSetEncryption(handshake->io, PEER_ENCRYPTION_NONE);
}
dbgmsg(handshake, "sending handshake");
logtrace(handshake, "sending handshake");
/* send our handshake */
{
@ -959,7 +960,7 @@ static ReadState readPayloadStream(tr_handshake* handshake, struct evbuffer* inb
{
size_t const needlen = HANDSHAKE_SIZE;
dbgmsg(handshake, "reading payload stream... have %zu, need %zu", evbuffer_get_length(inbuf), needlen);
logtrace(handshake, "reading payload stream... have %zu, need %zu", evbuffer_get_length(inbuf), needlen);
if (evbuffer_get_length(inbuf) < needlen)
{
@ -968,7 +969,7 @@ static ReadState readPayloadStream(tr_handshake* handshake, struct evbuffer* inb
/* parse the handshake ... */
handshake_parse_err_t const i = parseHandshake(handshake, inbuf);
dbgmsg(handshake, "parseHandshake returned %d", i);
logtrace(handshake, "parseHandshake returned %d", i);
if (i != HANDSHAKE_OK)
{
@ -997,7 +998,7 @@ static ReadState canRead(tr_peerIo* io, void* vhandshake, size_t* piece)
/* no piece data in handshake */
*piece = 0;
dbgmsg(handshake, "handling canRead; state is [%s]", getStateName(handshake->state));
logtrace(handshake, "handling canRead; state is [%s]", getStateName(handshake->state));
ReadState ret = READ_NOW;
while (readyForMore)
@ -1108,7 +1109,7 @@ static void tr_handshakeFree(tr_handshake* handshake)
static ReadState tr_handshakeDone(tr_handshake* handshake, bool isOK)
{
dbgmsg(handshake, "handshakeDone: %s", isOK ? "connected" : "aborting");
logtrace(handshake, "handshakeDone: %s", isOK ? "connected" : "aborting");
tr_peerIoSetIOFuncs(handshake->io, nullptr, nullptr, nullptr, nullptr);
bool const success = fireDoneFunc(handshake, isOK);
@ -1160,7 +1161,7 @@ static void gotError(tr_peerIo* io, short what, void* vhandshake)
{
uint8_t msg[HANDSHAKE_SIZE];
dbgmsg(handshake, "handshake failed, trying plaintext...");
logtrace(handshake, "handshake failed, trying plaintext...");
buildHandshakeMessage(handshake, msg);
handshake->haveSentBitTorrentHandshake = true;
setReadState(handshake, AWAITING_HANDSHAKE);
@ -1168,7 +1169,7 @@ static void gotError(tr_peerIo* io, short what, void* vhandshake)
}
else
{
dbgmsg(handshake, "libevent got an error what==%d, errno=%d (%s)", (int)what, errcode, tr_strerror(errcode));
logtrace(handshake, "libevent got an error what==%d, errno=%d (%s)", (int)what, errcode, tr_strerror(errcode));
tr_handshakeDone(handshake, false);
}
}

67
libtransmission/log.cc
View File

@ -28,16 +28,6 @@ static tr_log_message* myQueue = nullptr;
static tr_log_message** myQueueTail = &myQueue;
static int myQueueLength = 0;
#ifndef _WIN32
/* make null versions of these win32 functions */
static inline bool IsDebuggerPresent()
{
return false;
}
#endif
/***
****
***/
@ -141,56 +131,6 @@ char* tr_logGetTimeStr(char* buf, size_t buflen)
return buf;
}
bool tr_logGetDeepEnabled()
{
static int8_t deepLoggingIsActive = -1;
if (deepLoggingIsActive < 0)
{
deepLoggingIsActive = (int8_t)(IsDebuggerPresent() || tr_logGetFile() != TR_BAD_SYS_FILE);
}
return deepLoggingIsActive != 0;
}
void tr_logAddDeep(char const* file, int line, char const* name, char const* fmt, ...)
{
tr_sys_file_t const fp = tr_logGetFile();
if (fp != TR_BAD_SYS_FILE || IsDebuggerPresent())
{
struct evbuffer* buf = evbuffer_new();
char* base = tr_sys_path_basename(file, nullptr);
char timestr[64];
evbuffer_add_printf(buf, "[%s] ", tr_logGetTimeStr(timestr, sizeof(timestr)));
if (name != nullptr)
{
evbuffer_add_printf(buf, "%s ", name);
}
va_list args;
va_start(args, fmt);
evbuffer_add_vprintf(buf, fmt, args);
va_end(args);
evbuffer_add_printf(buf, " (%s:%d)" TR_NATIVE_EOL_STR, base, line);
auto const message = evbuffer_free_to_str(buf);
#ifdef _WIN32
OutputDebugStringA(message.c_str());
#endif
if (fp != TR_BAD_SYS_FILE)
{
tr_sys_file_write(fp, std::data(message), std::size(message), nullptr, nullptr);
}
tr_free(base);
}
}
/***
****
***/
@ -198,11 +138,16 @@ void tr_logAddDeep(char const* file, int line, char const* name, char const* fmt
void tr_logAddMessage(
[[maybe_unused]] char const* file,
[[maybe_unused]] int line,
[[maybe_unused]] tr_log_level level,
tr_log_level level,
[[maybe_unused]] char const* name,
char const* fmt,
...)
{
if (!tr_logLevelIsActive(level))
{
return;
}
int const err = errno; /* message logging shouldn't affect errno */
char buf[1024];
va_list ap;

17
libtransmission/log.h
View File

@ -8,7 +8,7 @@
#include <stddef.h> /* size_t */
#include "file.h" /* tr_sys_file_t */
#include "tr-macros.h"
#include "transmission.h"
#define TR_LOG_MAX_QUEUE_LENGTH 10000
@ -49,21 +49,6 @@ void tr_logAddMessage(char const* file, int line, tr_log_level level, char const
tr_sys_file_t tr_logGetFile(void);
/** @brief return true if deep logging has been enabled by the user, false otherwise */
bool tr_logGetDeepEnabled(void);
void tr_logAddDeep(char const* file, int line, char const* name, char const* fmt, ...) TR_GNUC_PRINTF(4, 5)
TR_GNUC_NONNULL(1, 4);
#define tr_logAddDeepNamed(name, ...) \
do \
{ \
if (tr_logGetDeepEnabled()) \
{ \
tr_logAddDeep(__FILE__, __LINE__, name, __VA_ARGS__); \
} \
} while (0)
/** @brief set the buffer with the current time formatted for deep logging. */
char* tr_logGetTimeStr(char* buf, size_t buflen) TR_GNUC_NONNULL(1);

39
libtransmission/net.cc
View File

@ -44,6 +44,11 @@ tr_address const tr_in6addr_any = { TR_AF_INET6, { IN6ADDR_ANY_INIT } };
tr_address const tr_inaddr_any = { TR_AF_INET, { { { { INADDR_ANY } } } } };
#define logerr(...) tr_logAddNamed(TR_LOG_ERROR, "net", __VA_ARGS__)
#define logwarn(...) tr_logAddNamed(TR_LOG_WARN, "net", __VA_ARGS__)
#define logdbg(...) tr_logAddNamed(TR_LOG_DEBUG, "net", __VA_ARGS__)
#define logtrace(...) tr_logAddNamed(TR_LOG_TRACE, "net", __VA_ARGS__)
std::string tr_net_strerror(int err)
{
#ifdef _WIN32
@ -235,7 +240,7 @@ void tr_netSetTOS([[maybe_unused]] tr_socket_t s, [[maybe_unused]] int tos, tr_a
if (setsockopt(s, IPPROTO_IP, IP_TOS, (void const*)&tos, sizeof(tos)) == -1)
{
tr_logAddNamedInfo("Net", "Can't set TOS '%d': %s", tos, tr_net_strerror(sockerrno).c_str());
logwarn("Can't set TOS '%d': %s", tos, tr_net_strerror(sockerrno).c_str());
}
#endif
}
@ -244,14 +249,14 @@ void tr_netSetTOS([[maybe_unused]] tr_socket_t s, [[maybe_unused]] int tos, tr_a
#if defined(IPV6_TCLASS) && !defined(_WIN32)
if (setsockopt(s, IPPROTO_IPV6, IPV6_TCLASS, (void const*)&tos, sizeof(tos)) == -1)
{
tr_logAddNamedInfo("Net", "Can't set IPv6 QoS '%d': %s", tos, tr_net_strerror(sockerrno).c_str());
logwarn("Can't set IPv6 QoS '%d': %s", tos, tr_net_strerror(sockerrno).c_str());
}
#endif
}
else
{
/* program should never reach here! */
tr_logAddNamedInfo("Net", "Something goes wrong while setting TOS/Traffic-Class");
logdbg("Something goes wrong while setting TOS/Traffic-Class");
}
}
@ -261,11 +266,7 @@ void tr_netSetCongestionControl([[maybe_unused]] tr_socket_t s, [[maybe_unused]]
if (setsockopt(s, IPPROTO_TCP, TCP_CONGESTION, (void const*)algorithm, strlen(algorithm) + 1) == -1)
{
tr_logAddNamedInfo(
"Net",
"Can't set congestion control algorithm '%s': %s",
algorithm,
tr_net_strerror(sockerrno).c_str());
logwarn("Can't set congestion control algorithm '%s': %s", algorithm, tr_net_strerror(sockerrno).c_str());
}
#endif
@ -345,10 +346,7 @@ struct tr_peer_socket tr_netOpenPeerSocket(tr_session* session, tr_address const
if (setsockopt(s, SOL_SOCKET, SO_RCVBUF, reinterpret_cast<char const*>(&n), sizeof(n)) == -1)
{
tr_logAddInfo(
"Unable to set SO_RCVBUF on socket %" PRIdMAX ": %s",
(intmax_t)s,
tr_net_strerror(sockerrno).c_str());
logwarn("Unable to set SO_RCVBUF on socket %" PRIdMAX ": %s", (intmax_t)s, tr_net_strerror(sockerrno).c_str());
}
}
@ -367,7 +365,7 @@ struct tr_peer_socket tr_netOpenPeerSocket(tr_session* session, tr_address const
if (bind(s, (struct sockaddr*)&source_sock, sourcelen) == -1)
{
tr_logAddError(
logwarn(
_("Couldn't set source address %s on %" PRIdMAX ": %s"),
tr_address_to_string(source_addr),
(intmax_t)s,
@ -386,7 +384,7 @@ struct tr_peer_socket tr_netOpenPeerSocket(tr_session* session, tr_address const
if ((tmperrno != ENETUNREACH && tmperrno != EHOSTUNREACH) || addr->type == TR_AF_INET)
{
tr_logAddError(
logwarn(
_("Couldn't connect socket %" PRIdMAX " to %s, port %d (errno %d - %s)"),
(intmax_t)s,
tr_address_to_string(addr),
@ -402,12 +400,9 @@ struct tr_peer_socket tr_netOpenPeerSocket(tr_session* session, tr_address const
ret = tr_peer_socket_tcp_create(s);
}
if (tr_logGetDeepEnabled())
{
char addrstr[TR_ADDRSTRLEN];
tr_address_and_port_to_string(addrstr, sizeof(addrstr), addr, port);
tr_logAddDeep(__FILE__, __LINE__, nullptr, "New OUTGOING connection %" PRIdMAX " (%s)", (intmax_t)s, addrstr);
}
char addrstr[TR_ADDRSTRLEN];
tr_address_and_port_to_string(addrstr, sizeof(addrstr), addr, port);
logtrace("New OUTGOING connection %" PRIdMAX " (%s)", (intmax_t)s, addrstr);
return ret;
}
@ -504,7 +499,7 @@ static tr_socket_t tr_netBindTCPImpl(tr_address const* addr, tr_port port, bool
char const* const fmt = hint == nullptr ? _("Couldn't bind port %d on %s: %s") :
_("Couldn't bind port %d on %s: %s (%s)");
tr_logAddError(fmt, port, tr_address_to_string(addr), tr_net_strerror(err).c_str(), hint);
logerr(fmt, port, tr_address_to_string(addr), tr_net_strerror(err).c_str(), hint);
}
tr_netCloseSocket(fd);
@ -514,7 +509,7 @@ static tr_socket_t tr_netBindTCPImpl(tr_address const* addr, tr_port port, bool
if (!suppressMsgs)
{
tr_logAddDebug("Bound socket %" PRIdMAX " to port %d on %s", (intmax_t)fd, port, tr_address_to_string(addr));
logdbg("Bound socket %" PRIdMAX " to port %d on %s", (intmax_t)fd, port, tr_address_to_string(addr));
}
#ifdef TCP_FASTOPEN

93
libtransmission/peer-io.cc
View File

@ -68,17 +68,22 @@ static size_t guessPacketOverhead(size_t d)
***
**/
#define dbgmsg(io, ...) \
#define logimpl(io, level, ...) \
do \
{ \
if (tr_logGetDeepEnabled()) \
if (tr_logLevelIsActive(level)) \
{ \
char addrstr[TR_ADDRSTRLEN]; \
tr_peerIoGetAddrStr(io, addrstr, sizeof(addrstr)); \
tr_logAddDeep(__FILE__, __LINE__, addrstr, __VA_ARGS__); \
auto name = std::array<char, TR_ADDRSTRLEN>{}; \
tr_peerIoGetAddrStr(io, std::data(name), std::size(name)); \
tr_logAddMessage(__FILE__, __LINE__, level, std::data(name), __VA_ARGS__); \
} \
} while (0)
#define logerr(io, ...) logimpl(io, TR_LOG_ERROR, __VA_ARGS__)
#define logwarn(io, ...) logimpl(io, TR_LOG_WARN, __VA_ARGS__)
#define logdbg(io, ...) logimpl(io, TR_LOG_DEBUG, __VA_ARGS__)
#define logtrace(io, ...) logimpl(io, TR_LOG_TRACE, __VA_ARGS__)
/**
***
**/
@ -188,7 +193,7 @@ static void didWriteWrapper(tr_peerIo* io, unsigned int bytes_transferred)
static void canReadWrapper(tr_peerIo* io)
{
dbgmsg(io, "canRead");
logtrace(io, "canRead");
tr_peerIoRef(io);
@ -273,7 +278,7 @@ static void event_read_cb(evutil_socket_t fd, short /*event*/, void* vio)
unsigned int howmuch = curlen >= max ? 0 : max - curlen;
howmuch = io->bandwidth->clamp(TR_DOWN, howmuch);
dbgmsg(io, "libevent says this peer is ready to read");
logtrace(io, "libevent says this peer is ready to read");
/* if we don't have any bandwidth left, stop reading */
if (howmuch < 1)
@ -312,7 +317,7 @@ static void event_read_cb(evutil_socket_t fd, short /*event*/, void* vio)
what |= BEV_EVENT_ERROR;
}
dbgmsg(io, "event_read_cb err: res:%d, what:%hd, errno:%d (%s)", res, what, e, tr_net_strerror(e).c_str());
logdbg(io, "event_read_cb err: res:%d, what:%hd, errno:%d (%s)", res, what, e, tr_net_strerror(e).c_str());
if (io->gotError != nullptr)
{
@ -326,7 +331,7 @@ static int tr_evbuffer_write(tr_peerIo* io, int fd, size_t howmuch)
EVUTIL_SET_SOCKET_ERROR(0);
int const n = evbuffer_write_atmost(io->outbuf, fd, howmuch);
int const e = EVUTIL_SOCKET_ERROR();
dbgmsg(io, "wrote %d to peer (%s)", n, (n == -1 ? tr_net_strerror(e).c_str() : ""));
logtrace(io, "wrote %d to peer (%s)", n, (n == -1 ? tr_net_strerror(e).c_str() : ""));
return n;
}
@ -344,7 +349,7 @@ static void event_write_cb(evutil_socket_t fd, short /*event*/, void* vio)
io->pendingEvents &= ~EV_WRITE;
dbgmsg(io, "libevent says this peer is ready to write");
logtrace(io, "libevent says this peer is ready to write");
/* Write as much as possible, since the socket is non-blocking, write() will
* return if it can't write any more data without blocking */
@ -400,7 +405,7 @@ RESCHEDULE:
FAIL:
auto const errmsg = tr_net_strerror(e);
dbgmsg(io, "event_write_cb got an err. res:%d, what:%hd, errno:%d (%s)", res, what, e, errmsg.c_str());
logdbg(io, "event_write_cb got an err. res:%d, what:%hd, errno:%d (%s)", res, what, e, errmsg.c_str());
if (io->gotError != nullptr)
{
@ -430,7 +435,7 @@ static void utp_on_read(void* vio, unsigned char const* buf, size_t buflen)
TR_ASSERT(tr_isPeerIo(io));
int rc = evbuffer_add(io->inbuf, buf, buflen);
dbgmsg(io, "utp_on_read got %zu bytes", buflen);
logtrace(io, "utp_on_read got %zu bytes", buflen);
if (rc < 0)
{
@ -449,12 +454,12 @@ static void utp_on_write(void* vio, unsigned char* buf, size_t buflen)
TR_ASSERT(tr_isPeerIo(io));
int rc = evbuffer_remove(io->outbuf, buf, buflen);
dbgmsg(io, "utp_on_write sending %zu bytes... evbuffer_remove returned %d", buflen, rc);
logtrace(io, "utp_on_write sending %zu bytes... evbuffer_remove returned %d", buflen, rc);
TR_ASSERT(rc == (int)buflen); /* if this fails, we've corrupted our bookkeeping somewhere */
if (rc < (long)buflen)
{
tr_logAddNamedError("UTP", "Short write: %d < %ld", rc, (long)buflen);
logwarn(io, "Short write: %d < %ld", rc, (long)buflen);
}
didWriteWrapper(io, buflen);
@ -468,7 +473,7 @@ static size_t utp_get_rb_size(void* vio)
size_t bytes = io->bandwidth->clamp(TR_DOWN, UTP_READ_BUFFER_SIZE);
dbgmsg(io, "utp_get_rb_size is saying it's ready to read %zu bytes", bytes);
logtrace(io, "utp_get_rb_size is saying it's ready to read %zu bytes", bytes);
return UTP_READ_BUFFER_SIZE - bytes;
}
@ -476,7 +481,7 @@ static int tr_peerIoTryWrite(tr_peerIo* io, size_t howmuch);
static void utp_on_writable(tr_peerIo* io)
{
dbgmsg(io, "libutp says this peer is ready to write");
logtrace(io, "libutp says this peer is ready to write");
int const n = tr_peerIoTryWrite(io, SIZE_MAX);
tr_peerIoSetEnabled(io, TR_UP, n != 0 && evbuffer_get_length(io->outbuf) != 0);
@ -490,12 +495,12 @@ static void utp_on_state_change(void* vio, int state)
if (state == UTP_STATE_CONNECT)
{
dbgmsg(io, "utp_on_state_change -- changed to connected");
logdbg(io, "utp_on_state_change -- changed to connected");
io->utpSupported = true;
}
else if (state == UTP_STATE_WRITABLE)
{
dbgmsg(io, "utp_on_state_change -- changed to writable");
logdbg(io, "utp_on_state_change -- changed to writable");
if ((io->pendingEvents & EV_WRITE) != 0)
{
@ -511,12 +516,12 @@ static void utp_on_state_change(void* vio, int state)
}
else if (state == UTP_STATE_DESTROYING)
{
tr_logAddNamedError("UTP", "Impossible state UTP_STATE_DESTROYING");
logerr(io, "Impossible state UTP_STATE_DESTROYING");
return;
}
else
{
tr_logAddNamedError("UTP", "Unknown state %d", state);
logerr(io, "Unknown state %d", state);
}
}
@ -526,7 +531,7 @@ static void utp_on_error(void* vio, int errcode)
TR_ASSERT(tr_isPeerIo(io));
dbgmsg(io, "utp_on_error -- errcode is %d", errcode);
logdbg(io, "utp_on_error -- errcode is %d", errcode);
if (io->gotError != nullptr)
{
@ -541,7 +546,7 @@ static void utp_on_overhead(void* vio, bool send, size_t count, int /*type*/)
TR_ASSERT(tr_isPeerIo(io));
dbgmsg(io, "utp_on_overhead -- count is %zu", count);
logtrace(io, "utp_on_overhead -- count is %zu", count);
io->bandwidth->notifyBandwidthConsumed(send ? TR_UP : TR_DOWN, count, false, tr_time_msec());
}
@ -622,12 +627,12 @@ static tr_peerIo* tr_peerIoNew(
io->socket = socket;
io->bandwidth = new Bandwidth(parent);
io->bandwidth->setPeer(io);
dbgmsg(io, "bandwidth is %p; its parent is %p", (void*)&io->bandwidth, (void*)parent);
logtrace(io, "bandwidth is %p; its parent is %p", (void*)&io->bandwidth, (void*)parent);
switch (socket.type)
{
case TR_PEER_SOCKET_TYPE_TCP:
dbgmsg(io, "socket (tcp) is %" PRIdMAX, (intmax_t)socket.handle.tcp);
logtrace(io, "socket (tcp) is %" PRIdMAX, (intmax_t)socket.handle.tcp);
io->event_read = event_new(session->event_base, socket.handle.tcp, EV_READ, event_read_cb, io);
io->event_write = event_new(session->event_base, socket.handle.tcp, EV_WRITE, event_write_cb, io);
break;
@ -635,14 +640,14 @@ static tr_peerIo* tr_peerIoNew(
#ifdef WITH_UTP
case TR_PEER_SOCKET_TYPE_UTP:
dbgmsg(io, "socket (utp) is %p", (void*)socket.handle.utp);
logtrace(io, "socket (utp) is %p", (void*)socket.handle.utp);
UTP_SetSockopt(socket.handle.utp, SO_RCVBUF, UTP_READ_BUFFER_SIZE);
dbgmsg(io, "%s", "calling UTP_SetCallbacks &utp_function_table");
logtrace(io, "%s", "calling UTP_SetCallbacks &utp_function_table");
UTP_SetCallbacks(socket.handle.utp, &utp_function_table, io);
if (!is_incoming)
{
dbgmsg(io, "%s", "calling UTP_Connect");
logtrace(io, "%s", "calling UTP_Connect");
UTP_Connect(socket.handle.utp);
}
@ -694,7 +699,7 @@ tr_peerIo* tr_peerIoNewOutgoing(
if (socket.type == TR_PEER_SOCKET_TYPE_NONE)
{
socket = tr_netOpenPeerSocket(session, addr, port, is_seed);
dbgmsg(
logdbg(
nullptr,
"tr_netOpenPeerSocket returned fd %" PRIdMAX,
(intmax_t)(socket.type != TR_PEER_SOCKET_TYPE_NONE ? socket.handle.tcp : TR_BAD_SOCKET));
@ -728,7 +733,7 @@ static void event_enable(tr_peerIo* io, short event)
if ((event & EV_READ) != 0 && (io->pendingEvents & EV_READ) == 0)
{
dbgmsg(io, "enabling ready-to-read polling");
logtrace(io, "enabling ready-to-read polling");
if (need_events)
{
@ -740,7 +745,7 @@ static void event_enable(tr_peerIo* io, short event)
if ((event & EV_WRITE) != 0 && (io->pendingEvents & EV_WRITE) == 0)
{
dbgmsg(io, "enabling ready-to-write polling");
logtrace(io, "enabling ready-to-write polling");
if (need_events)
{
@ -767,7 +772,7 @@ static void event_disable(tr_peerIo* io, short event)
if ((event & EV_READ) != 0 && (io->pendingEvents & EV_READ) != 0)
{
dbgmsg(io, "disabling ready-to-read polling");
logtrace(io, "disabling ready-to-read polling");
if (need_events)
{
@ -779,7 +784,7 @@ static void event_disable(tr_peerIo* io, short event)
if ((event & EV_WRITE) != 0 && (io->pendingEvents & EV_WRITE) != 0)
{
dbgmsg(io, "disabling ready-to-write polling");
logtrace(io, "disabling ready-to-write polling");
if (need_events)
{
@ -834,7 +839,7 @@ static void io_close_socket(tr_peerIo* io)
#endif
default:
dbgmsg(io, "unsupported peer socket type %d", io->socket.type);
logdbg(io, "unsupported peer socket type %d", io->socket.type);
}
io->socket = {};
@ -858,7 +863,7 @@ static void io_dtor(tr_peerIo* const io)
TR_ASSERT(tr_amInEventThread(io->session));
TR_ASSERT(io->session->events != nullptr);
dbgmsg(io, "in tr_peerIo destructor");
logdbg(io, "in tr_peerIo destructor");
event_disable(io, EV_READ | EV_WRITE);
delete io->bandwidth;
io_close_socket(io);
@ -876,7 +881,7 @@ static void tr_peerIoFree(tr_peerIo* io)
{
if (io != nullptr)
{
dbgmsg(io, "in tr_peerIoFree");
logdbg(io, "in tr_peerIoFree");
io->canRead = nullptr;
io->didWrite = nullptr;
io->gotError = nullptr;
@ -888,7 +893,7 @@ void tr_peerIoRefImpl(char const* file, int line, tr_peerIo* io)
{
TR_ASSERT(tr_isPeerIo(io));
dbgmsg(io, "%s:%d is incrementing the IO's refcount from %d to %d", file, line, io->refCount, io->refCount + 1);
logtrace(io, "%s:%d is incrementing the IO's refcount from %d to %d", file, line, io->refCount, io->refCount + 1);
++io->refCount;
}
@ -897,7 +902,7 @@ void tr_peerIoUnrefImpl(char const* file, int line, tr_peerIo* io)
{
TR_ASSERT(tr_isPeerIo(io));
dbgmsg(io, "%s:%d is decrementing the IO's refcount from %d to %d", file, line, io->refCount, io->refCount - 1);
logtrace(io, "%s:%d is decrementing the IO's refcount from %d to %d", file, line, io->refCount, io->refCount - 1);
if (--io->refCount == 0)
{
@ -1248,7 +1253,7 @@ static int tr_peerIoTryRead(tr_peerIo* io, size_t howmuch)
res = evbuffer_read(io->inbuf, io->socket.handle.tcp, (int)howmuch);
int const e = EVUTIL_SOCKET_ERROR();
dbgmsg(io, "read %d from peer (%s)", res, res == -1 ? tr_net_strerror(e).c_str() : "");
logtrace(io, "read %d from peer (%s)", res, res == -1 ? tr_net_strerror(e).c_str() : "");
if (evbuffer_get_length(io->inbuf) != 0)
{
@ -1264,7 +1269,7 @@ static int tr_peerIoTryRead(tr_peerIo* io, size_t howmuch)
what |= BEV_EVENT_EOF;
}
dbgmsg(io, "tr_peerIoTryRead err: res:%d what:%hd, errno:%d (%s)", res, what, e, tr_net_strerror(e).c_str());
logtrace(io, "tr_peerIoTryRead err: res:%d what:%hd, errno:%d (%s)", res, what, e, tr_net_strerror(e).c_str());
io->gotError(io, what, io->userData);
}
@ -1273,7 +1278,7 @@ static int tr_peerIoTryRead(tr_peerIo* io, size_t howmuch)
}
default:
dbgmsg(io, "unsupported peer socket type %d", io->socket.type);
logdbg(io, "unsupported peer socket type %d", io->socket.type);
}
return res;
@ -1283,7 +1288,7 @@ static int tr_peerIoTryWrite(tr_peerIo* io, size_t howmuch)
{
auto const old_len = size_t{ evbuffer_get_length(io->outbuf) };
dbgmsg(io, "in tr_peerIoTryWrite %zu", howmuch);
logtrace(io, "in tr_peerIoTryWrite %zu", howmuch);
howmuch = std::min(howmuch, old_len);
howmuch = io->bandwidth->clamp(TR_UP, howmuch);
if (howmuch == 0)
@ -1314,7 +1319,7 @@ static int tr_peerIoTryWrite(tr_peerIo* io, size_t howmuch)
{
short const what = BEV_EVENT_WRITING | BEV_EVENT_ERROR;
dbgmsg(io, "tr_peerIoTryWrite err: res:%d, what:%hd, errno:%d (%s)", n, what, e, tr_net_strerror(e).c_str());
logtrace(io, "tr_peerIoTryWrite err: res:%d, what:%hd, errno:%d (%s)", n, what, e, tr_net_strerror(e).c_str());
io->gotError(io, what, io->userData);
}
@ -1322,7 +1327,7 @@ static int tr_peerIoTryWrite(tr_peerIo* io, size_t howmuch)
}
default:
dbgmsg(io, "unsupported peer socket type %d", io->socket.type);
logdbg(io, "unsupported peer socket type %d", io->socket.type);
}
return n;
@ -1334,7 +1339,7 @@ int tr_peerIoFlush(tr_peerIo* io, tr_direction dir, size_t limit)
TR_ASSERT(tr_isDirection(dir));
int const bytes_used = dir == TR_DOWN ? tr_peerIoTryRead(io, limit) : tr_peerIoTryWrite(io, limit);
dbgmsg(io, "flushing peer-io, direction:%d, limit:%zu, byte_used:%d", (int)dir, limit, bytes_used);
logtrace(io, "flushing peer-io, direction:%d, limit:%zu, byte_used:%d", (int)dir, limit, bytes_used);
return bytes_used;
}

54
libtransmission/peer-mgr.cc
View File

@ -225,9 +225,9 @@ struct tr_peerMgr
event* atomTimer = nullptr;
};
#define tordbg(t, ...) tr_logAddDeepNamed(tr_torrentName((t)->tor), __VA_ARGS__)
#define dbgmsg(...) tr_logAddDeepNamed(nullptr, __VA_ARGS__)
#define logdbgSwarm(swarm, ...) tr_logAddNamed(TR_LOG_DEBUG, tr_torrentName((swarm)->tor), __VA_ARGS__)
#define logtraceSwarm(swarm, ...) tr_logAddNamed(TR_LOG_TRACE, tr_torrentName((swarm)->tor), __VA_ARGS__)
#define logtrace(...) tr_logAddNamed(TR_LOG_TRACE, nullptr, __VA_ARGS__)
/**
*** tr_peer virtual functions
@ -447,7 +447,7 @@ static constexpr bool atomIsSeed(struct peer_atom const* atom)
static void atomSetSeed(tr_swarm* s, struct peer_atom* atom)
{
tordbg(s, "marking peer %s as a seed", tr_atomAddrStr(atom));
logtraceSwarm(s, "marking peer %s as a seed", tr_atomAddrStr(atom));
atom->flags |= ADDED_F_SEED_FLAG;
s->poolIsAllSeedsDirty = true;
}
@ -665,14 +665,14 @@ static void refillUpkeep(evutil_socket_t /*fd*/, short /*what*/, void* vmgr)
static void addStrike(tr_swarm* s, tr_peer* peer)
{
tordbg(s, "increasing peer %s strike count to %d", tr_atomAddrStr(peer->atom), peer->strikes + 1);
logtraceSwarm(s, "increasing peer %s strike count to %d", tr_atomAddrStr(peer->atom), peer->strikes + 1);
if (++peer->strikes >= MaxBadPiecesPerPeer)
{
struct peer_atom* atom = peer->atom;
atom->flags2 |= MyflagBanned;
peer->doPurge = true;
tordbg(s, "banning peer %s", tr_atomAddrStr(atom));
logtraceSwarm(s, "banning peer %s", tr_atomAddrStr(atom));
}
}
@ -848,14 +848,14 @@ static void peerCallbackFunc(tr_peer* peer, tr_peer_event const* e, void* vs)
{
/* some protocol error from the peer */
peer->doPurge = true;
tordbg(
logdbgSwarm(
s,
"setting %s doPurge flag because we got an ERANGE, EMSGSIZE, or ENOTCONN error",
tr_atomAddrStr(peer->atom));
}
else
{
tordbg(s, "unhandled error: %s", tr_strerror(e->err));
logdbgSwarm(s, "unhandled error: %s", tr_strerror(e->err));
}
break;
@ -922,7 +922,7 @@ static struct peer_atom* ensureAtomExists(
a->blocklisted = -1;
tr_ptrArrayInsertSorted(&s->pool, a, compareAtomsByAddress);
tordbg(s, "got a new atom: %s", tr_atomAddrStr(a));
logtraceSwarm(s, "got a new atom: %s", tr_atomAddrStr(a));
}
else
{
@ -1012,7 +1012,11 @@ static bool on_handshake_done(tr_handshake_result const& result)
if (!result.readAnythingFromPeer)
{
tordbg(s, "marking peer %s as unreachable... numFails is %d", tr_atomAddrStr(atom), int(atom->numFails));
logtraceSwarm(
s,
"marking peer %s as unreachable... numFails is %d",
tr_atomAddrStr(atom),
int(atom->numFails));
atom->flags2 |= MyflagUnreachable;
}
}
@ -1041,7 +1045,7 @@ static bool on_handshake_done(tr_handshake_result const& result)
if ((atom->flags2 & MyflagBanned) != 0)
{
tordbg(s, "banned peer %s tried to reconnect", tr_atomAddrStr(atom));
logtraceSwarm(s, "banned peer %s tried to reconnect", tr_atomAddrStr(atom));
}
else if (tr_peerIoIsIncoming(result.io) && getPeerCount(s) >= getMaxPeerCount(s->tor))
{
@ -1202,7 +1206,7 @@ void tr_peerMgrGotBadPiece(tr_torrent* tor, tr_piece_index_t pieceIndex)
if (peer->blame.test(pieceIndex))
{
tordbg(
logtraceSwarm(
s,
"peer %s contributed to corrupt piece (%d); now has %d strikes",
tr_atomAddrStr(peer->atom),
@ -1902,7 +1906,7 @@ static void rechokeDownloads(tr_swarm* s)
double const cancelRate = cancels / (double)(cancels + blocks);
double const mult = 1 - std::min(cancelRate, 0.5);
maxPeers = s->interestedCount * mult;
tordbg(
logtraceSwarm(
s,
"cancel rate is %.3f -- reducing the number of peers we're interested in by %.0f percent",
cancelRate,
@ -1919,7 +1923,7 @@ static void rechokeDownloads(tr_swarm* s)
double const mult = std::min(timeSinceCancel, maxHistory) / (double)maxHistory;
int const inc = maxIncrease * mult;
maxPeers = s->maxPeers + inc;
tordbg(
logtraceSwarm(
s,
"time since last cancel is %jd -- increasing the number of peers we're interested in by %d",
(intmax_t)timeSinceCancel,
@ -2255,7 +2259,7 @@ static bool shouldPeerBeClosed(tr_swarm const* s, tr_peer const* peer, int peerC
/* if it's marked for purging, close it */
if (peer->doPurge)
{
tordbg(s, "purging peer %s because its doPurge flag is set", tr_atomAddrStr(atom));
logtraceSwarm(s, "purging peer %s because its doPurge flag is set", tr_atomAddrStr(atom));
return true;
}
@ -2280,7 +2284,11 @@ static bool shouldPeerBeClosed(tr_swarm const* s, tr_peer const* peer, int peerC
if (idleTime > limit)
{
tordbg(s, "purging peer %s because it's been %d secs since we shared anything", tr_atomAddrStr(atom), idleTime);
logtraceSwarm(
s,
"purging peer %s because it's been %d secs since we shared anything",
tr_atomAddrStr(atom),
idleTime);
return true;
}
}
@ -2344,7 +2352,7 @@ static int getReconnectIntervalSecs(struct peer_atom const* atom, time_t const n
}
}
dbgmsg("reconnect interval for %s is %d seconds", tr_atomAddrStr(atom), sec);
logtrace("reconnect interval for %s is %d seconds", tr_atomAddrStr(atom), sec);
return sec;
}
@ -2378,16 +2386,16 @@ static void closePeer(tr_peer* peer)
to them fruitlessly, so mark it as another fail */
if (auto* const atom = peer->atom; atom->piece_data_time != 0)
{
tordbg(s, "resetting atom %s numFails to 0", tr_atomAddrStr(atom));
logtraceSwarm(s, "resetting atom %s numFails to 0", tr_atomAddrStr(atom));
atom->numFails = 0;
}
else
{
++atom->numFails;
tordbg(s, "incremented atom %s numFails to %d", tr_atomAddrStr(atom), int(atom->numFails));
logtraceSwarm(s, "incremented atom %s numFails to %d", tr_atomAddrStr(atom), int(atom->numFails));
}
tordbg(s, "removing bad peer %s", tr_atomAddrStr(peer->atom));
logtraceSwarm(s, "removing bad peer %s", tr_atomAddrStr(peer->atom));
removePeer(peer);
}
@ -2752,7 +2760,7 @@ static void atomPulse(evutil_socket_t /*fd*/, short /*what*/, void* vmgr)
tr_ptrArrayAppend(&s->pool, keep[i]);
}
tordbg(s, "max atom count is %d... pruned from %d to %d\n", maxAtomCount, atomCount, keepCount);
logtraceSwarm(s, "max atom count is %d... pruned from %d to %d\n", maxAtomCount, atomCount, keepCount);
/* cleanup */
tr_free(test);
@ -3006,7 +3014,7 @@ static void initiateConnection(tr_peerMgr* mgr, tr_swarm* s, struct peer_atom* a
utp = utp && (atom->flags & ADDED_F_UTP_FLAGS) != 0;
}
tordbg(s, "Starting an OUTGOING%s connection with %s", utp ? " µTP" : "", tr_atomAddrStr(atom));
logtraceSwarm(s, "Starting an OUTGOING%s connection with %s", utp ? " µTP" : "", tr_atomAddrStr(atom));
tr_peerIo* const io = tr_peerIoNewOutgoing(
mgr->session,
@ -3020,7 +3028,7 @@ static void initiateConnection(tr_peerMgr* mgr, tr_swarm* s, struct peer_atom* a
if (io == nullptr)
{
tordbg(s, "peerIo not created; marking peer %s as unreachable", tr_atomAddrStr(atom));
logtraceSwarm(s, "peerIo not created; marking peer %s as unreachable", tr_atomAddrStr(atom));
atom->flags2 |= MyflagUnreachable;
atom->numFails++;
}

192
libtransmission/peer-msgs.cc
View File

@ -374,7 +374,7 @@ public:
if (chokeChangedAt > fibrillationTime)
{
// TODO dbgmsg(msgs, "Not changing choke to %d to avoid fibrillation", peer_is_choked);
// TODO logtrace(msgs, "Not changing choke to %d to avoid fibrillation", peer_is_choked);
}
else if (peer_is_choked_ != peer_is_choked)
{
@ -548,7 +548,7 @@ private:
void set_active(tr_direction direction, bool active)
{
// TODO dbgmsg(msgs, "direction [%d] is_active [%d]", int(direction), int(is_active));
// TODO logtrace(msgs, "direction [%d] is_active [%d]", int(direction), int(is_active));
auto& val = is_active_[direction];
if (val != active)
{
@ -656,47 +656,27 @@ tr_peerMsgs* tr_peerMsgsNew(tr_torrent* torrent, peer_atom* atom, tr_peerIo* io,
***
**/
static void myDebug(char const* file, int line, tr_peerMsgsImpl const* msgs, char const* fmt, ...) TR_GNUC_PRINTF(4, 5);
static void myDebug(char const* file, int line, tr_peerMsgsImpl const* msgs, char const* fmt, ...)
static void myDebug(char const* file, int line, tr_log_level level, tr_peerMsgsImpl const* msgs, char const* fmt, ...)
{
tr_sys_file_t const fp = tr_logGetFile();
if (fp != TR_BAD_SYS_FILE)
if (!tr_logLevelIsActive(level))
{
va_list args;
char timestr[64];
char addrstr[TR_ADDRSTRLEN];
struct evbuffer* buf = evbuffer_new();
char* base = tr_sys_path_basename(file, nullptr);
evbuffer_add_printf(
buf,
"[%s] %s - %s [%s]: ",
tr_logGetTimeStr(timestr, sizeof(timestr)),
tr_torrentName(msgs->torrent),
tr_peerIoGetAddrStr(msgs->io, addrstr, sizeof(addrstr)),
msgs->client.c_str());
va_start(args, fmt);
evbuffer_add_vprintf(buf, fmt, args);
va_end(args);
evbuffer_add_printf(buf, " (%s:%d)", base, line);
auto const message = evbuffer_free_to_str(buf);
tr_sys_file_write_line(fp, message, nullptr);
tr_free(base);
return;
}
va_list args;
char addrstr[TR_ADDRSTRLEN];
auto* const buf = evbuffer_new();
evbuffer_add_printf(buf, "%s [%s]: ", tr_peerIoGetAddrStr(msgs->io, addrstr, sizeof(addrstr)), msgs->client.c_str());
va_start(args, fmt);
evbuffer_add_vprintf(buf, fmt, args);
va_end(args);
auto const message = evbuffer_free_to_str(buf);
tr_logAddMessage(file, line, level, tr_torrentName(msgs->torrent), "%s", message.c_str());
}
#define dbgmsg(msgs, ...) \
do \
{ \
if (tr_logGetDeepEnabled()) \
{ \
myDebug(__FILE__, __LINE__, msgs, __VA_ARGS__); \
} \
} while (0)
#define logdbg(msgs, ...) myDebug(__FILE__, __LINE__, TR_LOG_DEBUG, msgs, __VA_ARGS__)
#define logtrace(msgs, ...) myDebug(__FILE__, __LINE__, TR_LOG_TRACE, msgs, __VA_ARGS__)
/**
***
@ -707,13 +687,13 @@ static void pokeBatchPeriod(tr_peerMsgsImpl* msgs, int interval)
if (msgs->outMessagesBatchPeriod > interval)
{
msgs->outMessagesBatchPeriod = interval;
dbgmsg(msgs, "lowering batch interval to %d seconds", interval);
logtrace(msgs, "lowering batch interval to %d seconds", interval);
}
}
static void dbgOutMessageLen(tr_peerMsgsImpl* msgs)
{
dbgmsg(msgs, "outMessage size is now %zu", evbuffer_get_length(msgs->outMessages));
logtrace(msgs, "outMessage size is now %zu", evbuffer_get_length(msgs->outMessages));
}
static void protocolSendReject(tr_peerMsgsImpl* msgs, struct peer_request const* req)
@ -728,7 +708,7 @@ static void protocolSendReject(tr_peerMsgsImpl* msgs, struct peer_request const*
evbuffer_add_uint32(out, req->offset);
evbuffer_add_uint32(out, req->length);
dbgmsg(msgs, "rejecting %u:%u->%u...", req->index, req->offset, req->length);
logtrace(msgs, "rejecting %u:%u->%u...", req->index, req->offset, req->length);
dbgOutMessageLen(msgs);
}
@ -742,7 +722,7 @@ static void protocolSendRequest(tr_peerMsgsImpl* msgs, struct peer_request const
evbuffer_add_uint32(out, req.offset);
evbuffer_add_uint32(out, req.length);
dbgmsg(msgs, "requesting %u:%u->%u...", req.index, req.offset, req.length);
logtrace(msgs, "requesting %u:%u->%u...", req.index, req.offset, req.length);
dbgOutMessageLen(msgs);
pokeBatchPeriod(msgs, ImmediatePriorityIntervalSecs);
}
@ -757,7 +737,7 @@ static void protocolSendCancel(tr_peerMsgsImpl* msgs, peer_request const& req)
evbuffer_add_uint32(out, req.offset);
evbuffer_add_uint32(out, req.length);
dbgmsg(msgs, "cancelling %u:%u->%u...", req.index, req.offset, req.length);
logtrace(msgs, "cancelling %u:%u->%u...", req.index, req.offset, req.length);
dbgOutMessageLen(msgs);
pokeBatchPeriod(msgs, ImmediatePriorityIntervalSecs);
}
@ -766,7 +746,7 @@ static void protocolSendPort(tr_peerMsgsImpl* msgs, uint16_t port)
{
struct evbuffer* out = msgs->outMessages;
dbgmsg(msgs, "sending Port %u", port);
logtrace(msgs, "sending Port %u", port);
evbuffer_add_uint32(out, 3);
evbuffer_add_uint8(out, BtPeerMsgs::Port);
evbuffer_add_uint16(out, port);
@ -780,7 +760,7 @@ static void protocolSendHave(tr_peerMsgsImpl* msgs, tr_piece_index_t index)
evbuffer_add_uint8(out, BtPeerMsgs::Have);
evbuffer_add_uint32(out, index);
dbgmsg(msgs, "sending Have %u", index);
logtrace(msgs, "sending Have %u", index);
dbgOutMessageLen(msgs);
pokeBatchPeriod(msgs, LowPriorityIntervalSecs);
}
@ -798,7 +778,7 @@ static void protocolSendAllowedFast(tr_peerMsgs* msgs, uint32_t pieceIndex)
evbuffer_add_uint8(io, out, BtPeerMsgs::FextAllowedFast);
evbuffer_add_uint32(io, out, pieceIndex);
dbgmsg(msgs, "sending Allowed Fast %u...", pieceIndex);
logtrace(msgs, "sending Allowed Fast %u...", pieceIndex);
dbgOutMessageLen(msgs);
}
@ -811,7 +791,7 @@ static void protocolSendChoke(tr_peerMsgsImpl* msgs, bool choke)
evbuffer_add_uint32(out, sizeof(uint8_t));
evbuffer_add_uint8(out, choke ? BtPeerMsgs::Choke : BtPeerMsgs::Unchoke);
dbgmsg(msgs, "sending %s...", choke ? "Choke" : "Unchoke");
logtrace(msgs, "sending %s...", choke ? "Choke" : "Unchoke");
dbgOutMessageLen(msgs);
pokeBatchPeriod(msgs, ImmediatePriorityIntervalSecs);
}
@ -825,7 +805,7 @@ static void protocolSendHaveAll(tr_peerMsgsImpl* msgs)
evbuffer_add_uint32(out, sizeof(uint8_t));
evbuffer_add_uint8(out, BtPeerMsgs::FextHaveAll);
dbgmsg(msgs, "sending HAVE_ALL...");
logtrace(msgs, "sending HAVE_ALL...");
dbgOutMessageLen(msgs);
pokeBatchPeriod(msgs, ImmediatePriorityIntervalSecs);
}
@ -839,7 +819,7 @@ static void protocolSendHaveNone(tr_peerMsgsImpl* msgs)
evbuffer_add_uint32(out, sizeof(uint8_t));
evbuffer_add_uint8(out, BtPeerMsgs::FextHaveNone);
dbgmsg(msgs, "sending HAVE_NONE...");
logtrace(msgs, "sending HAVE_NONE...");
dbgOutMessageLen(msgs);
pokeBatchPeriod(msgs, ImmediatePriorityIntervalSecs);
}
@ -938,7 +918,7 @@ static void sendInterest(tr_peerMsgsImpl* msgs, bool b)
struct evbuffer* out = msgs->outMessages;
dbgmsg(msgs, "Sending %s", b ? "Interested" : "Not Interested");
logtrace(msgs, "Sending %s", b ? "Interested" : "Not Interested");
evbuffer_add_uint32(out, sizeof(uint8_t));
evbuffer_add_uint8(out, b ? BtPeerMsgs::Interested : BtPeerMsgs::NotInterested);
@ -1024,7 +1004,7 @@ static void sendLtepHandshake(tr_peerMsgsImpl* msgs)
version_quark = tr_quark_new(TR_NAME " " USERAGENT_PREFIX);
}
dbgmsg(msgs, "sending an ltep handshake");
logtrace(msgs, "sending an ltep handshake");
msgs->clientSentLtepHandshake = true;
/* decide if we want to advertise metadata xfer support (BEP 9) */
@ -1128,7 +1108,7 @@ static void parseLtepHandshake(tr_peerMsgsImpl* msgs, uint32_t len, struct evbuf
auto val = tr_variant{};
if (!tr_variantFromBuf(&val, TR_VARIANT_PARSE_BENC | TR_VARIANT_PARSE_INPLACE, { tmp, len }) || !tr_variantIsDict(&val))
{
dbgmsg(msgs, "GET extended-handshake, couldn't get dictionary");
logtrace(msgs, "GET extended-handshake, couldn't get dictionary");
tr_free(tmp);
return;
}
@ -1136,11 +1116,11 @@ static void parseLtepHandshake(tr_peerMsgsImpl* msgs, uint32_t len, struct evbuf
/* arbitrary limit, should be more than enough */
if (len <= 4096)
{
dbgmsg(msgs, "here is the handshake: [%*.*s]", TR_ARG_TUPLE(int(len), int(len), tmp));
logtrace(msgs, "here is the handshake: [%*.*s]", TR_ARG_TUPLE(int(len), int(len), tmp));
}
else
{
dbgmsg(msgs, "handshake length is too big (%" PRIu32 "), printing skipped", len);
logtrace(msgs, "handshake length is too big (%" PRIu32 "), printing skipped", len);
}
/* does the peer prefer encrypted connections? */
@ -1166,14 +1146,14 @@ static void parseLtepHandshake(tr_peerMsgsImpl* msgs, uint32_t len, struct evbuf
{
msgs->peerSupportsPex = i != 0;
msgs->ut_pex_id = (uint8_t)i;
dbgmsg(msgs, "msgs->ut_pex is %d", int(msgs->ut_pex_id));
logtrace(msgs, "msgs->ut_pex is %d", int(msgs->ut_pex_id));
}
if (tr_variantDictFindInt(sub, TR_KEY_ut_metadata, &i))
{
msgs->peerSupportsMetadataXfer = i != 0;
msgs->ut_metadata_id = (uint8_t)i;
dbgmsg(msgs, "msgs->ut_metadata_id is %d", int(msgs->ut_metadata_id));
logtrace(msgs, "msgs->ut_metadata_id is %d", int(msgs->ut_metadata_id));
}
if (tr_variantDictFindInt(sub, TR_KEY_ut_holepunch, &i))
@ -1201,7 +1181,7 @@ static void parseLtepHandshake(tr_peerMsgsImpl* msgs, uint32_t len, struct evbuf
{
pex.port = htons((uint16_t)i);
msgs->publishClientGotPort(pex.port);
dbgmsg(msgs, "peer's port is now %d", int(i));
logtrace(msgs, "peer's port is now %d", int(i));
}
uint8_t const* addr = nullptr;
@ -1250,7 +1230,7 @@ static void parseUtMetadata(tr_peerMsgsImpl* msgs, uint32_t msglen, struct evbuf
tr_variantFree(&dict);
}
dbgmsg(msgs, "got ut_metadata msg: type %d, piece %d, total_size %d", int(msg_type), int(piece), int(total_size));
logtrace(msgs, "got ut_metadata msg: type %d, piece %d, total_size %d", int(msg_type), int(piece), int(total_size));
if (msg_type == MetadataMsgType::Reject)
{
@ -1362,7 +1342,7 @@ static void parseLtep(tr_peerMsgsImpl* msgs, uint32_t msglen, struct evbuffer* i
if (ltep_msgid == LtepMessages::Handshake)
{
dbgmsg(msgs, "got ltep handshake");
logtrace(msgs, "got ltep handshake");
parseLtepHandshake(msgs, msglen, inbuf);
if (tr_peerIoSupportsLTEP(msgs->io))
@ -1373,19 +1353,19 @@ static void parseLtep(tr_peerMsgsImpl* msgs, uint32_t msglen, struct evbuffer* i
}
else if (ltep_msgid == UT_PEX_ID)
{
dbgmsg(msgs, "got ut pex");
logtrace(msgs, "got ut pex");
msgs->peerSupportsPex = true;
parseUtPex(msgs, msglen, inbuf);
}
else if (ltep_msgid == UT_METADATA_ID)
{
dbgmsg(msgs, "got ut metadata");
logtrace(msgs, "got ut metadata");
msgs->peerSupportsMetadataXfer = true;
parseUtMetadata(msgs, msglen, inbuf);
}
else
{
dbgmsg(msgs, "skipping unknown ltep message (%d)", int(ltep_msgid));
logtrace(msgs, "skipping unknown ltep message (%d)", int(ltep_msgid));
evbuffer_drain(inbuf, msglen);
}
}
@ -1401,7 +1381,7 @@ static ReadState readBtLength(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, siz
tr_peerIoReadUint32(msgs->io, inbuf, &len);
if (len == 0) /* peer sent us a keepalive message */
{
dbgmsg(msgs, "got KeepAlive");
logtrace(msgs, "got KeepAlive");
}
else
{
@ -1424,7 +1404,7 @@ static ReadState readBtId(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, size_t
auto id = uint8_t{};
tr_peerIoReadUint8(msgs->io, inbuf, &id);
msgs->incoming.id = id;
dbgmsg(msgs, "msgs->incoming.id is now %d; msgs->incoming.length is %zu", id, (size_t)msgs->incoming.length);
logtrace(msgs, "msgs->incoming.id is now %d; msgs->incoming.length is %zu", id, (size_t)msgs->incoming.length);
if (id == BtPeerMsgs::Piece)
{
@ -1482,19 +1462,19 @@ static void peerMadeRequest(tr_peerMsgsImpl* msgs, struct peer_request const* re
if (!reqIsValid)
{
dbgmsg(msgs, "rejecting an invalid request.");
logtrace(msgs, "rejecting an invalid request.");
}
else if (!clientHasPiece)
{
dbgmsg(msgs, "rejecting request for a piece we don't have.");
logtrace(msgs, "rejecting request for a piece we don't have.");
}
else if (peerIsChoked)
{
dbgmsg(msgs, "rejecting request from choked peer");
logtrace(msgs, "rejecting request from choked peer");
}
else if (msgs->pendingReqsToClient + 1 >= ReqQ)
{
dbgmsg(msgs, "rejecting request ... reqq is full");
logtrace(msgs, "rejecting request ... reqq is full");
}
else
{
@ -1569,7 +1549,7 @@ static ReadState readBtPiece(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, size
{
TR_ASSERT(evbuffer_get_length(inbuf) >= inlen);
dbgmsg(msgs, "In readBtPiece");
logtrace(msgs, "In readBtPiece");
struct peer_request* req = &msgs->incoming.blockReq;
@ -1583,7 +1563,7 @@ static ReadState readBtPiece(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, size
tr_peerIoReadUint32(msgs->io, inbuf, &req->index);
tr_peerIoReadUint32(msgs->io, inbuf, &req->offset);
req->length = msgs->incoming.length - 9;
dbgmsg(msgs, "got incoming block header %u:%u->%u", req->index, req->offset, req->length);
logtrace(msgs, "got incoming block header %u:%u->%u", req->index, req->offset, req->length);
return READ_NOW;
}
@ -1602,7 +1582,7 @@ static ReadState readBtPiece(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, size
msgs->publishClientGotPieceData(n);
*setme_piece_bytes_read += n;
dbgmsg(
logtrace(
msgs,
"got %zu bytes for block %u:%u->%u ... %d remain",
n,
@ -1641,7 +1621,7 @@ static ReadState readBtMessage(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, si
--msglen; /* id length */
dbgmsg(msgs, "got BT id %d, len %d, buffer size is %zu", int(id), int(msglen), inlen);
logtrace(msgs, "got BT id %d, len %d, buffer size is %zu", int(id), int(msglen), inlen);
if (inlen < msglen)
{
@ -1650,7 +1630,7 @@ static ReadState readBtMessage(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, si
if (!messageLengthIsCorrect(msgs, id, msglen + 1))
{
dbgmsg(msgs, "bad packet - BT message #%d with a length of %d", int(id), int(msglen));
logdbg(msgs, "bad packet - BT message #%d with a length of %d", int(id), int(msglen));
msgs->publishError(EMSGSIZE);
return READ_ERR;
}
@ -1658,7 +1638,7 @@ static ReadState readBtMessage(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, si
switch (id)
{
case BtPeerMsgs::Choke:
dbgmsg(msgs, "got Choke");
logtrace(msgs, "got Choke");
msgs->client_is_choked_ = true;
if (!fext)
@ -1670,27 +1650,27 @@ static ReadState readBtMessage(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, si
break;
case BtPeerMsgs::Unchoke:
dbgmsg(msgs, "got Unchoke");
logtrace(msgs, "got Unchoke");
msgs->client_is_choked_ = false;
msgs->update_active(TR_PEER_TO_CLIENT);
updateDesiredRequestCount(msgs);
break;
case BtPeerMsgs::Interested:
dbgmsg(msgs, "got Interested");
logtrace(msgs, "got Interested");
msgs->peer_is_interested_ = true;
msgs->update_active(TR_CLIENT_TO_PEER);
break;
case BtPeerMsgs::NotInterested:
dbgmsg(msgs, "got Not Interested");
logtrace(msgs, "got Not Interested");
msgs->peer_is_interested_ = false;
msgs->update_active(TR_CLIENT_TO_PEER);
break;
case BtPeerMsgs::Have:
tr_peerIoReadUint32(msgs->io, inbuf, &ui32);
dbgmsg(msgs, "got Have: %u", ui32);
logtrace(msgs, "got Have: %u", ui32);
if (msgs->torrent->hasMetadata() && ui32 >= msgs->torrent->pieceCount())
{
@ -1711,7 +1691,7 @@ static ReadState readBtMessage(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, si
case BtPeerMsgs::Bitfield:
{
auto* const tmp = tr_new(uint8_t, msglen);
dbgmsg(msgs, "got a bitfield");
logtrace(msgs, "got a bitfield");
tr_peerIoReadBytes(msgs->io, inbuf, tmp, msglen);
msgs->have.setRaw(tmp, msglen);
msgs->publishClientGotBitfield(&msgs->have);
@ -1726,7 +1706,7 @@ static ReadState readBtMessage(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, si
tr_peerIoReadUint32(msgs->io, inbuf, &r.index);
tr_peerIoReadUint32(msgs->io, inbuf, &r.offset);
tr_peerIoReadUint32(msgs->io, inbuf, &r.length);
dbgmsg(msgs, "got Request: %u:%u->%u", r.index, r.offset, r.length);
logtrace(msgs, "got Request: %u:%u->%u", r.index, r.offset, r.length);
peerMadeRequest(msgs, &r);
break;
}
@ -1738,7 +1718,7 @@ static ReadState readBtMessage(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, si
tr_peerIoReadUint32(msgs->io, inbuf, &r.offset);
tr_peerIoReadUint32(msgs->io, inbuf, &r.length);
msgs->cancelsSentToClient.add(tr_time(), 1);
dbgmsg(msgs, "got a Cancel %u:%u->%u", r.index, r.offset, r.length);
logtrace(msgs, "got a Cancel %u:%u->%u", r.index, r.offset, r.length);
for (int i = 0; i < msgs->pendingReqsToClient; ++i)
{
@ -1765,7 +1745,7 @@ static ReadState readBtMessage(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, si
break;
case BtPeerMsgs::Port:
dbgmsg(msgs, "Got a BtPeerMsgs::Port");
logtrace(msgs, "Got a BtPeerMsgs::Port");
tr_peerIoReadUint16(msgs->io, inbuf, &msgs->dht_port);
if (msgs->dht_port > 0)
@ -1776,7 +1756,7 @@ static ReadState readBtMessage(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, si
break;
case BtPeerMsgs::FextSuggest:
dbgmsg(msgs, "Got a BtPeerMsgs::FextSuggest");
logtrace(msgs, "Got a BtPeerMsgs::FextSuggest");
tr_peerIoReadUint32(msgs->io, inbuf, &ui32);
if (fext)
@ -1792,7 +1772,7 @@ static ReadState readBtMessage(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, si
break;
case BtPeerMsgs::FextAllowedFast:
dbgmsg(msgs, "Got a BtPeerMsgs::FextAllowedFast");
logtrace(msgs, "Got a BtPeerMsgs::FextAllowedFast");
tr_peerIoReadUint32(msgs->io, inbuf, &ui32);
if (fext)
@ -1808,7 +1788,7 @@ static ReadState readBtMessage(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, si
break;
case BtPeerMsgs::FextHaveAll:
dbgmsg(msgs, "Got a BtPeerMsgs::FextHaveAll");
logtrace(msgs, "Got a BtPeerMsgs::FextHaveAll");
if (fext)
{
@ -1825,7 +1805,7 @@ static ReadState readBtMessage(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, si
break;
case BtPeerMsgs::FextHaveNone:
dbgmsg(msgs, "Got a BtPeerMsgs::FextHaveNone");
logtrace(msgs, "Got a BtPeerMsgs::FextHaveNone");
if (fext)
{
@ -1844,7 +1824,7 @@ static ReadState readBtMessage(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, si
case BtPeerMsgs::FextReject:
{
struct peer_request r;
dbgmsg(msgs, "Got a BtPeerMsgs::FextReject");
logtrace(msgs, "Got a BtPeerMsgs::FextReject");
tr_peerIoReadUint32(msgs->io, inbuf, &r.index);
tr_peerIoReadUint32(msgs->io, inbuf, &r.offset);
tr_peerIoReadUint32(msgs->io, inbuf, &r.length);
@ -1863,12 +1843,12 @@ static ReadState readBtMessage(tr_peerMsgsImpl* msgs, struct evbuffer* inbuf, si
}
case BtPeerMsgs::Ltep:
dbgmsg(msgs, "Got a BtPeerMsgs::Ltep");
logtrace(msgs, "Got a BtPeerMsgs::Ltep");
parseLtep(msgs, msglen, inbuf);
break;
default:
dbgmsg(msgs, "peer sent us an UNKNOWN: %d", int(id));
logtrace(msgs, "peer sent us an UNKNOWN: %d", int(id));
tr_peerIoDrain(msgs->io, inbuf, msglen);
break;
}
@ -1891,27 +1871,27 @@ static int clientGotBlock(tr_peerMsgsImpl* msgs, struct evbuffer* data, struct p
if (!requestIsValid(msgs, req))
{
dbgmsg(msgs, "dropping invalid block %u:%u->%u", req->index, req->offset, req->length);
logdbg(msgs, "dropping invalid block %u:%u->%u", req->index, req->offset, req->length);
return EBADMSG;
}
if (req->length != msgs->torrent->blockSize(block))
{
dbgmsg(msgs, "wrong block size -- expected %u, got %d", msgs->torrent->blockSize(block), req->length);
logdbg(msgs, "wrong block size -- expected %u, got %d", msgs->torrent->blockSize(block), req->length);
return EMSGSIZE;
}
dbgmsg(msgs, "got block %u:%u->%u", req->index, req->offset, req->length);
logtrace(msgs, "got block %u:%u->%u", req->index, req->offset, req->length);
if (!tr_peerMgrDidPeerRequest(msgs->torrent, msgs, block))
{
dbgmsg(msgs, "we didn't ask for this message...");
logdbg(msgs, "we didn't ask for this message...");
return 0;
}
if (msgs->torrent->hasPiece(req->index))
{
dbgmsg(msgs, "we did ask for this message, but the piece is already complete...");
logtrace(msgs, "we did ask for this message, but the piece is already complete...");
return 0;
}
@ -1952,7 +1932,7 @@ static ReadState canRead(tr_peerIo* io, void* vmsgs, size_t* piece)
struct evbuffer* in = tr_peerIoGetReadBuffer(io);
size_t const inlen = evbuffer_get_length(in);
dbgmsg(msgs, "canRead: inlen is %zu, msgs->state is %d", inlen, int(msgs->state));
logtrace(msgs, "canRead: inlen is %zu, msgs->state is %d", inlen, int(msgs->state));
auto ret = ReadState{};
if (inlen == 0)
@ -1989,7 +1969,7 @@ static ReadState canRead(tr_peerIo* io, void* vmsgs, size_t* piece)
}
}
dbgmsg(msgs, "canRead: ret is %d", int(ret));
logtrace(msgs, "canRead: ret is %d", int(ret));
return ret;
}
@ -2050,7 +2030,7 @@ static void updateMetadataRequests(tr_peerMsgsImpl* msgs, time_t now)
tr_variantDictAddInt(&tmp, TR_KEY_piece, piece);
auto* const payload = tr_variantToBuf(&tmp, TR_VARIANT_FMT_BENC);
dbgmsg(msgs, "requesting metadata piece #%d", piece);
logtrace(msgs, "requesting metadata piece #%d", piece);
/* write it out as a LTEP message to our outMessages buffer */
evbuffer_add_uint32(out, 2 * sizeof(uint8_t) + evbuffer_get_length(payload));
@ -2112,14 +2092,14 @@ static size_t fillOutputBuffer(tr_peerMsgsImpl* msgs, time_t now)
if (haveMessages && msgs->outMessagesBatchedAt == 0) /* fresh batch */
{
dbgmsg(msgs, "started an outMessages batch (length is %zu)", evbuffer_get_length(msgs->outMessages));
logtrace(msgs, "started an outMessages batch (length is %zu)", evbuffer_get_length(msgs->outMessages));
msgs->outMessagesBatchedAt = now;
}
else if (haveMessages && now - msgs->outMessagesBatchedAt >= msgs->outMessagesBatchPeriod)
{
size_t const len = evbuffer_get_length(msgs->outMessages);
/* flush the protocol messages */
dbgmsg(msgs, "flushing outMessages... to %p (length is %zu)", (void*)msgs->io, len);
logtrace(msgs, "flushing outMessages... to %p (length is %zu)", (void*)msgs->io, len);
tr_peerIoWriteBuf(msgs->io, msgs->outMessages, false);
msgs->clientSentAnythingAt = now;
msgs->outMessagesBatchedAt = 0;
@ -2245,7 +2225,7 @@ static size_t fillOutputBuffer(tr_peerMsgsImpl* msgs, time_t now)
else
{
size_t const n = evbuffer_get_length(out);
dbgmsg(msgs, "sending block %u:%u->%u", req.index, req.offset, req.length);
logtrace(msgs, "sending block %u:%u->%u", req.index, req.offset, req.length);
TR_ASSERT(n == msglen);
tr_peerIoWriteBuf(msgs->io, out, true);
bytesWritten += n;
@ -2278,7 +2258,7 @@ static size_t fillOutputBuffer(tr_peerMsgsImpl* msgs, time_t now)
if (msgs != nullptr && msgs->clientSentAnythingAt != 0 && now - msgs->clientSentAnythingAt > KeepaliveIntervalSecs)
{
dbgmsg(msgs, "sending a keepalive message");
logtrace(msgs, "sending a keepalive message");
evbuffer_add_uint32(msgs->outMessages, 0);
pokeBatchPeriod(msgs, ImmediatePriorityIntervalSecs);
}
@ -2313,12 +2293,12 @@ static void gotError(tr_peerIo* /*io*/, short what, void* vmsgs)
if ((what & BEV_EVENT_TIMEOUT) != 0)
{
dbgmsg(msgs, "libevent got a timeout, what=%hd", what);
logdbg(msgs, "libevent got a timeout, what=%hd", what);
}
if ((what & (BEV_EVENT_EOF | BEV_EVENT_ERROR)) != 0)
{
dbgmsg(msgs, "libevent got an error! what=%hd, errno=%d (%s)", what, errno, tr_strerror(errno));
logdbg(msgs, "libevent got an error! what=%hd, errno=%d (%s)", what, errno, tr_strerror(errno));
}
msgs->publishError(ENOTCONN);
@ -2334,7 +2314,7 @@ static void sendBitfield(tr_peerMsgsImpl* msgs)
evbuffer_add_uint32(out, sizeof(uint8_t) + bytes.size());
evbuffer_add_uint8(out, BtPeerMsgs::Bitfield);
evbuffer_add(out, bytes.data(), std::size(bytes));
dbgmsg(msgs, "sending bitfield... outMessage size is now %zu", evbuffer_get_length(out));
logtrace(msgs, "sending bitfield... outMessage size is now %zu", evbuffer_get_length(out));
pokeBatchPeriod(msgs, ImmediatePriorityIntervalSecs);
}
@ -2521,7 +2501,7 @@ static void sendPex(tr_peerMsgsImpl* msgs)
pexAddedCb,
pexElementCb,
&diffs6);
dbgmsg(
logtrace(
msgs,
"pex: old peer count %d+%d, new peer count %d+%d, added %d+%d, removed %d+%d",
msgs->pexCount,
@ -2661,7 +2641,7 @@ static void sendPex(tr_peerMsgsImpl* msgs)
evbuffer_add_uint8(out, msgs->ut_pex_id);
evbuffer_add_buffer(out, payload);
pokeBatchPeriod(msgs, HighPriorityIntervalSecs);
dbgmsg(msgs, "sending a pex message; outMessage size is now %zu", evbuffer_get_length(out));
logtrace(msgs, "sending a pex message; outMessage size is now %zu", evbuffer_get_length(out));
dbgOutMessageLen(msgs);
evbuffer_free(payload);

29
libtransmission/port-forwarding.cc
View File

@ -20,10 +20,8 @@
#include "upnp.h"
#include "utils.h"
static char const* getKey()
{
return _("Port Forwarding");
}
#define loginfo(...) tr_logAddNamed(TR_LOG_INFO, "port-forwarding", __VA_ARGS__)
#define logtrace(...) tr_logAddNamed(TR_LOG_TRACE, "port-forwarding", __VA_ARGS__)
struct tr_shared
{
@ -68,7 +66,8 @@ static char const* getNatStateStr(int state)
static void natPulse(tr_shared* s, bool do_check)
{
tr_port const private_peer_port = s->session->private_peer_port;
auto* session = s->session;
tr_port const private_peer_port = session->private_peer_port;
bool const is_enabled = s->isEnabled && !s->isShuttingDown;
if (s->natpmp == nullptr)
@ -89,13 +88,9 @@ static void natPulse(tr_shared* s, bool do_check)
if (s->natpmpStatus == TR_PORT_MAPPED)
{
s->session->public_peer_port = public_peer_port;
s->session->private_peer_port = received_private_port;
tr_logAddNamedInfo(
getKey(),
"public peer port %d (private %d) ",
s->session->public_peer_port,
s->session->private_peer_port);
session->public_peer_port = public_peer_port;
session->private_peer_port = received_private_port;
loginfo("public peer port %d (private %d) ", session->public_peer_port, session->private_peer_port);
}
s->upnpStatus = tr_upnpPulse(
@ -103,17 +98,13 @@ static void natPulse(tr_shared* s, bool do_check)
private_peer_port,
is_enabled,
do_check,
tr_address_to_string(&s->session->bind_ipv4->addr));
tr_address_to_string(&session->bind_ipv4->addr));
auto const new_status = tr_sharedTraversalStatus(s);
if (new_status != old_status)
{
tr_logAddNamedInfo(
getKey(),
_("State changed from \"%1$s\" to \"%2$s\""),
getNatStateStr(old_status),
getNatStateStr(new_status));
loginfo(_("State changed from \"%1$s\" to \"%2$s\""), getNatStateStr(old_status), getNatStateStr(new_status));
}
}
@ -202,7 +193,7 @@ static void stop_timer(tr_shared* s)
static void stop_forwarding(tr_shared* s)
{
tr_logAddNamedInfo(getKey(), "%s", _("Stopped"));
logtrace("stopped");
natPulse(s, false);
tr_natpmpClose(s->natpmp);

56
libtransmission/rpc-server.cc
View File

@ -56,8 +56,6 @@ using namespace std::literals;
* http://www.webappsec.org/lists/websecurity/archive/2008-04/msg00037.html */
#define REQUIRE_SESSION_ID
static char constexpr MyName[] = "RPC Server";
static auto constexpr TrUnixSocketPrefix = "unix:"sv;
/* The maximum size of a unix socket path is defined per-platform based on sockaddr_un.sun_path.
@ -96,7 +94,10 @@ struct tr_rpc_address
#define MY_REALM "Transmission"
#define dbgmsg(...) tr_logAddDeepNamed(MyName, __VA_ARGS__)
#define logerr(...) tr_logAddNamed(TR_LOG_ERROR, "rpc", __VA_ARGS__)
#define logwarn(...) tr_logAddNamed(TR_LOG_WARN, "rpc", __VA_ARGS__)
#define loginfo(...) tr_logAddNamed(TR_LOG_INFO, "rpc", __VA_ARGS__)
#define logdbg(...) tr_logAddNamed(TR_LOG_DEBUG, "rpc", __VA_ARGS__)
static int constexpr DeflateLevel = 6; // medium / default
@ -633,8 +634,7 @@ static bool tr_rpc_address_from_string(tr_rpc_address& dst, std::string_view src
{
if (std::size(src) >= TrUnixAddrStrLen)
{
tr_logAddNamedError(
MyName,
logerr(
_("Unix socket path must be fewer than %zu characters (including \"%" TR_PRIsv "\" prefix)"),
TrUnixAddrStrLen - 1,
TR_PRIsv_ARG(TrUnixSocketPrefix));
@ -668,10 +668,9 @@ static bool bindUnixSocket(
[[maybe_unused]] int socket_mode)
{
#ifdef _WIN32
tr_logAddNamedError(
MyName,
logerr(
_("Unix sockets are not supported on Windows. Please change \"%s\" in your configuration file."),
tr_quark_get_string(TR_KEY_rpc_bind_address, nullptr));
tr_quark_get_string(TR_KEY_rpc_bind_address));
return false;
#else
struct sockaddr_un addr;
@ -696,7 +695,7 @@ static bool bindUnixSocket(
if (chmod(addr.sun_path, (mode_t)socket_mode) != 0)
{
tr_logAddNamedError(MyName, _("Could not set RPC socket mode to %o, defaulting to 755"), socket_mode);
logwarn(_("Could not set RPC socket mode to %o, defaulting to 755"), socket_mode);
}
return evhttp_bind_listener(httpd, lev) != nullptr;
@ -767,22 +766,18 @@ static void startServer(tr_rpc_server* server)
{
int const retry_delay = rpc_server_start_retry(server);
tr_logAddNamedDbg(MyName, "Unable to bind to %s, retrying in %d seconds", addr_port_str.c_str(), retry_delay);
logdbg("Unable to bind to %s, retrying in %d seconds", addr_port_str.c_str(), retry_delay);
return;
}
tr_logAddNamedError(
MyName,
"Unable to bind to %s after %d attempts, giving up",
addr_port_str.c_str(),
ServerStartRetryCount);
logerr("Unable to bind to %s after %d attempts, giving up", addr_port_str.c_str(), ServerStartRetryCount);
}
else
{
evhttp_set_gencb(httpd, handle_request, server);
server->httpd = httpd;
tr_logAddNamedDbg(MyName, "Started listening on %s", addr_port_str.c_str());
loginfo("Started listening on %s", addr_port_str.c_str());
}
rpc_server_start_retry_cancel(server);
@ -811,7 +806,7 @@ static void stopServer(tr_rpc_server* server)
unlink(address + std::size(TrUnixSocketPrefix));
}
tr_logAddNamedDbg(MyName, "Stopped listening on %s", tr_rpc_address_with_port(server).c_str());
loginfo("Stopped listening on %s", tr_rpc_address_with_port(server).c_str());
}
static void onEnabledChanged(tr_rpc_server* const server)
@ -870,7 +865,7 @@ tr_port tr_rpcGetPort(tr_rpc_server const* server)
void tr_rpcSetUrl(tr_rpc_server* server, std::string_view url)
{
server->url = url;
dbgmsg("setting our URL to [%s]", server->url.c_str());
logdbg("setting our URL to [%s]", server->url.c_str());
}
std::string const& tr_rpcGetUrl(tr_rpc_server const* server)
@ -891,14 +886,13 @@ static auto parseWhitelist(std::string_view whitelist)
if (token.find_first_of("+-"sv) != std::string_view::npos)
{
tr_logAddNamedInfo(
MyName,
logwarn(
"Adding address to whitelist: %" TR_PRIsv " (And it has a '+' or '-'! Are you using an old ACL by mistake?)",
TR_PRIsv_ARG(token));
}
else
{
tr_logAddNamedInfo(MyName, "Adding address to whitelist: %" TR_PRIsv, TR_PRIsv_ARG(token));
loginfo("Adding address to whitelist: %" TR_PRIsv, TR_PRIsv_ARG(token));
}
}
@ -953,7 +947,7 @@ static void tr_rpcSetRPCSocketMode(tr_rpc_server* server, int socket_mode)
void tr_rpcSetUsername(tr_rpc_server* server, std::string_view username)
{
server->username = username;
dbgmsg("setting our Username to [%s]", server->username.c_str());
logdbg("setting our Username to [%s]", server->username.c_str());
}
std::string const& tr_rpcGetUsername(tr_rpc_server const* server)
@ -970,7 +964,7 @@ void tr_rpcSetPassword(tr_rpc_server* server, std::string_view password)
{
server->salted_password = isSalted(password) ? password : tr_ssha1(password);
dbgmsg("setting our salted password to [%s]", server->salted_password.c_str());
logdbg("setting our salted password to [%s]", server->salted_password.c_str());
}
std::string const& tr_rpcGetPassword(tr_rpc_server const* server)
@ -981,7 +975,7 @@ std::string const& tr_rpcGetPassword(tr_rpc_server const* server)
void tr_rpcSetPasswordEnabled(tr_rpc_server* server, bool isEnabled)
{
server->isPasswordEnabled = isEnabled;
dbgmsg("setting 'password enabled' to %d", (int)isEnabled);
logdbg("setting 'password enabled' to %d", (int)isEnabled);
}
bool tr_rpcIsPasswordEnabled(tr_rpc_server const* server)
@ -1025,8 +1019,7 @@ void tr_rpcSetAntiBruteForceThreshold(tr_rpc_server* server, int badRequests)
static void missing_settings_key(tr_quark const q)
{
char const* str = tr_quark_get_string(q);
tr_logAddNamedError(MyName, _("Couldn't find settings key \"%s\""), str);
logdbg(_("Couldn't find settings key \"%s\""), tr_quark_get_string(q));
}
tr_rpc_server::tr_rpc_server(tr_session* session_in, tr_variant* settings)
@ -1194,8 +1187,7 @@ tr_rpc_server::tr_rpc_server(tr_session* session_in, tr_variant* settings)
}
else if (!tr_rpc_address_from_string(*bindAddress, sv))
{
tr_logAddNamedError(
MyName,
logwarn(
_("%" TR_PRIsv
" is not an IPv4 address, an IPv6 address, or a unix socket path. RPC listeners must be one of the previously mentioned types. Falling back to 0.0.0.0."),
TR_PRIsv_ARG(sv));
@ -1211,24 +1203,24 @@ tr_rpc_server::tr_rpc_server(tr_session* session_in, tr_variant* settings)
if (this->isEnabled)
{
auto const rpc_uri = tr_rpc_address_with_port(this) + this->url;
tr_logAddNamedInfo(MyName, _("Serving RPC and Web requests on %s"), rpc_uri.c_str());
loginfo(_("Serving RPC and Web requests on %s"), rpc_uri.c_str());
tr_runInEventThread(session, startServer, this);
if (this->isWhitelistEnabled)
{
tr_logAddNamedInfo(MyName, "%s", _("Whitelist enabled"));
loginfo("%s", _("Whitelist enabled"));
}
if (this->isPasswordEnabled)
{
tr_logAddNamedInfo(MyName, "%s", _("Password required"));
loginfo("%s", _("Password required"));
}
}
char const* webClientDir = tr_getWebClientDir(this->session);
if (!tr_str_is_empty(webClientDir))
{
tr_logAddNamedInfo(MyName, _("Serving RPC and Web requests from directory '%s'"), webClientDir);
loginfo(_("Serving RPC and Web requests from directory '%s'"), webClientDir);
}
}

10
libtransmission/rpcimpl.cc
View File

@ -46,11 +46,7 @@ static auto constexpr RecentlyActiveSeconds = time_t{ 60 };
using namespace std::literals;
#if 0
#define dbgmsg(fmt, ...) fprintf(stderr, "%s:%d " fmt "\n", __FILE__, __LINE__, __VA_ARGS__)
#else
#define dbgmsg(...) tr_logAddDeepNamed("RPC", __VA_ARGS__)
#endif
#define logtrace(...) tr_logAddNamed(TR_LOG_TRACE, "rpc", __VA_ARGS__)
enum class TrFormat
{
@ -1518,7 +1514,7 @@ static void onMetadataFetched(tr_web::FetchResponse const& web_response)
auto const& [status, body, did_connect, did_timeout, user_data] = web_response;
auto* data = static_cast<struct add_torrent_idle_data*>(user_data);
dbgmsg(
logtrace(
"torrentAdd: HTTP response code was %ld (%s); response length was %zu bytes",
status,
tr_webGetResponseStr(status),
@ -1660,7 +1656,7 @@ static char const* torrentAdd(tr_session* session, tr_variant* args_in, tr_varia
tr_ctorSetLabels(ctor, std::move(labels));
}
dbgmsg("torrentAdd: filename is \"%" TR_PRIsv "\"", TR_PRIsv_ARG(filename));
logtrace("torrentAdd: filename is \"%" TR_PRIsv "\"", TR_PRIsv_ARG(filename));
if (isCurlURL(filename))
{

35
libtransmission/session.cc
View File

@ -75,7 +75,8 @@ static auto constexpr DefaultPrefetchEnabled = bool{ true };
#endif
static auto constexpr SaveIntervalSecs = int{ 360 };
#define dbgmsg(...) tr_logAddDeepNamed(nullptr, __VA_ARGS__)
#define logdbg(...) tr_logAddNamed(TR_LOG_DEBUG, nullptr, __VA_ARGS__)
#define logtrace(...) tr_logAddNamed(TR_LOG_TRACE, nullptr, __VA_ARGS__)
static tr_port getRandomPort(tr_session const* s)
{
@ -229,18 +230,9 @@ static void accept_incoming_peer(evutil_socket_t fd, short /*what*/, void* vsess
if (clientSocket != TR_BAD_SOCKET)
{
if (tr_logGetDeepEnabled())
{
char addrstr[TR_ADDRSTRLEN];
tr_address_and_port_to_string(addrstr, sizeof(addrstr), &clientAddr, clientPort);
tr_logAddDeep(
__FILE__,
__LINE__,
nullptr,
"new incoming connection %" PRIdMAX " (%s)",
(intmax_t)clientSocket,
addrstr);
}
char addrstr[TR_ADDRSTRLEN];
tr_address_and_port_to_string(addrstr, sizeof(addrstr), &clientAddr, clientPort);
logtrace("new incoming connection %" PRIdMAX " (%s)", (intmax_t)clientSocket, addrstr);
tr_peerMgrAddIncoming(session->peerMgr, &clientAddr, clientPort, tr_peer_socket_tcp_create(clientSocket));
}
@ -702,7 +694,7 @@ static void tr_sessionInitImpl(init_data* data)
TR_ASSERT(tr_amInEventThread(session));
TR_ASSERT(tr_variantIsDict(clientSettings));
dbgmsg("tr_sessionInit: the session's top-level bandwidth object is %p", (void*)&session->bandwidth);
logtrace("tr_sessionInit: the session's top-level bandwidth object is %p", (void*)&session->bandwidth);
tr_variant settings;
@ -1936,7 +1928,7 @@ void tr_sessionClose(tr_session* session)
time_t const deadline = time(nullptr) + ShutdownMaxSeconds;
dbgmsg(
logdbg(
"shutting down transmission session %p... now is %zu, deadline is %zu",
(void*)session,
(size_t)time(nullptr),
@ -1947,7 +1939,7 @@ void tr_sessionClose(tr_session* session)
while (!session->isClosed && !deadlineReached(deadline))
{
dbgmsg("waiting for the libtransmission thread to finish");
logtrace("waiting for the libtransmission thread to finish");
tr_wait_msec(10);
}
@ -1959,7 +1951,7 @@ void tr_sessionClose(tr_session* session)
session->announcer_udp != nullptr) &&
!deadlineReached(deadline))
{
dbgmsg(
logtrace(
"waiting on port unmap (%p) or announcer (%p)... now %zu deadline %zu",
(void*)session->shared,
(void*)session->announcer,
@ -1976,19 +1968,22 @@ void tr_sessionClose(tr_session* session)
while (session->events != nullptr)
{
static bool forced = false;
dbgmsg("waiting for libtransmission thread to finish... now %zu deadline %zu", (size_t)time(nullptr), (size_t)deadline);
logtrace(
"waiting for libtransmission thread to finish... now %zu deadline %zu",
(size_t)time(nullptr),
(size_t)deadline);
tr_wait_msec(10);
if (deadlineReached(deadline) && !forced)
{
dbgmsg("calling event_loopbreak()");
logtrace("calling event_loopbreak()");
forced = true;
event_base_loopbreak(session->event_base);
}
if (deadlineReached(deadline + 3))
{
dbgmsg("deadline+3 reached... calling break...\n");
logtrace("deadline+3 reached... calling break...\n");
break;
}
}

8
libtransmission/stats.cc
View File

@ -93,13 +93,7 @@ static void saveCumulativeStats(tr_session const* session, tr_session_stats cons
tr_variantDictAddInt(&top, TR_KEY_session_count, s->sessionCount);
tr_variantDictAddInt(&top, TR_KEY_uploaded_bytes, s->uploadedBytes);
auto const filename = getFilename(session);
if (tr_logGetDeepEnabled())
{
tr_logAddDeep(__FILE__, __LINE__, nullptr, "Saving stats to \"%s\"", filename.c_str());
}
tr_variantToFile(&top, TR_VARIANT_FMT_JSON, filename);
tr_variantToFile(&top, TR_VARIANT_FMT_JSON, getFilename(session));
tr_variantFree(&top);
}

14
libtransmission/torrent-magnet.cc
View File

@ -29,7 +29,7 @@
using namespace std::literals;
#define dbgmsg(tor, ...) tr_logAddDeepNamed(tr_torrentName(tor), __VA_ARGS__)
#define logdbg(tor, ...) tr_logAddNamed(TR_LOG_DEBUG, tr_torrentName(tor), __VA_ARGS__)
/***
****
@ -76,7 +76,7 @@ bool tr_torrentSetMetadataSizeHint(tr_torrent* tor, int64_t size)
int const n = (size <= 0 || size > INT_MAX) ? -1 : size / METADATA_PIECE_SIZE + (size % METADATA_PIECE_SIZE != 0 ? 1 : 0);
dbgmsg(tor, "metadata is %" PRId64 " bytes in %d pieces", size, n);
logdbg(tor, "metadata is %" PRId64 " bytes in %d pieces", size, n);
if (n <= 0)
{
@ -311,7 +311,7 @@ static void onHaveAllMetainfo(tr_torrent* tor, tr_incomplete_metadata* m)
m->piecesNeededCount = n;
char const* const msg = error != nullptr && error->message != nullptr ? error->message : "unknown error";
dbgmsg(tor, "metadata error: %s. (trying again; %d pieces left)", msg, n);
logdbg(tor, "metadata error: %s. (trying again; %d pieces left)", msg, n);
tr_error_clear(&error);
}
}
@ -322,7 +322,7 @@ void tr_torrentSetMetadataPiece(tr_torrent* tor, int piece, void const* data, in
TR_ASSERT(data != nullptr);
TR_ASSERT(len >= 0);
dbgmsg(tor, "got metadata piece %d of %d bytes", piece, len);
logdbg(tor, "got metadata piece %d of %d bytes", piece, len);
// are we set up to download metadata?
tr_incomplete_metadata* const m = tor->incompleteMetadata;
@ -356,12 +356,12 @@ void tr_torrentSetMetadataPiece(tr_torrent* tor, int piece, void const* data, in
tr_removeElementFromArray(m->piecesNeeded, idx, sizeof(struct metadata_node), m->piecesNeededCount);
--m->piecesNeededCount;
dbgmsg(tor, "saving metainfo piece %d... %d remain", piece, m->piecesNeededCount);
logdbg(tor, "saving metainfo piece %d... %d remain", piece, m->piecesNeededCount);
/* are we done? */
if (m->piecesNeededCount == 0)
{
dbgmsg(tor, "metainfo piece %d was the last one", piece);
logdbg(tor, "metainfo piece %d was the last one", piece);
onHaveAllMetainfo(tor, m);
}
}
@ -382,7 +382,7 @@ bool tr_torrentGetNextMetadataRequest(tr_torrent* tor, time_t now, int* setme_pi
m->piecesNeeded[i].piece = piece;
m->piecesNeeded[i].requestedAt = now;
dbgmsg(tor, "next piece to request: %d", piece);
logdbg(tor, "next piece to request: %d", piece);
*setme_piece = piece;
have_request = true;
}

62
libtransmission/torrent.cc
View File

@ -60,7 +60,11 @@
****
***/
#define tr_deeplog_tor(tor, ...) tr_logAddDeepNamed(tr_torrentName(tor), __VA_ARGS__)
#define logerr(tor, ...) tr_logAddNamed(TR_LOG_ERROR, tr_torrentName(tor), __VA_ARGS__)
#define logwarn(tor, ...) tr_logAddNamed(TR_LOG_WARN, tr_torrentName(tor), __VA_ARGS__)
#define loginfo(tor, ...) tr_logAddNamed(TR_LOG_INFO, tr_torrentName(tor), __VA_ARGS__)
#define logdbg(tor, ...) tr_logAddNamed(TR_LOG_DEBUG, tr_torrentName(tor), __VA_ARGS__)
#define logtrace(tor, ...) tr_logAddNamed(TR_LOG_TRACE, tr_torrentName(tor), __VA_ARGS__)
using namespace std::literals;
@ -472,7 +476,7 @@ void tr_torrentCheckSeedLimit(tr_torrent* tor)
/* if we're seeding and reach our seed ratio limit, stop the torrent */
if (tr_torrentIsSeedRatioDone(tor))
{
tr_logAddTorInfo(tor, "%s", "Seed ratio reached; pausing torrent");
loginfo(tor, "%s", "Seed ratio reached; pausing torrent");
tor->isStopping = true;
@ -485,7 +489,7 @@ void tr_torrentCheckSeedLimit(tr_torrent* tor)
/* if we're seeding and reach our inactivity limit, stop the torrent */
else if (tr_torrentIsSeedIdleLimitDone(tor))
{
tr_logAddTorInfo(tor, "%s", "Seeding idle limit reached; pausing torrent");
loginfo(tor, "%s", "Seeding idle limit reached; pausing torrent");
tor->isStopping = true;
tor->finishedSeedingByIdle = true;
@ -519,7 +523,7 @@ static void onTrackerResponse(tr_torrent* tor, tr_tracker_event const* event, vo
switch (event->messageType)
{
case TR_TRACKER_PEERS:
tr_logAddTorDbg(tor, "Got %zu peers from tracker", size_t(std::size(event->pex)));
logtrace(tor, "Got %zu peers from tracker", size_t(std::size(event->pex)));
tr_peerMgrAddPex(tor, TR_PEER_FROM_TRACKER, std::data(event->pex), std::size(event->pex));
break;
@ -532,7 +536,7 @@ static void onTrackerResponse(tr_torrent* tor, tr_tracker_event const* event, vo
break;
case TR_TRACKER_WARNING:
tr_logAddTorErr(tor, _("Tracker warning: \"%" TR_PRIsv "\""), TR_PRIsv_ARG(event->text));
logwarn(tor, _("Tracker warning: \"%" TR_PRIsv "\""), TR_PRIsv_ARG(event->text));
tor->error = TR_STAT_TRACKER_WARNING;
tor->error_announce_url = event->announce_url;
tor->error_string = event->text;
@ -574,7 +578,7 @@ static void torrentInitFromInfoDict(tr_torrent* tor)
else
{
// lookups by obfuscated hash will fail for this torrent
tr_logAddTorErr(tor, "error computing obfuscated info hash");
logerr(tor, "error computing obfuscated info hash");
tor->obfuscated_hash = tr_sha1_digest_t{};
}
@ -616,7 +620,7 @@ static bool setLocalErrorIfFilesDisappeared(tr_torrent* tor)
if (disappeared)
{
tr_deeplog_tor(tor, "%s", "[LAZY] uh oh, the files disappeared");
logtrace(tor, "%s", "[LAZY] uh oh, the files disappeared");
tor->setLocalError(_(
"No data found! Ensure your drives are connected or use \"Set Location\". To re-download, remove the torrent and re-add it."));
}
@ -1397,7 +1401,7 @@ static void torrentStart(tr_torrent* tor, bool bypass_queue)
/* allow finished torrents to be resumed */
if (tr_torrentIsSeedRatioDone(tor))
{
tr_logAddTorInfo(tor, "%s", _("Restarted manually -- disabling its seed ratio"));
loginfo(tor, "%s", _("Restarted manually -- disabling its seed ratio"));
tr_torrentSetRatioMode(tor, TR_RATIOLIMIT_UNLIMITED);
}
@ -1509,7 +1513,10 @@ static void stopTorrent(tr_torrent* const tor)
TR_ASSERT(tr_amInEventThread(tor->session));
auto const lock = tor->unique_lock();
tr_logAddTorInfo(tor, "%s", "Pausing");
if (!tor->session->isClosing())
{
loginfo(tor, _("Pausing"));
}
tr_verifyRemove(tor);
tr_peerMgrStopTorrent(tor);
@ -1528,7 +1535,7 @@ static void stopTorrent(tr_torrent* const tor)
if (tor->magnetVerify)
{
tor->magnetVerify = false;
tr_logAddTorInfo(tor, "%s", "Magnet Verify");
logtrace(tor, "%s", "Magnet Verify");
refreshCurrentDir(tor);
tr_torrentVerify(tor);
@ -1559,7 +1566,10 @@ static void closeTorrent(tr_torrent* const tor)
tor->session->removed_torrents.emplace_back(tor->uniqueId, tr_time());
tr_logAddTorInfo(tor, "%s", _("Removing torrent"));
if (!tor->session->isClosing())
{
loginfo(tor, "%s", _("Removing torrent"));
}
tor->magnetVerify = false;
stopTorrent(tor);
@ -1768,13 +1778,13 @@ static void torrentCallScript(tr_torrent const* tor, char const* script)
{ "TR_TORRENT_TRACKERS"sv, trackers_str },
};
tr_logAddTorInfo(tor, "Calling script \"%s\"", script);
loginfo(tor, "Calling script \"%s\"", script);
tr_error* error = nullptr;
if (!tr_spawn_async(std::data(cmd), env, TR_IF_WIN32("\\", "/"), &error))
{
tr_logAddTorErr(tor, "Error executing script \"%s\" (%d): %s", script, error->code, error->message);
logwarn(tor, "Error executing script \"%s\" (%d): %s", script, error->code, error->message);
tr_error_free(error);
}
}
@ -1793,7 +1803,7 @@ void tr_torrent::recheckCompleteness()
if (recentChange)
{
tr_logAddTorInfo(
logtrace(
this,
_("State changed from \"%1$s\" to \"%2$s\""),
getCompletionString(this->completeness),
@ -1969,7 +1979,7 @@ bool tr_torrentReqIsValid(tr_torrent const* tor, tr_piece_index_t index, uint32_
if (err != 0)
{
tr_logAddTorDbg(
logtrace(
tor,
"index %lu offset %lu length %lu err %d\n",
(unsigned long)index,
@ -2005,7 +2015,7 @@ tr_block_span_t tr_torGetFileBlockSpan(tr_torrent const* tor, tr_file_index_t i)
bool tr_torrent::checkPiece(tr_piece_index_t piece)
{
bool const pass = tr_ioTestPiece(this, piece);
tr_logAddTorDbg(this, "[LAZY] tr_torrent.checkPiece tested piece %zu, pass==%d", size_t(piece), int(pass));
logtrace(this, "[LAZY] tr_torrent.checkPiece tested piece %zu, pass==%d", size_t(piece), int(pass));
return pass;
}
@ -2338,7 +2348,8 @@ static void setLocationImpl(struct LocationData* const data)
auto const& location = data->location;
double bytesHandled = 0;
tr_logAddDebug(
logtrace(
tor,
"Moving \"%s\" location from currentDir \"%s\" to \"%s\"",
tr_torrentName(tor),
tor->currentDir().c_str(),
@ -2365,23 +2376,18 @@ static void setLocationImpl(struct LocationData* const data)
auto const oldpath = tr_strvPath(oldbase, sub);
auto const newpath = tr_strvPath(location, sub);
tr_logAddDebug("Found file #%d: %s", (int)i, oldpath.c_str());
logtrace(tor, "Found file #%d: %s", (int)i, oldpath.c_str());
if (do_move && !tr_sys_path_is_same(oldpath.c_str(), newpath.c_str(), nullptr))
{
tr_error* error = nullptr;
tr_logAddTorInfo(tor, "moving \"%s\" to \"%s\"", oldpath.c_str(), newpath.c_str());
logtrace(tor, "moving \"%s\" to \"%s\"", oldpath.c_str(), newpath.c_str());
if (!tr_moveFile(oldpath.c_str(), newpath.c_str(), &error))
{
err = true;
tr_logAddTorErr(
tor,
"error moving \"%s\" to \"%s\": %s",
oldpath.c_str(),
newpath.c_str(),
error->message);
logerr(tor, "error moving \"%s\" to \"%s\": %s", oldpath.c_str(), newpath.c_str(), error->message);
tr_error_free(error);
}
}
@ -2520,7 +2526,7 @@ static void tr_torrentFileCompleted(tr_torrent* tor, tr_file_index_t i)
if (!tr_sys_path_rename(oldpath.c_str(), newpath.c_str(), &error))
{
tr_logAddTorErr(tor, "Error moving \"%s\" to \"%s\": %s", oldpath.c_str(), newpath.c_str(), error->message);
logerr(tor, "Error moving \"%s\" to \"%s\": %s", oldpath.c_str(), newpath.c_str(), error->message);
tr_error_free(error);
}
}
@ -2567,7 +2573,7 @@ void tr_torrentGotBlock(tr_torrent* tor, tr_block_index_t block)
else
{
uint32_t const n = tor->pieceSize(piece);
tr_logAddTorErr(tor, _("Piece %" PRIu32 ", which was just downloaded, failed its checksum test"), piece);
logdbg(tor, _("Piece %" PRIu32 ", which was just downloaded, failed its checksum test"), piece);
tor->corruptCur += n;
tor->downloadedCur -= std::min(tor->downloadedCur, uint64_t{ n });
tr_peerMgrGotBadPiece(tor, piece);
@ -2578,7 +2584,7 @@ void tr_torrentGotBlock(tr_torrent* tor, tr_block_index_t block)
{
uint32_t const n = tor->blockSize(block);
tor->downloadedCur -= std::min(tor->downloadedCur, uint64_t{ n });
tr_logAddTorDbg(tor, "we have this block already...");
logdbg(tor, "we have this block already...");
}
}

30
libtransmission/tr-lpd.cc
View File

@ -37,6 +37,12 @@ using in_port_t = uint16_t; /* all missing */
static auto constexpr SIZEOF_HASH_STRING = TR_SHA1_DIGEST_STRLEN;
#define logwarn(...) tr_logAddNamed(TR_LOG_WARN, "lpd", __VA_ARGS__)
#define logdbg(...) tr_logAddNamed(TR_LOG_DEBUG, "lpd", __VA_ARGS__)
#define logtrace(...) tr_logAddNamed(TR_LOG_TRACE, "lpd", __VA_ARGS__)
#define logdbgTor(tor, ...) tr_logAddNamed(TR_LOG_DEBUG, tr_torrentName(tor), __VA_ARGS__)
#define logtraceTor(tor, ...) tr_logAddNamed(TR_LOG_TRACE, tr_torrentName(tor), __VA_ARGS__)
/**
* @brief Local Peer Discovery
* @file tr-lpd.c
@ -278,7 +284,7 @@ int tr_lpdInit(tr_session* ss, tr_address* /*tr_addr*/)
return -1;
}
tr_logAddNamedDbg("LPD", "Initialising Local Peer Discovery");
logdbg("Initialising Local Peer Discovery");
/* setup datagram socket (receive) */
{
@ -371,7 +377,7 @@ int tr_lpdInit(tr_session* ss, tr_address* /*tr_addr*/)
upkeep_timer = evtimer_new(ss->event_base, on_upkeep_timer, ss);
tr_timerAdd(upkeep_timer, UpkeepIntervalSecs, 0);
tr_logAddNamedDbg("LPD", "Local Peer Discovery initialised");
logdbg("Local Peer Discovery initialised");
return 1;
@ -382,7 +388,7 @@ fail:
evutil_closesocket(lpd_socket2);
lpd_socket = lpd_socket2 = TR_BAD_SOCKET;
session = nullptr;
tr_logAddNamedDbg("LPD", "LPD initialisation failed (errno = %d)", save);
logwarn("LPD initialisation failed (errno = %d)", save);
errno = save;
}
@ -396,7 +402,7 @@ void tr_lpdUninit(tr_session* ss)
return;
}
tr_logAddNamedDbg("LPD", "Uninitialising Local Peer Discovery");
logtrace("Uninitialising Local Peer Discovery");
event_free(lpd_event);
lpd_event = nullptr;
@ -407,7 +413,7 @@ void tr_lpdUninit(tr_session* ss)
/* just shut down, we won't remember any former nodes */
evutil_closesocket(lpd_socket);
evutil_closesocket(lpd_socket2);
tr_logAddNamedDbg("LPD", "Done uninitialising Local Peer Discovery");
logtrace("Done uninitialising Local Peer Discovery");
session = nullptr;
}
@ -471,7 +477,7 @@ bool tr_lpdSendAnnounce(tr_torrent const* t)
}
}
tr_logAddTorDbg(t, "LPD announce message away");
logtraceTor(t, "LPD announce message away");
return true;
}
@ -539,14 +545,14 @@ static int tr_lpdConsiderAnnounce(tr_pex* peer, char const* const msg)
{
/* we found a suitable peer, add it to the torrent */
tr_peerMgrAddPex(tor, TR_PEER_FROM_LPD, peer, 1);
tr_logAddTorDbg(tor, "Learned %d local peer from LPD (%s:%u)", 1, tr_address_to_string(&peer->addr), peerPort);
logdbgTor(tor, "Learned %d local peer from LPD (%s:%u)", 1, tr_address_to_string(&peer->addr), peerPort);
/* periodic reconnectPulse() deals with the rest... */
return 1;
}
tr_logAddNamedDbg("LPD", "Cannot serve torrent #%s", hashString);
logdbg("Cannot serve torrent #%s", hashString);
}
return res;
@ -620,11 +626,7 @@ static int tr_lpdAnnounceMore(time_t const now, int const interval)
if (lpd_unsolicitedMsgCounter < 0)
{
tr_logAddNamedInfo(
"LPD",
"Dropped %d announces in the last interval (max. %d allowed)",
-lpd_unsolicitedMsgCounter,
maxAnnounceCap);
logtrace("Dropped %d announces in the last interval (max. %d allowed)", -lpd_unsolicitedMsgCounter, maxAnnounceCap);
}
lpd_unsolicitedMsgCounter = maxAnnounceCap;
@ -690,6 +692,6 @@ static void event_callback(evutil_socket_t /*s*/, short type, void* /*user_data*
}
}
tr_logAddNamedDbg("LPD", "Discarded invalid multicast message");
logtrace("Discarded invalid multicast message");
}
}

31
libtransmission/tr-udp.cc
View File

@ -24,6 +24,11 @@
#include "tr-utp.h"
#include "tr-udp.h"
#define logwarn(...) tr_logAddNamed(TR_LOG_WARN, "udp", __VA_ARGS__)
#define loginfo(...) tr_logAddNamed(TR_LOG_INFO, "udp", __VA_ARGS__)
#define logdbg(...) tr_logAddNamed(TR_LOG_DEBUG, "udp", __VA_ARGS__)
#define logtrace(...) tr_logAddNamed(TR_LOG_TRACE, "udp", __VA_ARGS__)
/* Since we use a single UDP socket in order to implement multiple
uTP sockets, try to set up huge buffers. */
@ -43,7 +48,7 @@ static void set_socket_buffers(tr_socket_t fd, bool large)
if (rc < 0)
{
tr_logAddNamedError("UDP", "Failed to set receive buffer: %s", tr_net_strerror(sockerrno).c_str());
logdbg("Failed to set receive buffer: %s", tr_net_strerror(sockerrno).c_str());
}
size = large ? SEND_BUFFER_SIZE : SMALL_BUFFER_SIZE;
@ -51,7 +56,7 @@ static void set_socket_buffers(tr_socket_t fd, bool large)
if (rc < 0)
{
tr_logAddNamedError("UDP", "Failed to set send buffer: %s", tr_net_strerror(sockerrno).c_str());
logdbg("Failed to set send buffer: %s", tr_net_strerror(sockerrno).c_str());
}
if (large)
@ -72,17 +77,17 @@ static void set_socket_buffers(tr_socket_t fd, bool large)
if (rbuf < RECV_BUFFER_SIZE)
{
tr_logAddNamedError("UDP", "Failed to set receive buffer: requested %d, got %d", RECV_BUFFER_SIZE, rbuf);
loginfo("Failed to set receive buffer: requested %d, got %d", RECV_BUFFER_SIZE, rbuf);
#ifdef __linux__
tr_logAddNamedInfo("UDP", "Please add the line \"net.core.rmem_max = %d\" to /etc/sysctl.conf", RECV_BUFFER_SIZE);
loginfo("Please add the line \"net.core.rmem_max = %d\" to /etc/sysctl.conf", RECV_BUFFER_SIZE);
#endif
}
if (sbuf < SEND_BUFFER_SIZE)
{
tr_logAddNamedError("UDP", "Failed to set send buffer: requested %d, got %d", SEND_BUFFER_SIZE, sbuf);
loginfo("Failed to set send buffer: requested %d, got %d", SEND_BUFFER_SIZE, sbuf);
#ifdef __linux__
tr_logAddNamedInfo("UDP", "Please add the line \"net.core.wmem_max = %d\" to /etc/sysctl.conf", SEND_BUFFER_SIZE);
loginfo("Please add the line \"net.core.wmem_max = %d\" to /etc/sysctl.conf", SEND_BUFFER_SIZE);
#endif
}
}
@ -200,7 +205,7 @@ static void rebind_ipv6(tr_session* ss, bool force)
FAIL:
/* Something went wrong. It's difficult to recover, so let's simply
set things up so that we try again next time. */
tr_logAddNamedError("UDP", "Couldn't rebind IPv6 socket");
logwarn("Couldn't rebind IPv6 socket");
if (s != TR_BAD_SOCKET)
{
@ -247,7 +252,7 @@ static void event_callback(evutil_socket_t s, [[maybe_unused]] short type, void*
{
if (!tau_handle_message(session, buf, rc))
{
tr_logAddNamedDbg("UDP", "Couldn't parse UDP tracker packet.");
logtrace("Couldn't parse UDP tracker packet.");
}
}
else
@ -256,7 +261,7 @@ static void event_callback(evutil_socket_t s, [[maybe_unused]] short type, void*
{
if (!tr_utpPacket(buf, rc, (struct sockaddr*)&from, fromlen, session))
{
tr_logAddNamedDbg("UDP", "Unexpected UDP packet");
logtrace("Unexpected UDP packet");
}
}
}
@ -279,7 +284,7 @@ void tr_udpInit(tr_session* ss)
if (ss->udp_socket == TR_BAD_SOCKET)
{
tr_logAddNamedError("UDP", "Couldn't create IPv4 socket");
logwarn("Couldn't create IPv4 socket");
}
else
{
@ -298,7 +303,7 @@ void tr_udpInit(tr_session* ss)
if (rc == -1)
{
tr_logAddNamedError("UDP", "Couldn't bind IPv4 socket");
logwarn("Couldn't bind IPv4 socket");
tr_netCloseSocket(ss->udp_socket);
ss->udp_socket = TR_BAD_SOCKET;
}
@ -308,7 +313,7 @@ void tr_udpInit(tr_session* ss)
if (ss->udp_event == nullptr)
{
tr_logAddNamedError("UDP", "Couldn't allocate IPv4 event");
logwarn("Couldn't allocate IPv4 event");
}
}
}
@ -326,7 +331,7 @@ void tr_udpInit(tr_session* ss)
if (ss->udp6_event == nullptr)
{
tr_logAddNamedError("UDP", "Couldn't allocate IPv6 event");
logwarn("Couldn't allocate IPv6 event");
}
}

18
libtransmission/tr-utp.cc
View File

@ -17,28 +17,24 @@
#include "tr-utp.h"
#include "utils.h"
#define logwarn(...) tr_logAddNamed(TR_LOG_WARN, "utp", __VA_ARGS__)
#define logtrace(...) tr_logAddNamed(TR_LOG_TRACE, "utp", __VA_ARGS__)
#ifndef WITH_UTP
static char constexpr MyName[] = "UTP";
#define dbgmsg(...) tr_logAddDeepNamed(MyName, __VA_ARGS__)
void UTP_Close(struct UTPSocket* socket)
{
tr_logAddNamedError(MyName, "UTP_Close(%p) was called.", socket);
dbgmsg("UTP_Close(%p) was called.", socket);
logtrace("UTP_Close(%p) was called.", socket);
}
void UTP_RBDrained(struct UTPSocket* socket)
{
tr_logAddNamedError(MyName, "UTP_RBDrained(%p) was called.", socket);
dbgmsg("UTP_RBDrained(%p) was called.", socket);
logtrace("UTP_RBDrained(%p) was called.", socket);
}
bool UTP_Write(struct UTPSocket* socket, size_t count)
{
tr_logAddNamedError(MyName, "UTP_RBDrained(%p, %zu) was called.", socket, count);
dbgmsg("UTP_RBDrained(%p, %zu) was called.", socket, count);
logtrace("UTP_RBDrained(%p, %zu) was called.", socket, count);
return false;
}
@ -99,7 +95,7 @@ static void incoming(void* vsession, struct UTPSocket* s)
if (!tr_address_from_sockaddr_storage(&addr, &port, &from_storage))
{
tr_logAddNamedError("UTP", "Unknown socket family");
logwarn("Unknown socket family");
UTP_Close(s);
return;
}

28
libtransmission/transmission.h
View File

@ -744,11 +744,29 @@ bool tr_sessionIsScriptEnabled(tr_session const*, TrScript);
enum tr_log_level
{
TR_LOG_SILENT = 0,
TR_LOG_ERROR = 1,
TR_LOG_INFO = 2,
TR_LOG_DEBUG = 3,
TR_LOG_FIREHOSE = 4
// No logging at all
TR_LOG_OFF,
// Errors that prevent Transmission from running
TR_LOG_CRITICAL,
// Errors that could prevent a single torrent from running, e.g. missing
// files or a private torrent's tracker responding "unregistered torrent"
TR_LOG_ERROR,
// Smaller errors that don't stop the overall system,
// e.g. unable to preallocate a file, or unable to connect to a tracker
// when other trackers are available
TR_LOG_WARN,
// User-visible info, e.g. "torrent completed" or "running script"
TR_LOG_INFO,
// Debug messages
TR_LOG_DEBUG,
// High-volume debug messages, e.g. tracing peer protocol messages
TR_LOG_TRACE
};
void tr_logSetLevel(tr_log_level);

9
libtransmission/trevent.cc
View File

@ -29,6 +29,8 @@
#include "trevent.h"
#include "utils.h"
#define logtrace(...) tr_logAddNamed(TR_LOG_TRACE, "trevent", __VA_ARGS__)
/***
****
***/
@ -211,7 +213,7 @@ static void libeventThreadFunc(tr_event_handle* events)
events->session->evdns_base = nullptr;
events->session->events = nullptr;
delete events;
tr_logAddDebug("Closing libevent thread");
logtrace("Closing libevent thread");
}
void tr_eventInit(tr_session* session)
@ -241,10 +243,7 @@ void tr_eventClose(tr_session* session)
event_base_loopexit(events->base, nullptr);
if (tr_logGetDeepEnabled())
{
tr_logAddDeep(__FILE__, __LINE__, nullptr, "closing trevent pipe");
}
logtrace("closing trevent pipe");
}
/**

4
libtransmission/utils.cc
View File

@ -51,6 +51,8 @@
using namespace std::literals;
#define logtrace(...) tr_logAddNamed(TR_LOG_TRACE, nullptr, __VA_ARGS__)
time_t __tr_current_time = 0;
/***
@ -362,7 +364,7 @@ bool tr_saveFile(std::string const& filename, std::string_view contents, tr_erro
return false;
}
tr_logAddInfo(_("Saved \"%s\""), filename.c_str());
logtrace("Saved \"%s\"", filename.c_str());
return true;
}

13
libtransmission/web.cc
View File

@ -34,7 +34,8 @@ using namespace std::literals;
#define USE_LIBCURL_SOCKOPT
#endif
#define dbgmsg(...) tr_logAddDeepNamed("web", __VA_ARGS__)
#define loginfo(...) tr_logAddNamed(TR_LOG_INFO, "web", __VA_ARGS__)
#define logtrace(...) tr_logAddNamed(TR_LOG_TRACE, "web", __VA_ARGS__)
/***
****
@ -118,9 +119,9 @@ public:
if (curl_ssl_verify)
{
auto const* bundle = std::empty(curl_ca_bundle) ? "none" : curl_ca_bundle.c_str();
tr_logAddNamedInfo("web", "will verify tracker certs using envvar CURL_CA_BUNDLE: %s", bundle);
tr_logAddNamedInfo("web", "NB: this only works if you built against libcurl with openssl or gnutls, NOT nss");
tr_logAddNamedInfo("web", "NB: Invalid certs will appear as 'Could not connect to tracker' like many other errors");
loginfo("will verify tracker certs using envvar CURL_CA_BUNDLE: %s", bundle);
loginfo("NB: this only works if you built against libcurl with openssl or gnutls, NOT nss");
loginfo("NB: Invalid certs will appear as 'Could not connect to tracker' like many other errors");
}
if (auto const& file = mediator.cookieFile(); file)
@ -290,7 +291,7 @@ private:
}
evbuffer_add(task->body(), data, bytes_used);
dbgmsg("wrote %zu bytes to task %p's buffer", bytes_used, (void*)task);
logtrace("wrote %zu bytes to task %p's buffer", bytes_used, (void*)task);
return bytes_used;
}
@ -456,7 +457,7 @@ private:
// add queued tasks
for (auto* task : impl->queued_tasks)
{
dbgmsg("adding task to curl: [%s]", task->url().c_str());
logtrace("adding task to curl: [%s]", task->url().c_str());
initEasy(impl, task);
curl_multi_add_handle(multi.get(), task->easy());
}

16
tests/libtransmission/announcer-test.cc
View File

@ -21,6 +21,8 @@ using AnnouncerTest = ::testing::Test;
using namespace std::literals;
static char const* const LogName = "LogName";
TEST_F(AnnouncerTest, parseHttpAnnounceResponseNoPeers)
{
// clang-format off
@ -37,7 +39,7 @@ TEST_F(AnnouncerTest, parseHttpAnnounceResponseNoPeers)
// clang-format on
auto response = tr_announce_response{};
tr_announcerParseHttpAnnounceResponse(response, NoPeers);
tr_announcerParseHttpAnnounceResponse(response, NoPeers, LogName);
EXPECT_EQ(1803, response.interval);
EXPECT_EQ(1800, response.min_interval);
EXPECT_EQ(3, response.seeders);
@ -66,7 +68,7 @@ TEST_F(AnnouncerTest, parseHttpAnnounceResponsePexCompact)
// clang-format on
auto response = tr_announce_response{};
tr_announcerParseHttpAnnounceResponse(response, IPv4Peers);
tr_announcerParseHttpAnnounceResponse(response, IPv4Peers, LogName);
EXPECT_EQ(1803, response.interval);
EXPECT_EQ(1800, response.min_interval);
EXPECT_EQ(3, response.seeders);
@ -105,7 +107,7 @@ TEST_F(AnnouncerTest, parseHttpAnnounceResponsePexList)
// clang-format on
auto response = tr_announce_response{};
tr_announcerParseHttpAnnounceResponse(response, IPv4Peers);
tr_announcerParseHttpAnnounceResponse(response, IPv4Peers, LogName);
EXPECT_EQ(1803, response.interval);
EXPECT_EQ(1800, response.min_interval);
EXPECT_EQ(3, response.seeders);
@ -138,7 +140,7 @@ TEST_F(AnnouncerTest, parseHttpAnnounceResponseFailureReason)
// clang-format on
auto response = tr_announce_response{};
tr_announcerParseHttpAnnounceResponse(response, NoPeers);
tr_announcerParseHttpAnnounceResponse(response, NoPeers, LogName);
EXPECT_EQ(1803, response.interval);
EXPECT_EQ(1800, response.min_interval);
EXPECT_EQ(3, response.seeders);
@ -186,7 +188,7 @@ TEST_F(AnnouncerTest, parseHttpScrapeResponseMulti)
std::fill_n(std::data(response.rows[1].info_hash), std::size(response.rows[1].info_hash), std::byte{ 'b' });
std::fill_n(std::data(response.rows[2].info_hash), std::size(response.rows[2].info_hash), std::byte{ 'c' });
response.row_count = 3;
tr_announcerParseHttpScrapeResponse(response, ResponseBenc);
tr_announcerParseHttpScrapeResponse(response, ResponseBenc, LogName);
EXPECT_EQ(1, response.rows[0].seeders);
EXPECT_EQ(2, response.rows[0].leechers);
@ -244,7 +246,7 @@ TEST_F(AnnouncerTest, parseHttpScrapeResponseMultiWithUnexpected)
std::fill_n(std::data(response.rows[1].info_hash), std::size(response.rows[1].info_hash), std::byte{ 'b' });
std::fill_n(std::data(response.rows[2].info_hash), std::size(response.rows[2].info_hash), std::byte{ 'c' });
response.row_count = 3;
tr_announcerParseHttpScrapeResponse(response, ResponseBenc);
tr_announcerParseHttpScrapeResponse(response, ResponseBenc, LogName);
EXPECT_EQ(1, response.rows[0].seeders);
EXPECT_EQ(2, response.rows[0].leechers);
@ -288,7 +290,7 @@ TEST_F(AnnouncerTest, parseHttpScrapeResponseMultiWithMissing)
std::fill_n(std::data(response.rows[1].info_hash), std::size(response.rows[1].info_hash), std::byte{ 'b' });
std::fill_n(std::data(response.rows[2].info_hash), std::size(response.rows[2].info_hash), std::byte{ 'c' });
response.row_count = 3;
tr_announcerParseHttpScrapeResponse(response, ResponseBenc);
tr_announcerParseHttpScrapeResponse(response, ResponseBenc, LogName);
EXPECT_EQ(1, response.rows[0].seeders);
EXPECT_EQ(2, response.rows[0].leechers);

2
tests/libtransmission/torrent-metainfo-test.cc
View File

@ -75,7 +75,7 @@ TEST_F(TorrentMetainfoTest, bucket)
{ "", false },
} };
tr_logSetLevel(TR_LOG_SILENT);
tr_logSetLevel(TR_LOG_OFF);
for (auto const& test : tests)
{