diff --git a/daemon/daemon.cc b/daemon/daemon.cc index f9794c5ef..b686a53ee 100644 --- a/daemon/daemon.cc +++ b/daemon/daemon.cc @@ -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{}; 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; } diff --git a/gtk/MessageLogWindow.cc b/gtk/MessageLogWindow.cc index 6c47e82cd..c3e215c6e 100644 --- a/gtk/MessageLogWindow.cc +++ b/gtk/MessageLogWindow.cc @@ -71,7 +71,7 @@ private: Glib::RefPtr store_; Glib::RefPtr filter_; Glib::RefPtr sort_; - tr_log_level maxLevel_ = TR_LOG_SILENT; + tr_log_level maxLevel_ = TR_LOG_OFF; bool isPaused_ = false; sigc::connection refresh_tag_; }; diff --git a/libtransmission/announcer-common.h b/libtransmission/announcer-common.h index 1df6eb716..0870e493f 100644 --- a/libtransmission/announcer-common.h +++ b/libtransmission/announcer-common.h @@ -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); diff --git a/libtransmission/announcer-http.cc b/libtransmission/announcer-http.cc index a1954c1df..ffca9688d 100644 --- a/libtransmission/announcer-http.cc +++ b/libtransmission/announcer-http.cc @@ -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; diff --git a/libtransmission/announcer-udp.cc b/libtransmission/announcer-udp.cc index e1921931c..7b3966eed 100644 --- a/libtransmission/announcer-udp.cc +++ b/libtransmission/announcer-udp.cc @@ -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& 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(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); diff --git a/libtransmission/announcer.cc b/libtransmission/announcer.cc index 3e4da366d..effe9324f 100644 --- a/libtransmission/announcer.cc +++ b/libtransmission/announcer.cc @@ -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{}; \ + auto name = std::array{}; \ 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{}; - 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{}; + 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 " -- " diff --git a/libtransmission/bandwidth.cc b/libtransmission/bandwidth.cc index 49d1c6dc1..b7bc4b5a0 100644 --- a/libtransmission/bandwidth.cc +++ b/libtransmission/bandwidth.cc @@ -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& 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& 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)) { diff --git a/libtransmission/cache.cc b/libtransmission/cache.cc index cbfc912ae..7d44861c2 100644 --- a/libtransmission/cache.cc +++ b/libtransmission/cache.cc @@ -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; diff --git a/libtransmission/fdlimit.cc b/libtransmission/fdlimit.cc index be7f84f4e..7d1fe5f52 100644 --- a/libtransmission/fdlimit.cc +++ b/libtransmission/fdlimit.cc @@ -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(&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(&i), &size) != -1) { - tr_logAddDebug("SO_RCVBUF size is %d", i); + logtrace("SO_RCVBUF size is %d", i); } buf_logged = true; diff --git a/libtransmission/handshake.cc b/libtransmission/handshake.cc index 0e12eaa61..c4aa9cdb2 100644 --- a/libtransmission/handshake.cc +++ b/libtransmission/handshake.cc @@ -4,6 +4,7 @@ // License text can be found in the licenses/ folder. #include +#include #include #include #include @@ -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{}; \ + 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); } } diff --git a/libtransmission/log.cc b/libtransmission/log.cc index 353f9a7be..dda16b892 100644 --- a/libtransmission/log.cc +++ b/libtransmission/log.cc @@ -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; diff --git a/libtransmission/log.h b/libtransmission/log.h index 6fc9019a8..115ee0ea9 100644 --- a/libtransmission/log.h +++ b/libtransmission/log.h @@ -8,7 +8,7 @@ #include /* 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); diff --git a/libtransmission/net.cc b/libtransmission/net.cc index 0a7ff56e5..a54b1fb34 100644 --- a/libtransmission/net.cc +++ b/libtransmission/net.cc @@ -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(&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 diff --git a/libtransmission/peer-io.cc b/libtransmission/peer-io.cc index 204ff41c0..9e8e33dfe 100644 --- a/libtransmission/peer-io.cc +++ b/libtransmission/peer-io.cc @@ -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{}; \ + 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; } diff --git a/libtransmission/peer-mgr.cc b/libtransmission/peer-mgr.cc index 312ce4107..f14dde8a8 100644 --- a/libtransmission/peer-mgr.cc +++ b/libtransmission/peer-mgr.cc @@ -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++; } diff --git a/libtransmission/peer-msgs.cc b/libtransmission/peer-msgs.cc index d8e4cec44..2ce7bce0e 100644 --- a/libtransmission/peer-msgs.cc +++ b/libtransmission/peer-msgs.cc @@ -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); diff --git a/libtransmission/port-forwarding.cc b/libtransmission/port-forwarding.cc index 47cd84cad..1ac8f6401 100644 --- a/libtransmission/port-forwarding.cc +++ b/libtransmission/port-forwarding.cc @@ -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); diff --git a/libtransmission/rpc-server.cc b/libtransmission/rpc-server.cc index 6d46163b3..3a1469f60 100644 --- a/libtransmission/rpc-server.cc +++ b/libtransmission/rpc-server.cc @@ -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); } } diff --git a/libtransmission/rpcimpl.cc b/libtransmission/rpcimpl.cc index e1ece7a82..0b713a3ae 100644 --- a/libtransmission/rpcimpl.cc +++ b/libtransmission/rpcimpl.cc @@ -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(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)) { diff --git a/libtransmission/session.cc b/libtransmission/session.cc index 0d6d11a35..6f23be70d 100644 --- a/libtransmission/session.cc +++ b/libtransmission/session.cc @@ -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; } } diff --git a/libtransmission/stats.cc b/libtransmission/stats.cc index 6a0b8f057..98121bd5e 100644 --- a/libtransmission/stats.cc +++ b/libtransmission/stats.cc @@ -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); } diff --git a/libtransmission/torrent-magnet.cc b/libtransmission/torrent-magnet.cc index 953244618..7ebb41284 100644 --- a/libtransmission/torrent-magnet.cc +++ b/libtransmission/torrent-magnet.cc @@ -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; } diff --git a/libtransmission/torrent.cc b/libtransmission/torrent.cc index b3c026beb..6b02dc437 100644 --- a/libtransmission/torrent.cc +++ b/libtransmission/torrent.cc @@ -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..."); } } diff --git a/libtransmission/tr-lpd.cc b/libtransmission/tr-lpd.cc index f16d39b4a..3a3405a5a 100644 --- a/libtransmission/tr-lpd.cc +++ b/libtransmission/tr-lpd.cc @@ -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"); } } diff --git a/libtransmission/tr-udp.cc b/libtransmission/tr-udp.cc index 8b9952c77..4b0e7030c 100644 --- a/libtransmission/tr-udp.cc +++ b/libtransmission/tr-udp.cc @@ -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"); } } diff --git a/libtransmission/tr-utp.cc b/libtransmission/tr-utp.cc index f870def08..71437f09f 100644 --- a/libtransmission/tr-utp.cc +++ b/libtransmission/tr-utp.cc @@ -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; } diff --git a/libtransmission/transmission.h b/libtransmission/transmission.h index c9a2eb59b..9061d340c 100644 --- a/libtransmission/transmission.h +++ b/libtransmission/transmission.h @@ -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); diff --git a/libtransmission/trevent.cc b/libtransmission/trevent.cc index f1b6b7664..aa06ae55c 100644 --- a/libtransmission/trevent.cc +++ b/libtransmission/trevent.cc @@ -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"); } /** diff --git a/libtransmission/utils.cc b/libtransmission/utils.cc index 2286c16d2..b6909c744 100644 --- a/libtransmission/utils.cc +++ b/libtransmission/utils.cc @@ -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; } diff --git a/libtransmission/web.cc b/libtransmission/web.cc index 4b1c314f8..eeffa7669 100644 --- a/libtransmission/web.cc +++ b/libtransmission/web.cc @@ -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()); } diff --git a/tests/libtransmission/announcer-test.cc b/tests/libtransmission/announcer-test.cc index ec660db74..c86e5bd2c 100644 --- a/tests/libtransmission/announcer-test.cc +++ b/tests/libtransmission/announcer-test.cc @@ -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); diff --git a/tests/libtransmission/torrent-metainfo-test.cc b/tests/libtransmission/torrent-metainfo-test.cc index 4abb782aa..4746a895d 100644 --- a/tests/libtransmission/torrent-metainfo-test.cc +++ b/tests/libtransmission/torrent-metainfo-test.cc @@ -75,7 +75,7 @@ TEST_F(TorrentMetainfoTest, bucket) { "", false }, } }; - tr_logSetLevel(TR_LOG_SILENT); + tr_logSetLevel(TR_LOG_OFF); for (auto const& test : tests) {