From d2f8e1d4e028dd6d3ca333a4659f59c1c40e5ab2 Mon Sep 17 00:00:00 2001 From: Charles Kerr Date: Fri, 11 Mar 2022 15:09:22 -0600 Subject: [PATCH] refactor: set logging levels (#2755) --- daemon/daemon.cc | 36 ++++++-- libtransmission/announcer-http.cc | 4 +- libtransmission/announcer.cc | 80 ++++++++---------- libtransmission/bandwidth.cc | 2 +- libtransmission/benc.h | 2 +- libtransmission/blocklist.cc | 13 +-- libtransmission/cache.cc | 15 ++-- libtransmission/fdlimit.cc | 35 ++++---- libtransmission/handshake.cc | 108 ++++++++++++------------ libtransmission/inout.cc | 6 +- libtransmission/log.cc | 10 +-- libtransmission/log.h | 40 ++++----- libtransmission/makemeta.cc | 4 +- libtransmission/natpmp.cc | 18 ++-- libtransmission/net.cc | 17 ++++ libtransmission/net.h | 3 + libtransmission/peer-io.cc | 123 ++++++++++++++-------------- libtransmission/peer-io.h | 2 + libtransmission/peer-mgr.cc | 47 ++++++----- libtransmission/platform.cc | 2 +- libtransmission/resume.cc | 14 ++-- libtransmission/session-id.cc | 4 +- libtransmission/session.cc | 26 +++--- libtransmission/torrent-metainfo.cc | 6 +- libtransmission/torrent.h | 8 ++ libtransmission/tr-dht.cc | 54 ++++++------ libtransmission/upnp.cc | 42 +++++----- libtransmission/utils.cc | 24 +++--- libtransmission/verify.cc | 8 +- macosx/Torrent.mm | 2 +- utils/remote.cc | 4 +- 31 files changed, 392 insertions(+), 367 deletions(-) diff --git a/daemon/daemon.cc b/daemon/daemon.cc index b686a53ee..d1021546f 100644 --- a/daemon/daemon.cc +++ b/daemon/daemon.cc @@ -54,6 +54,28 @@ static void sd_notifyf(int /*status*/, char const* /*fmt*/, ...) using namespace std::literals; +/*** +**** +***/ + +static auto constexpr CodeName = "daemon"sv; + +#undef tr_logAddError +#undef tr_logAddWarn +#undef tr_logAddInfo +#undef tr_logAddDebug +#undef tr_logAddTrace + +#define tr_logAddError(...) tr_logAddNamedError(CodeName, __VA_ARGS__) +#define tr_logAddWarn(...) tr_logAddNamedWarn(CodeName, __VA_ARGS__) +#define tr_logAddInfo(...) tr_logAddNamedInfo(CodeName, __VA_ARGS__) +#define tr_logAddDebug(...) tr_logAddNamedDebug(CodeName, __VA_ARGS__) +#define tr_logAddTrace(...) tr_logAddNamedTrace(CodeName, __VA_ARGS__) + +/*** +**** +***/ + static char constexpr MyName[] = "transmission-daemon"; static char constexpr Usage[] = "Transmission " LONG_VERSION_STRING " https://transmissionbt.com/\n" @@ -270,17 +292,17 @@ static char const* levelName(tr_log_level level) switch (level) { case TR_LOG_CRITICAL: - return "CRIT "; + return "CRT"; case TR_LOG_ERROR: - return "ERR "; + return "ERR"; case TR_LOG_WARN: - return "WARN "; + return "WRN"; case TR_LOG_DEBUG: - return "DEBUG"; + return "dbg"; case TR_LOG_TRACE: - return "TRACE"; + return "trc"; default: - return "INFO "; + return "inf"; } } @@ -678,7 +700,7 @@ static int daemon_start(void* varg, [[maybe_unused]] bool foreground) tr_formatter_speed_init(SpeedK, SpeedKStr, SpeedMStr, SpeedGStr, SpeedTStr); session = tr_sessionInit(configDir, true, settings); tr_sessionSetRPCCallback(session, on_rpc_callback, nullptr); - tr_logAddNamedInfo(nullptr, "Using settings from \"%s\"", configDir); + tr_logAddNamedInfo(MyName, "Using settings from \"%s\"", configDir); tr_sessionSaveSettings(session, configDir, settings); auto sv = std::string_view{}; diff --git a/libtransmission/announcer-http.cc b/libtransmission/announcer-http.cc index ffca9688d..c375a5a74 100644 --- a/libtransmission/announcer-http.cc +++ b/libtransmission/announcer-http.cc @@ -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_logAddMessage(__FILE__, __LINE__, TR_LOG_WARN, log_name, "%s (%d)", error->message, error->code); + tr_logAddMessage(__FILE__, __LINE__, TR_LOG_WARN, log_name, "scrape response: %s (%d)", error->message, error->code); tr_error_clear(&error); } } @@ -473,7 +473,7 @@ static void onScrapeDone(tr_web::FetchResponse const& web_response) auto const* const response_str = tr_webGetResponseStr(status); response.errmsg = tr_strvJoin("Tracker HTTP response "sv, std::to_string(status), " ("sv, response_str, ")"sv); } - else + else if (!std::empty(body)) { tr_announcerParseHttpScrapeResponse(response, body, data->log_name); } diff --git a/libtransmission/announcer.cc b/libtransmission/announcer.cc index effe9324f..67f359393 100644 --- a/libtransmission/announcer.cc +++ b/libtransmission/announcer.cc @@ -38,21 +38,10 @@ using namespace std::literals; -#define logimpl(tier, level, ...) \ - do \ - { \ - if (tr_logLevelIsActive(level)) \ - { \ - auto name = std::array{}; \ - tier->buildLogName(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__) +#define tr_logAddErrorTier(tier, ...) tr_logAddNamedError(tier->buildLogName().c_str(), __VA_ARGS__) +#define tr_logAddWarnTier(tier, ...) tr_logAddNamedWarn(tier->buildLogName().c_str(), __VA_ARGS__) +#define tr_logAddDebugTier(tier, ...) tr_logAddNamedDebug(tier->buildLogName().c_str(), __VA_ARGS__) +#define tr_logAddTraceTier(tier, ...) tr_logAddNamedTrace(tier->buildLogName().c_str(), __VA_ARGS__) /* unless the tracker says otherwise, rescrape this frequently */ static auto constexpr DefaultScrapeIntervalSec = int{ 60 * 30 }; @@ -401,12 +390,19 @@ struct tr_tier return std::nullopt; } + [[nodiscard]] std::string buildLogName() const + { + auto buf = std::array{}; + buildLogName(std::data(buf), std::size(buf)); + return std::string{ std::data(buf) }; + } + void buildLogName(char* buf, size_t buflen) const { auto const* const torrent_name = tr_torrentName(tor); auto const* const current_tracker = currentTracker(); auto const host_sv = current_tracker == nullptr ? "?"sv : current_tracker->host.sv(); - tr_snprintf(buf, buflen, "[%s---%" TR_PRIsv "]", torrent_name, TR_PRIsv_ARG(host_sv)); + tr_snprintf(buf, buflen, "%s at %" TR_PRIsv, torrent_name, TR_PRIsv_ARG(host_sv)); } [[nodiscard]] bool canManualAnnounce() const @@ -658,7 +654,7 @@ static void publishPeerCounts(tr_tier* tier, int seeders, int leechers) e.messageType = TR_TRACKER_COUNTS; e.seeders = seeders; e.leechers = leechers; - logdbg(tier, "peer counts: %d seeders, %d leechers.", seeders, leechers); + tr_logAddDebugTier(tier, "peer counts: %d seeders, %d leechers.", seeders, leechers); (*tier->tor->torrent_announcer->callback)(tier->tor, &e, nullptr); } @@ -673,7 +669,7 @@ static void publishPeersPex(tr_tier* tier, int seeders, int leechers, std::vecto e.seeders = seeders; e.leechers = leechers; e.pex = pex; - logdbg( + tr_logAddDebugTier( tier, "tracker knows of %d seeders and %d leechers and gave a list of %zu peers.", seeders, @@ -725,16 +721,13 @@ time_t tr_announcerNextManualAnnounce(tr_torrent const* tor) return ret; } -static void logtrace_tier_announce_queue(tr_tier const* tier) +static void tr_logAddTrace_tier_announce_queue(tr_tier const* tier) { if (!tr_logLevelIsActive(TR_LOG_TRACE)) { 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) { @@ -743,8 +736,8 @@ static void logtrace_tier_announce_queue(tr_tier const* tier) 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()); + auto const str = evbuffer_free_to_str(buf); + tr_logAddTraceTier(tier, "%s", str.c_str()); } // higher priorities go to the front of the announce queue @@ -774,8 +767,8 @@ static void tier_announce_event_push(tr_tier* tier, tr_announce_event e, time_t { TR_ASSERT(tier != nullptr); - logtrace_tier_announce_queue(tier); - logtrace(tier, "queued \"%s\"", tr_announce_event_get_string(e)); + tr_logAddTrace_tier_announce_queue(tier); + tr_logAddTraceTier(tier, "queued \"%s\"", tr_announce_event_get_string(e)); auto& events = tier->announce_events; if (!std::empty(events)) @@ -804,8 +797,8 @@ static void tier_announce_event_push(tr_tier* tier, tr_announce_event e, time_t tier->announceAt = announceAt; tier_update_announce_priority(tier); - logtrace_tier_announce_queue(tier); - logtrace(tier, "announcing in %d seconds", (int)difftime(announceAt, tr_time())); + tr_logAddTrace_tier_announce_queue(tier); + tr_logAddTraceTier(tier, "announcing in %d seconds", (int)difftime(announceAt, tr_time())); } static auto tier_announce_event_pull(tr_tier* tier) @@ -961,18 +954,15 @@ static void on_announce_error(tr_tier* tier, char const* err, tr_announce_event /* switch to the next tracker */ current_tracker = tier->useNextTracker(); - auto const* const host_cstr = current_tracker->host.c_str(); if (isUnregistered(err)) { - logerr(tier, "Tracker '%s' announce error: %s", host_cstr, err); - tr_logAddTorInfo(tier->tor, "Tracker '%s' announce error: %s", host_cstr, err); + tr_logAddErrorTier(tier, "announce error: %s", err); } else { /* schedule a reannounce */ int const interval = current_tracker->getRetryInterval(); - 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); + tr_logAddWarnTier(tier, "announce error: %s (Retrying in %d seconds)", err, interval); tier_announce_event_push(tier, e, tr_time() + interval); } } @@ -988,7 +978,7 @@ static void on_announce_done(tr_announce_response const* response, void* vdata) if (tier != nullptr) { - logtrace( + tr_logAddTraceTier( tier, "Got announce response: " "connected:%d " @@ -1089,7 +1079,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; - logtrace(tier, "tracker gave \"%s\"", warning.c_str()); + tr_logAddTraceTier(tier, "tracker gave \"%s\"", warning.c_str()); publishWarning(tier, warning); } else @@ -1125,10 +1115,9 @@ static void on_announce_done(tr_announce_response const* response, void* vdata) then a separate scrape isn't needed */ if (scrape_fields >= 3 || (scrape_fields >= 1 && tracker->scrape_info == nullptr)) { - tr_logAddTorDbg( - tier->tor, - "Announce response contained scrape info; " - "rescheduling next scrape to %d seconds from now.", + tr_logAddTraceTier( + tier, + "Announce response has scrape info; bumping next scrape to %d seconds from now.", tier->scrapeIntervalSec); tier->scheduleNextScrape(); tier->lastScrapeTime = now; @@ -1156,7 +1145,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; - logtrace(tier, "Sending periodic reannounce in %d seconds", i); + tr_logAddTraceTier(tier, "Sending periodic reannounce in %d seconds", i); tier_announce_event_push(tier, TR_ANNOUNCE_EVENT_NONE, now + i); } } @@ -1194,7 +1183,7 @@ static void announce_request_delegate( } else { - tr_logAddError("Unsupported url: %" TR_PRIsv, TR_PRIsv_ARG(announce_sv)); + tr_logAddWarn("Unsupported url: %" TR_PRIsv, TR_PRIsv_ARG(announce_sv)); delete callback_data; } @@ -1261,8 +1250,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(); - 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); + tr_logAddDebugTier(tier, "Tracker '%s' scrape error: %s (Retrying in %zu seconds)", host_cstr, errmsg, (size_t)interval); tier->lastScrapeSucceeded = false; tier->scheduleNextScrape(interval); } @@ -1325,7 +1313,7 @@ static void on_scrape_done(tr_scrape_response const* response, void* vsession) auto const scrape_url_sv = response->scrape_url.sv(); - logtrace( + tr_logAddTraceTier( tier, "scraped url:%" TR_PRIsv " -- " @@ -1369,7 +1357,7 @@ static void on_scrape_done(tr_scrape_response const* response, void* vsession) tier->lastScrapeSucceeded = true; tier->scrapeIntervalSec = std::max(int{ DefaultScrapeIntervalSec }, response->min_request_interval); tier->scheduleNextScrape(); - tr_logAddTorDbg(tier->tor, "Scrape successful. Rescraping in %d seconds.", tier->scrapeIntervalSec); + tr_logAddTraceTier(tier, "Scrape successful. Rescraping in %d seconds.", tier->scrapeIntervalSec); if (tr_tracker* const tracker = tier->currentTracker(); tracker != nullptr) { @@ -1578,7 +1566,7 @@ static void scrapeAndAnnounceMore(tr_announcer* announcer) for (auto*& tier : announce_me) { - tr_logAddTorDbg(tier->tor, "%s", "Announcing to tracker"); + tr_logAddTraceTier(tier, "%s", "Announcing to tracker"); tierAnnounce(announcer, tier); } } diff --git a/libtransmission/bandwidth.cc b/libtransmission/bandwidth.cc index b7bc4b5a0..341466d19 100644 --- a/libtransmission/bandwidth.cc +++ b/libtransmission/bandwidth.cc @@ -14,7 +14,7 @@ #include "tr-assert.h" #include "utils.h" -#define logtrace(...) tr_logAddMessage(__FILE__, __LINE__, TR_LOG_TRACE, nullptr, __VA_ARGS__) +#define logtrace(...) tr_logAddMessage(__FILE__, __LINE__, TR_LOG_TRACE, "", __VA_ARGS__) /*** **** diff --git a/libtransmission/benc.h b/libtransmission/benc.h index 374900a71..0674db8d2 100644 --- a/libtransmission/benc.h +++ b/libtransmission/benc.h @@ -378,7 +378,7 @@ bool parse( if (stack.stack[0].n_children_walked == 0) { err = EILSEQ; - tr_error_set(error, err, "no data found"); + tr_error_set(error, err, "no bencoded data to parse"); errno = err; return false; } diff --git a/libtransmission/blocklist.cc b/libtransmission/blocklist.cc index 5c5c8d474..17b352852 100644 --- a/libtransmission/blocklist.cc +++ b/libtransmission/blocklist.cc @@ -9,6 +9,7 @@ #include #include "transmission.h" + #include "blocklist.h" #include "error.h" #include "file.h" @@ -72,7 +73,7 @@ static void blocklistLoad(tr_blocklistFile* b) auto const fd = tr_sys_file_open(b->filename, TR_SYS_FILE_READ, 0, &error); if (fd == TR_BAD_SYS_FILE) { - tr_logAddError(err_fmt, b->filename, error->message); + tr_logAddWarn(err_fmt, b->filename, error->message); tr_error_free(error); return; } @@ -80,7 +81,7 @@ static void blocklistLoad(tr_blocklistFile* b) b->rules = static_cast(tr_sys_file_map_for_reading(fd, 0, byteCount, &error)); if (b->rules == nullptr) { - tr_logAddError(err_fmt, b->filename, error->message); + tr_logAddWarn(err_fmt, b->filename, error->message); tr_sys_file_close(fd, nullptr); tr_error_free(error); return; @@ -370,7 +371,7 @@ int tr_blocklistFileSetContent(tr_blocklistFile* b, char const* filename) auto const in = tr_sys_file_open(filename, TR_SYS_FILE_READ, 0, &error); if (in == TR_BAD_SYS_FILE) { - tr_logAddError(err_fmt, filename, error->message); + tr_logAddWarn(err_fmt, filename, error->message); tr_error_free(error); return 0; } @@ -380,7 +381,7 @@ int tr_blocklistFileSetContent(tr_blocklistFile* b, char const* filename) auto const out = tr_sys_file_open(b->filename, TR_SYS_FILE_WRITE | TR_SYS_FILE_CREATE | TR_SYS_FILE_TRUNCATE, 0666, &error); if (out == TR_BAD_SYS_FILE) { - tr_logAddError(err_fmt, b->filename, error->message); + tr_logAddWarn(err_fmt, b->filename, error->message); tr_error_free(error); tr_sys_file_close(in, nullptr); return 0; @@ -396,7 +397,7 @@ int tr_blocklistFileSetContent(tr_blocklistFile* b, char const* filename) if (!parseLine(line, &range)) { /* don't try to display the actual lines - it causes issues */ - tr_logAddError(_("blocklist skipped invalid address at line %d"), inCount); + tr_logAddWarn(_("blocklist skipped invalid address at line %d"), inCount); continue; } @@ -453,7 +454,7 @@ int tr_blocklistFileSetContent(tr_blocklistFile* b, char const* filename) if (!tr_sys_file_write(out, ranges, sizeof(struct tr_ipv4_range) * ranges_count, nullptr, &error)) { - tr_logAddError(_("Couldn't save file \"%1$s\": %2$s"), b->filename, error->message); + tr_logAddWarn(_("Couldn't save file \"%1$s\": %2$s"), b->filename, error->message); tr_error_free(error); } else diff --git a/libtransmission/cache.cc b/libtransmission/cache.cc index 7d44861c2..50f05249b 100644 --- a/libtransmission/cache.cc +++ b/libtransmission/cache.cc @@ -18,9 +18,7 @@ #include "trevent.h" #include "utils.h" -static char constexpr MyName[] = "Cache"; - -#define logtrace(...) tr_logAddMessage(__FILE__, __LINE__, TR_LOG_TRACE, nullptr, __VA_ARGS__) +auto constexpr CodeName = std::string_view{ "cache" }; /**** ***** @@ -244,8 +242,8 @@ int tr_cacheSetLimit(tr_cache* cache, int64_t max_bytes) cache->max_bytes = max_bytes; cache->max_blocks = getMaxBlocks(max_bytes); - tr_logAddNamedDbg( - MyName, + tr_logAddNamedDebug( + CodeName, "Maximum cache size set to %s (%d blocks)", tr_formatter_mem_B(cache->max_bytes).c_str(), cache->max_blocks); @@ -409,7 +407,12 @@ 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)); - logtrace("flushing file %d from cache to disk: blocks [%zu...%zu)", (int)i, (size_t)begin, (size_t)end); + tr_logAddNamedTrace( + CodeName, + "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 7d1fe5f52..897c15030 100644 --- a/libtransmission/fdlimit.cc +++ b/libtransmission/fdlimit.cc @@ -21,11 +21,6 @@ #include "tr-assert.h" #include "utils.h" // tr_time() -#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__) - /*** **** **** Local Files @@ -46,7 +41,7 @@ static bool preallocate_file_sparse(tr_sys_file_t fd, uint64_t length, tr_error* return true; } - logdbg("Preallocating (sparse, normal) failed (%d): %s", my_error->code, my_error->message); + tr_logAddDebug("Preallocating (sparse, normal) failed (%d): %s", my_error->code, my_error->message); if (!TR_ERROR_IS_ENOSPC(my_error->code)) { @@ -60,7 +55,7 @@ static bool preallocate_file_sparse(tr_sys_file_t fd, uint64_t length, tr_error* return true; } - logdbg("Preallocating (sparse, fallback) failed (%d): %s", my_error->code, my_error->message); + tr_logAddDebug("Preallocating (sparse, fallback) failed (%d): %s", my_error->code, my_error->message); } tr_error_propagate(error, &my_error); @@ -81,7 +76,7 @@ static bool preallocate_file_full(tr_sys_file_t fd, uint64_t length, tr_error** return true; } - logdbg("Preallocating (full, normal) failed (%d): %s", my_error->code, my_error->message); + tr_logAddDebug("Preallocating (full, normal) failed (%d): %s", my_error->code, my_error->message); if (!TR_ERROR_IS_ENOSPC(my_error->code)) { @@ -104,7 +99,7 @@ static bool preallocate_file_full(tr_sys_file_t fd, uint64_t length, tr_error** return true; } - logdbg("Preallocating (full, fallback) failed (%d): %s", my_error->code, my_error->message); + tr_logAddDebug("Preallocating (full, fallback) failed (%d): %s", my_error->code, my_error->message); } tr_error_propagate(error, &my_error); @@ -171,13 +166,13 @@ static int cached_file_open( if (dir == nullptr) { - logerr(_("Couldn't get directory for \"%1$s\": %2$s"), filename, error->message); + tr_logAddError(_("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)) { - logerr(_("Couldn't create \"%1$s\": %2$s"), dir, error->message); + tr_logAddError(_("Couldn't create \"%1$s\": %2$s"), dir, error->message); tr_free(dir); goto FAIL; } @@ -198,7 +193,7 @@ static int cached_file_open( if (fd == TR_BAD_SYS_FILE) { - logerr(_("Couldn't open \"%1$s\": %2$s"), filename, error->message); + tr_logAddError(_("Couldn't open \"%1$s\": %2$s"), filename, error->message); goto FAIL; } @@ -222,7 +217,7 @@ static int cached_file_open( if (!success) { - logwarn( + tr_logAddWarn( _("Couldn't preallocate file \"%1$s\" (%2$s, size: %3$" PRIu64 "): %4$s"), filename, type, @@ -231,7 +226,7 @@ static int cached_file_open( goto FAIL; } - logdbg(_("Preallocated file \"%1$s\" (%2$s, size: %3$" PRIu64 ")"), filename, type, file_size); + tr_logAddDebug(_("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. @@ -242,7 +237,7 @@ static int cached_file_open( */ if (resize_needed && !tr_sys_file_truncate(fd, file_size, &error)) { - logwarn(_("Couldn't truncate \"%1$s\": %2$s"), filename, error->message); + tr_logAddWarn(_("Couldn't truncate \"%1$s\": %2$s"), filename, error->message); goto FAIL; } @@ -482,11 +477,11 @@ tr_sys_file_t tr_fdFileCheckout( return TR_BAD_SYS_FILE; } - logtrace("opened '%s' writable %c", filename, writable ? 'y' : 'n'); + tr_logAddTrace("opened '%s' writable %c", filename, writable ? 'y' : 'n'); o->is_writable = writable; } - logtrace("checking out '%s'", filename); + tr_logAddTrace("checking out '%s'", filename); o->torrent_id = torrent_id; o->file_index = i; o->used_at = tr_time(); @@ -514,7 +509,7 @@ tr_socket_t tr_fdSocketCreate(tr_session* session, int domain, int type) if ((s == TR_BAD_SOCKET) && (sockerrno != EAFNOSUPPORT)) { - logwarn(_("Couldn't create socket: %s"), tr_net_strerror(sockerrno).c_str()); + tr_logAddWarn(_("Couldn't create socket: %s"), tr_net_strerror(sockerrno).c_str()); } } @@ -536,7 +531,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) { - logtrace("SO_SNDBUF size is %d", i); + tr_logAddTrace("SO_SNDBUF size is %d", i); } i = 0; @@ -544,7 +539,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) { - logtrace("SO_RCVBUF size is %d", i); + tr_logAddTrace("SO_RCVBUF size is %d", i); } buf_logged = true; diff --git a/libtransmission/handshake.cc b/libtransmission/handshake.cc index c4aa9cdb2..7b3d0fab9 100644 --- a/libtransmission/handshake.cc +++ b/libtransmission/handshake.cc @@ -131,16 +131,7 @@ struct tr_handshake *** **/ -#define logtrace(handshake, ...) \ - do \ - { \ - if (tr_logLevelIsActive(TR_LOG_TRACE)) \ - { \ - 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) +#define tr_logAddTraceHand(handshake, ...) tr_logAddNamedTrace(handshake->io->addrStr(), __VA_ARGS__) static char const* getStateName(handshake_state_t const state) { @@ -164,7 +155,7 @@ static char const* getStateName(handshake_state_t const state) static void setState(tr_handshake* handshake, handshake_state_t state) { - logtrace(handshake, "setting to state [%s]", getStateName(state)); + tr_logAddTraceHand(handshake, "setting to state [%s]", getStateName(state)); handshake->state = state; } @@ -223,7 +214,7 @@ static handshake_parse_err_t parseHandshake(tr_handshake* handshake, struct evbu uint8_t name[HANDSHAKE_NAME_LEN]; uint8_t reserved[HANDSHAKE_FLAGS_LEN]; - logtrace(handshake, "payload: need %d, got %zu", HANDSHAKE_SIZE, evbuffer_get_length(inbuf)); + tr_logAddTraceHand(handshake, "payload: need %d, got %zu", HANDSHAKE_SIZE, evbuffer_get_length(inbuf)); if (evbuffer_get_length(inbuf) < HANDSHAKE_SIZE) { @@ -246,7 +237,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) { - logtrace(handshake, "peer returned the wrong hash. wtf?"); + tr_logAddTraceHand(handshake, "peer returned the wrong hash. wtf?"); return HANDSHAKE_BAD_TORRENT; } @@ -256,11 +247,11 @@ static handshake_parse_err_t parseHandshake(tr_handshake* handshake, struct evbu handshake->peer_id = peer_id; /* peer id */ - logtrace(handshake, "peer-id is [%" TR_PRIsv "]", TR_PRIsv_ARG(peer_id)); + tr_logAddTraceHand(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)) { - logtrace(handshake, "streuth! we've connected to ourselves."); + tr_logAddTraceHand(handshake, "streuth! we've connected to ourselves."); return HANDSHAKE_PEER_IS_SELF; } @@ -384,7 +375,7 @@ static ReadState readYb(tr_handshake* handshake, struct evbuffer* inbuf) } } - logtrace(handshake, "got an %s handshake", (isEncrypted ? "encrypted" : "plain")); + tr_logAddTraceHand(handshake, "got an %s handshake", (isEncrypted ? "encrypted" : "plain")); tr_peerIoSetEncryption(handshake->io, isEncrypted ? PEER_ENCRYPTION_RC4 : PEER_ENCRYPTION_NONE); @@ -413,7 +404,7 @@ static ReadState readYb(tr_handshake* handshake, struct evbuffer* inbuf) auto const req1 = computeRequestHash(handshake, "req1"sv); if (!req1) { - logtrace(handshake, "error while computing req1 hash after Yb"); + tr_logAddTraceHand(handshake, "error while computing req1 hash after Yb"); return tr_handshakeDone(handshake, false); } evbuffer_add(outbuf, std::data(*req1), std::size(*req1)); @@ -425,7 +416,7 @@ static ReadState readYb(tr_handshake* handshake, struct evbuffer* inbuf) auto const req3 = computeRequestHash(handshake, "req3"sv); if (!req2 || !req3) { - logtrace(handshake, "error while computing req2/req3 hash after Yb"); + tr_logAddTraceHand(handshake, "error while computing req2/req3 hash after Yb"); return tr_handshakeDone(handshake, false); } @@ -491,7 +482,7 @@ static ReadState readVC(tr_handshake* handshake, struct evbuffer* inbuf) { if (evbuffer_get_length(inbuf) < VC_LENGTH) { - logtrace(handshake, "not enough bytes... returning read_more"); + tr_logAddTraceHand(handshake, "not enough bytes... returning read_more"); return READ_LATER; } @@ -507,7 +498,7 @@ static ReadState readVC(tr_handshake* handshake, struct evbuffer* inbuf) evbuffer_drain(inbuf, 1); } - logtrace(handshake, "got it!"); + tr_logAddTraceHand(handshake, "got it!"); evbuffer_drain(inbuf, key_len); setState(handshake, AWAITING_CRYPTO_SELECT); return READ_NOW; @@ -525,21 +516,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; - logtrace(handshake, "crypto select is %d", (int)crypto_select); + tr_logAddTraceHand(handshake, "crypto select is %d", (int)crypto_select); if ((crypto_select & getCryptoProvide(handshake)) == 0) { - logtrace(handshake, "peer selected an encryption option we didn't offer"); + tr_logAddTraceHand(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); - logtrace(handshake, "pad_d_len is %d", (int)pad_d_len); + tr_logAddTraceHand(handshake, "pad_d_len is %d", (int)pad_d_len); if (pad_d_len > 512) { - logtrace(handshake, "encryption handshake: pad_d_len is too long"); + tr_logAddTraceHand(handshake, "encryption handshake: pad_d_len is too long"); return tr_handshakeDone(handshake, false); } @@ -553,7 +544,7 @@ static ReadState readPadD(tr_handshake* handshake, struct evbuffer* inbuf) { size_t const needlen = handshake->pad_d_len; - logtrace(handshake, "pad d: need %zu, got %zu", needlen, evbuffer_get_length(inbuf)); + tr_logAddTraceHand(handshake, "pad d: need %zu, got %zu", needlen, evbuffer_get_length(inbuf)); if (evbuffer_get_length(inbuf) < needlen) { @@ -576,7 +567,7 @@ static ReadState readPadD(tr_handshake* handshake, struct evbuffer* inbuf) static ReadState readHandshake(tr_handshake* handshake, struct evbuffer* inbuf) { - logtrace(handshake, "payload: need %d, got %zu", INCOMING_HANDSHAKE_LEN, evbuffer_get_length(inbuf)); + tr_logAddTraceHand(handshake, "payload: need %d, got %zu", INCOMING_HANDSHAKE_LEN, evbuffer_get_length(inbuf)); if (evbuffer_get_length(inbuf) < INCOMING_HANDSHAKE_LEN) { @@ -593,7 +584,7 @@ static ReadState readHandshake(tr_handshake* handshake, struct evbuffer* inbuf) if (handshake->encryptionMode == TR_ENCRYPTION_REQUIRED) { - logtrace(handshake, "peer is unencrypted, and we're disallowing that"); + tr_logAddTraceHand(handshake, "peer is unencrypted, and we're disallowing that"); return tr_handshakeDone(handshake, false); } } @@ -603,7 +594,7 @@ static ReadState readHandshake(tr_handshake* handshake, struct evbuffer* inbuf) if (tr_peerIoIsIncoming(handshake->io)) { - logtrace(handshake, "I think peer is sending us an encrypted handshake..."); + tr_logAddTraceHand(handshake, "I think peer is sending us an encrypted handshake..."); setState(handshake, AWAITING_YA); return READ_NOW; } @@ -612,7 +603,7 @@ static ReadState readHandshake(tr_handshake* handshake, struct evbuffer* inbuf) if (pstrlen != 19) { - logtrace(handshake, "I think peer has sent us a corrupt handshake..."); + tr_logAddTraceHand(handshake, "I think peer has sent us a corrupt handshake..."); return tr_handshakeDone(handshake, false); } } @@ -650,7 +641,7 @@ static ReadState readHandshake(tr_handshake* handshake, struct evbuffer* inbuf) { if (!handshake->session->torrents().contains(hash)) { - logtrace(handshake, "peer is trying to connect to us for a torrent we don't have."); + tr_logAddTraceHand(handshake, "peer is trying to connect to us for a torrent we don't have."); return tr_handshakeDone(handshake, false); } @@ -661,7 +652,7 @@ static ReadState readHandshake(tr_handshake* handshake, struct evbuffer* inbuf) auto const torrent_hash = tr_peerIoGetTorrentHash(handshake->io); if (!torrent_hash || *torrent_hash != hash) { - logtrace(handshake, "peer returned the wrong hash. wtf?"); + tr_logAddTraceHand(handshake, "peer returned the wrong hash. wtf?"); return tr_handshakeDone(handshake, false); } } @@ -700,7 +691,7 @@ static ReadState readPeerId(tr_handshake* handshake, struct evbuffer* inbuf) char client[128] = {}; tr_clientForId(client, sizeof(client), peer_id); - logtrace(handshake, "peer-id is [%s] ... isIncoming is %d", client, tr_peerIoIsIncoming(handshake->io)); + tr_logAddTraceHand(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); @@ -712,7 +703,7 @@ static ReadState readPeerId(tr_handshake* handshake, struct evbuffer* inbuf) static ReadState readYa(tr_handshake* handshake, struct evbuffer* inbuf) { - logtrace(handshake, "in readYa... need %d, have %zu", KEY_LEN, evbuffer_get_length(inbuf)); + tr_logAddTraceHand(handshake, "in readYa... need %d, have %zu", KEY_LEN, evbuffer_get_length(inbuf)); if (evbuffer_get_length(inbuf) < KEY_LEN) { @@ -731,13 +722,13 @@ static ReadState readYa(tr_handshake* handshake, struct evbuffer* inbuf) auto req1 = computeRequestHash(handshake, "req1"sv); if (!req1) { - logtrace(handshake, "error while computing req1 hash after Ya"); + tr_logAddTraceHand(handshake, "error while computing req1 hash after Ya"); return tr_handshakeDone(handshake, false); } handshake->myReq1 = *req1; /* send our public key to the peer */ - logtrace(handshake, "sending B->A: Diffie Hellman Yb, PadB"); + tr_logAddTraceHand(handshake, "sending B->A: Diffie Hellman Yb, PadB"); uint8_t outbuf[KEY_LEN + PadB_MAXLEN]; uint8_t* walk = outbuf; int len = 0; @@ -764,7 +755,7 @@ static ReadState readPadA(tr_handshake* handshake, struct evbuffer* inbuf) if (ptr.pos != -1) /* match */ { evbuffer_drain(inbuf, ptr.pos); - logtrace(handshake, "found it... looking setting to awaiting_crypto_provide"); + tr_logAddTraceHand(handshake, "found it... looking setting to awaiting_crypto_provide"); setState(handshake, AWAITING_CRYPTO_PROVIDE); return READ_NOW; } @@ -799,14 +790,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 */ - logtrace(handshake, "reading obfuscated torrent hash..."); + tr_logAddTraceHand(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) { - logtrace(handshake, "error while computing req3 hash after req2"); + tr_logAddTraceHand(handshake, "error while computing req3 hash after req2"); return tr_handshakeDone(handshake, false); } @@ -820,18 +811,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)); - logtrace(handshake, "got INCOMING connection's encrypted handshake for torrent [%s]", tr_torrentName(tor)); + tr_logAddTraceHand(handshake, "got INCOMING connection's encrypted handshake for torrent [%s]", tr_torrentName(tor)); tr_peerIoSetTorrentHash(handshake->io, tor->infoHash()); if (clientIsSeed && peerIsSeed) { - logtrace(handshake, "another seed tried to reconnect to us!"); + tr_logAddTraceHand(handshake, "another seed tried to reconnect to us!"); return tr_handshakeDone(handshake, false); } } else { - logtrace(handshake, "can't find that torrent..."); + tr_logAddTraceHand(handshake, "can't find that torrent..."); return tr_handshakeDone(handshake, false); } @@ -843,10 +834,10 @@ static ReadState readCryptoProvide(tr_handshake* handshake, struct evbuffer* inb tr_peerIoReadUint32(handshake->io, inbuf, &crypto_provide); handshake->crypto_provide = crypto_provide; - logtrace(handshake, "crypto_provide is %d", (int)crypto_provide); + tr_logAddTraceHand(handshake, "crypto_provide is %d", (int)crypto_provide); tr_peerIoReadUint16(handshake->io, inbuf, &padc_len); - logtrace(handshake, "padc is %d", (int)padc_len); + tr_logAddTraceHand(handshake, "padc is %d", (int)padc_len); handshake->pad_c_len = padc_len; setState(handshake, AWAITING_PAD_C); return READ_NOW; @@ -868,7 +859,7 @@ static ReadState readPadC(tr_handshake* handshake, struct evbuffer* inbuf) /* read ia_len */ tr_peerIoReadUint16(handshake->io, inbuf, &ia_len); - logtrace(handshake, "ia_len is %d", (int)ia_len); + tr_logAddTraceHand(handshake, "ia_len is %d", (int)ia_len); handshake->ia_len = ia_len; setState(handshake, AWAITING_IA); return READ_NOW; @@ -878,7 +869,7 @@ static ReadState readIA(tr_handshake* handshake, struct evbuffer const* inbuf) { size_t const needlen = handshake->ia_len; - logtrace(handshake, "reading IA... have %zu, need %zu", evbuffer_get_length(inbuf), needlen); + tr_logAddTraceHand(handshake, "reading IA... have %zu, need %zu", evbuffer_get_length(inbuf), needlen); if (evbuffer_get_length(inbuf) < needlen) { @@ -897,7 +888,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); - logtrace(handshake, "sending vc"); + tr_logAddTraceHand(handshake, "sending vc"); } /* send crypto_select */ @@ -905,17 +896,17 @@ static ReadState readIA(tr_handshake* handshake, struct evbuffer const* inbuf) if (crypto_select != 0) { - logtrace(handshake, "selecting crypto mode '%d'", (int)crypto_select); + tr_logAddTraceHand(handshake, "selecting crypto mode '%d'", (int)crypto_select); evbuffer_add_uint32(outbuf, crypto_select); } else { - logtrace(handshake, "peer didn't offer an encryption mode we like."); + tr_logAddTraceHand(handshake, "peer didn't offer an encryption mode we like."); evbuffer_free(outbuf); return tr_handshakeDone(handshake, false); } - logtrace(handshake, "sending pad d"); + tr_logAddTraceHand(handshake, "sending pad d"); /* ENCRYPT(VC, crypto_provide, len(PadD), PadD * PadD is reserved for future extensions to the handshake... @@ -932,7 +923,7 @@ static ReadState readIA(tr_handshake* handshake, struct evbuffer const* inbuf) tr_peerIoSetEncryption(handshake->io, PEER_ENCRYPTION_NONE); } - logtrace(handshake, "sending handshake"); + tr_logAddTraceHand(handshake, "sending handshake"); /* send our handshake */ { @@ -960,7 +951,7 @@ static ReadState readPayloadStream(tr_handshake* handshake, struct evbuffer* inb { size_t const needlen = HANDSHAKE_SIZE; - logtrace(handshake, "reading payload stream... have %zu, need %zu", evbuffer_get_length(inbuf), needlen); + tr_logAddTraceHand(handshake, "reading payload stream... have %zu, need %zu", evbuffer_get_length(inbuf), needlen); if (evbuffer_get_length(inbuf) < needlen) { @@ -969,7 +960,7 @@ static ReadState readPayloadStream(tr_handshake* handshake, struct evbuffer* inb /* parse the handshake ... */ handshake_parse_err_t const i = parseHandshake(handshake, inbuf); - logtrace(handshake, "parseHandshake returned %d", i); + tr_logAddTraceHand(handshake, "parseHandshake returned %d", i); if (i != HANDSHAKE_OK) { @@ -998,7 +989,7 @@ static ReadState canRead(tr_peerIo* io, void* vhandshake, size_t* piece) /* no piece data in handshake */ *piece = 0; - logtrace(handshake, "handling canRead; state is [%s]", getStateName(handshake->state)); + tr_logAddTraceHand(handshake, "handling canRead; state is [%s]", getStateName(handshake->state)); ReadState ret = READ_NOW; while (readyForMore) @@ -1109,7 +1100,7 @@ static void tr_handshakeFree(tr_handshake* handshake) static ReadState tr_handshakeDone(tr_handshake* handshake, bool isOK) { - logtrace(handshake, "handshakeDone: %s", isOK ? "connected" : "aborting"); + tr_logAddTraceHand(handshake, "handshakeDone: %s", isOK ? "connected" : "aborting"); tr_peerIoSetIOFuncs(handshake->io, nullptr, nullptr, nullptr, nullptr); bool const success = fireDoneFunc(handshake, isOK); @@ -1161,7 +1152,7 @@ static void gotError(tr_peerIo* io, short what, void* vhandshake) { uint8_t msg[HANDSHAKE_SIZE]; - logtrace(handshake, "handshake failed, trying plaintext..."); + tr_logAddTraceHand(handshake, "handshake failed, trying plaintext..."); buildHandshakeMessage(handshake, msg); handshake->haveSentBitTorrentHandshake = true; setReadState(handshake, AWAITING_HANDSHAKE); @@ -1169,7 +1160,12 @@ static void gotError(tr_peerIo* io, short what, void* vhandshake) } else { - logtrace(handshake, "libevent got an error what==%d, errno=%d (%s)", (int)what, errcode, tr_strerror(errcode)); + tr_logAddTraceHand( + handshake, + "libevent got an error what==%d, errno=%d (%s)", + (int)what, + errcode, + tr_strerror(errcode)); tr_handshakeDone(handshake, false); } } diff --git a/libtransmission/inout.cc b/libtransmission/inout.cc index bd801b01a..41a1746c9 100644 --- a/libtransmission/inout.cc +++ b/libtransmission/inout.cc @@ -131,7 +131,7 @@ int readOrWriteBytes( if (fd == TR_BAD_SYS_FILE) { err = errno; - tr_logAddTorErr(tor, "tr_fdFileCheckout failed for \"%s\": %s", filename.c_str(), tr_strerror(err)); + tr_logAddErrorTor(tor, "tr_fdFileCheckout failed for \"%s\": %s", filename.c_str(), tr_strerror(err)); } else if (doWrite) { @@ -160,7 +160,7 @@ int readOrWriteBytes( if (!readEntireBuf(fd, file_offset, buf, buflen, &error)) { err = error->code; - tr_logAddTorErr(tor, "read failed for \"%s\": %s", tor->fileSubpath(file_index).c_str(), error->message); + tr_logAddErrorTor(tor, "read failed for \"%s\": %s", tor->fileSubpath(file_index).c_str(), error->message); tr_error_free(error); } break; @@ -169,7 +169,7 @@ int readOrWriteBytes( if (!writeEntireBuf(fd, file_offset, buf, buflen, &error)) { err = error->code; - tr_logAddTorErr(tor, "write failed for \"%s\": %s", tor->fileSubpath(file_index).c_str(), error->message); + tr_logAddErrorTor(tor, "write failed for \"%s\": %s", tor->fileSubpath(file_index).c_str(), error->message); tr_error_free(error); } break; diff --git a/libtransmission/log.cc b/libtransmission/log.cc index dda16b892..c3a53351b 100644 --- a/libtransmission/log.cc +++ b/libtransmission/log.cc @@ -43,7 +43,7 @@ tr_log_level tr_logGetLevel() static std::recursive_mutex message_mutex_; -tr_sys_file_t tr_logGetFile() +static tr_sys_file_t tr_logGetFile() { static bool initialized = false; static tr_sys_file_t file = TR_BAD_SYS_FILE; @@ -139,7 +139,7 @@ void tr_logAddMessage( [[maybe_unused]] char const* file, [[maybe_unused]] int line, tr_log_level level, - [[maybe_unused]] char const* name, + [[maybe_unused]] std::string_view name, char const* fmt, ...) { @@ -218,7 +218,7 @@ void tr_logAddMessage( newmsg->message = tr_strndup(buf, buf_len); newmsg->file = file; newmsg->line = line; - newmsg->name = tr_strdup(name); + newmsg->name = tr_strvDup(name); *myQueueTail = newmsg; myQueueTail = &newmsg->next; @@ -247,8 +247,8 @@ void tr_logAddMessage( tr_logGetTimeStr(timestr, sizeof(timestr)); - auto const out = name != nullptr ? tr_strvJoin("["sv, timestr, "] "sv, name, ": "sv, buf) : - tr_strvJoin("["sv, timestr, "] "sv, buf); + auto const out = !std::empty(name) ? tr_strvJoin("["sv, timestr, "] "sv, name, ": "sv, buf) : + tr_strvJoin("["sv, timestr, "] "sv, buf); tr_sys_file_write_line(fp, out, nullptr); tr_sys_file_flush(fp, nullptr); } diff --git a/libtransmission/log.h b/libtransmission/log.h index 115ee0ea9..f88a4cefe 100644 --- a/libtransmission/log.h +++ b/libtransmission/log.h @@ -5,51 +5,45 @@ #pragma once -#include /* size_t */ +#include -#include "file.h" /* tr_sys_file_t */ #include "transmission.h" #define TR_LOG_MAX_QUEUE_LENGTH 10000 -tr_log_level tr_logGetLevel(void); +[[nodiscard]] tr_log_level tr_logGetLevel(void); -static inline bool tr_logLevelIsActive(tr_log_level level) +[[nodiscard]] static inline bool tr_logLevelIsActive(tr_log_level level) { return tr_logGetLevel() >= level; } -void tr_logAddMessage(char const* file, int line, tr_log_level level, char const* torrent, char const* fmt, ...) +void tr_logAddMessage(char const* file, int line, tr_log_level level, std::string_view name, char const* fmt, ...) TR_GNUC_PRINTF(5, 6); #define tr_logAddNamed(level, name, ...) \ do \ { \ - if (tr_logLevelIsActive(level)) \ + if (tr_logGetLevel() >= level) \ { \ tr_logAddMessage(__FILE__, __LINE__, level, name, __VA_ARGS__); \ } \ } while (0) -#define tr_logAddNamedError(name, ...) tr_logAddNamed(TR_LOG_ERROR, name, __VA_ARGS__) -#define tr_logAddNamedInfo(name, ...) tr_logAddNamed(TR_LOG_INFO, name, __VA_ARGS__) -#define tr_logAddNamedDbg(name, ...) tr_logAddNamed(TR_LOG_DEBUG, name, __VA_ARGS__) +#define tr_logAddNamedCritical(name, ...) tr_logAddNamed(TR_LOG_CRITICAL, (name), __VA_ARGS__) +#define tr_logAddNamedError(name, ...) tr_logAddNamed(TR_LOG_ERROR, (name), __VA_ARGS__) +#define tr_logAddNamedWarn(name, ...) tr_logAddNamed(TR_LOG_WARN, (name), __VA_ARGS__) +#define tr_logAddNamedInfo(name, ...) tr_logAddNamed(TR_LOG_INFO, (name), __VA_ARGS__) +#define tr_logAddNamedDebug(name, ...) tr_logAddNamed(TR_LOG_DEBUG, (name), __VA_ARGS__) +#define tr_logAddNamedTrace(name, ...) tr_logAddNamed(TR_LOG_TRACE, (name), __VA_ARGS__) -#define tr_logAddTor(level, tor, ...) tr_logAddNamed(level, tr_torrentName(tor), __VA_ARGS__) +#define tr_logAddCritical(...) tr_logAddNamed(TR_LOG_CRITICAL, "", __VA_ARGS__) +#define tr_logAddError(...) tr_logAddNamed(TR_LOG_ERROR, "", __VA_ARGS__) +#define tr_logAddWarn(...) tr_logAddNamed(TR_LOG_WARN, "", __VA_ARGS__) +#define tr_logAddInfo(...) tr_logAddNamed(TR_LOG_INFO, "", __VA_ARGS__) +#define tr_logAddDebug(...) tr_logAddNamed(TR_LOG_DEBUG, "", __VA_ARGS__) +#define tr_logAddTrace(...) tr_logAddNamed(TR_LOG_TRACE, "", __VA_ARGS__) -#define tr_logAddTorErr(tor, ...) tr_logAddTor(TR_LOG_ERROR, tor, __VA_ARGS__) -#define tr_logAddTorInfo(tor, ...) tr_logAddTor(TR_LOG_INFO, tor, __VA_ARGS__) -#define tr_logAddTorDbg(tor, ...) tr_logAddTor(TR_LOG_DEBUG, tor, __VA_ARGS__) - -#define tr_logAdd(level, ...) tr_logAddNamed(level, nullptr, __VA_ARGS__) - -#define tr_logAddError(...) tr_logAdd(TR_LOG_ERROR, __VA_ARGS__) -#define tr_logAddInfo(...) tr_logAdd(TR_LOG_INFO, __VA_ARGS__) -#define tr_logAddDebug(...) tr_logAdd(TR_LOG_DEBUG, __VA_ARGS__) - -tr_sys_file_t tr_logGetFile(void); - -/** @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/makemeta.cc b/libtransmission/makemeta.cc index 96ca22952..ab74ab5af 100644 --- a/libtransmission/makemeta.cc +++ b/libtransmission/makemeta.cc @@ -55,7 +55,7 @@ static struct FileList* getFiles(char const* dir, char const* base, struct FileL tr_sys_path_info info; if (tr_error* error = nullptr; !tr_sys_path_get_info(buf.c_str(), 0, &info, &error)) { - tr_logAddError(_("Torrent Creator is skipping file \"%s\": %s"), buf.c_str(), error->message); + tr_logAddWarn(_("Torrent Creator is skipping file \"%s\": %s"), buf.c_str(), error->message); tr_error_free(error); return list; } @@ -200,7 +200,7 @@ bool tr_metaInfoBuilderSetPieceSize(tr_metainfo_builder* b, uint32_t bytes) { if (!isValidPieceSize(bytes)) { - tr_logAddError( + tr_logAddWarn( _("Failed to set piece size to %s, leaving it at %s"), tr_formatter_mem_B(bytes).c_str(), tr_formatter_mem_B(b->pieceSize).c_str()); diff --git a/libtransmission/natpmp.cc b/libtransmission/natpmp.cc index 44e09b14a..466a0d5fc 100644 --- a/libtransmission/natpmp.cc +++ b/libtransmission/natpmp.cc @@ -6,6 +6,7 @@ #include #include #include +#include #include /* evutil_inet_ntop() */ @@ -22,10 +23,7 @@ static auto constexpr LifetimeSecs = uint32_t{ 3600 }; static auto constexpr CommandWaitSecs = time_t{ 8 }; -static char const* getKey() -{ - return _("Port Forwarding (NAT-PMP)"); -} +static auto constexpr CodeName = std::string_view{ "nat-pmp" }; /** *** @@ -40,12 +38,12 @@ static void logVal(char const* func, int ret) if (ret >= 0) { - tr_logAddNamedInfo(getKey(), _("%s succeeded (%d)"), func, ret); + tr_logAddNamedInfo(CodeName, _("%s succeeded (%d)"), func, ret); } else { - tr_logAddNamedDbg( - getKey(), + tr_logAddNamedDebug( + CodeName, "%s failed. Natpmp returned %d (%s); errno is %d (%s)", func, ret, @@ -112,7 +110,7 @@ tr_port_forwarding tr_natpmpPulse( { char str[128]; evutil_inet_ntop(AF_INET, &response.pnu.publicaddress.addr, str, sizeof(str)); - tr_logAddNamedInfo(getKey(), _("Found public address \"%s\""), str); + tr_logAddNamedInfo(CodeName, _("Found public address \"%s\""), str); nat->state = TR_NATPMP_IDLE; } else if (val != NATPMP_TRYAGAIN) @@ -145,7 +143,7 @@ tr_port_forwarding tr_natpmpPulse( { int const unmapped_port = resp.pnu.newportmapping.privateport; - tr_logAddNamedInfo(getKey(), _("no longer forwarding port %d"), unmapped_port); + tr_logAddNamedInfo(CodeName, _("no longer forwarding port %d"), unmapped_port); if (nat->private_port == unmapped_port) { @@ -194,7 +192,7 @@ tr_port_forwarding tr_natpmpPulse( nat->renew_time = tr_time() + (resp.pnu.newportmapping.lifetime / 2); nat->private_port = resp.pnu.newportmapping.privateport; nat->public_port = resp.pnu.newportmapping.mappedpublicport; - tr_logAddNamedInfo(getKey(), _("Port %d forwarded successfully"), nat->private_port); + tr_logAddNamedInfo(CodeName, _("Port %d forwarded successfully"), nat->private_port); } else if (val != NATPMP_TRYAGAIN) { diff --git a/libtransmission/net.cc b/libtransmission/net.cc index a54b1fb34..921fd0760 100644 --- a/libtransmission/net.cc +++ b/libtransmission/net.cc @@ -137,6 +137,23 @@ std::optional tr_address::from_string(std::string_view str) return addr; } +std::string tr_address::to_string() const +{ + auto addrbuf = std::array{}; + tr_address_to_string_with_buf(this, std::data(addrbuf), std::size(addrbuf)); + return std::data(addrbuf); +} + +std::string tr_address::to_string(tr_port port) const +{ + auto addrbuf = std::array{}; + tr_address_to_string_with_buf(this, std::data(addrbuf), std::size(addrbuf)); + + auto buf = std::array{}; + tr_snprintf(std::data(buf), std::size(buf), "[%s]:%u", std::data(addrbuf), ntohs(port)); + return std::data(buf); +} + tr_address tr_address::from_4byte_ipv4(std::string_view in) { TR_ASSERT(std::size(in) == 4); diff --git a/libtransmission/net.h b/libtransmission/net.h index d77020252..3cd41cdce 100644 --- a/libtransmission/net.h +++ b/libtransmission/net.h @@ -78,6 +78,9 @@ struct tr_address static std::optional from_string(std::string_view str); + std::string to_string() const; + std::string to_string(tr_port port) const; + tr_address_type type; union { diff --git a/libtransmission/peer-io.cc b/libtransmission/peer-io.cc index 9e8e33dfe..74e818c6b 100644 --- a/libtransmission/peer-io.cc +++ b/libtransmission/peer-io.cc @@ -41,6 +41,11 @@ #define UTP_READ_BUFFER_SIZE (256 * 1024) +#define tr_logAddErrorIo(io, ...) tr_logAddNamedError((io)->addrStr(), __VA_ARGS__) +#define tr_logAddWarnIo(io, ...) tr_logAddNamedWarn((io)->addrStr(), __VA_ARGS__) +#define tr_logAddDebugIo(io, ...) tr_logAddNamedDebug((io)->addrStr(), __VA_ARGS__) +#define tr_logAddTraceIo(io, ...) tr_logAddNamedTrace((io)->addrStr(), __VA_ARGS__) + static size_t guessPacketOverhead(size_t d) { /** @@ -68,26 +73,6 @@ static size_t guessPacketOverhead(size_t d) *** **/ -#define logimpl(io, level, ...) \ - do \ - { \ - if (tr_logLevelIsActive(level)) \ - { \ - 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__) - -/** -*** -**/ - struct tr_datatype { struct tr_datatype* next; @@ -193,7 +178,7 @@ static void didWriteWrapper(tr_peerIo* io, unsigned int bytes_transferred) static void canReadWrapper(tr_peerIo* io) { - logtrace(io, "canRead"); + tr_logAddTraceIo(io, "canRead"); tr_peerIoRef(io); @@ -278,7 +263,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); - logtrace(io, "libevent says this peer is ready to read"); + tr_logAddTraceIo(io, "libevent says this peer is ready to read"); /* if we don't have any bandwidth left, stop reading */ if (howmuch < 1) @@ -317,7 +302,7 @@ static void event_read_cb(evutil_socket_t fd, short /*event*/, void* vio) what |= BEV_EVENT_ERROR; } - logdbg(io, "event_read_cb err: res:%d, what:%hd, errno:%d (%s)", res, what, e, tr_net_strerror(e).c_str()); + tr_logAddDebugIo(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) { @@ -331,7 +316,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(); - logtrace(io, "wrote %d to peer (%s)", n, (n == -1 ? tr_net_strerror(e).c_str() : "")); + tr_logAddTraceIo(io, "wrote %d to peer (%s)", n, (n == -1 ? tr_net_strerror(e).c_str() : "")); return n; } @@ -349,7 +334,7 @@ static void event_write_cb(evutil_socket_t fd, short /*event*/, void* vio) io->pendingEvents &= ~EV_WRITE; - logtrace(io, "libevent says this peer is ready to write"); + tr_logAddTraceIo(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 */ @@ -405,7 +390,7 @@ RESCHEDULE: FAIL: auto const errmsg = tr_net_strerror(e); - logdbg(io, "event_write_cb got an err. res:%d, what:%hd, errno:%d (%s)", res, what, e, errmsg.c_str()); + tr_logAddDebugIo(io, "event_write_cb got an err. res:%d, what:%hd, errno:%d (%s)", res, what, e, errmsg.c_str()); if (io->gotError != nullptr) { @@ -435,7 +420,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); - logtrace(io, "utp_on_read got %zu bytes", buflen); + tr_logAddTraceIo(io, "utp_on_read got %zu bytes", buflen); if (rc < 0) { @@ -454,12 +439,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); - logtrace(io, "utp_on_write sending %zu bytes... evbuffer_remove returned %d", buflen, rc); + tr_logAddTraceIo(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) { - logwarn(io, "Short write: %d < %ld", rc, (long)buflen); + tr_logAddWarnIo(io, "Short write: %d < %ld", rc, (long)buflen); } didWriteWrapper(io, buflen); @@ -473,7 +458,7 @@ static size_t utp_get_rb_size(void* vio) size_t bytes = io->bandwidth->clamp(TR_DOWN, UTP_READ_BUFFER_SIZE); - logtrace(io, "utp_get_rb_size is saying it's ready to read %zu bytes", bytes); + tr_logAddTraceIo(io, "utp_get_rb_size is saying it's ready to read %zu bytes", bytes); return UTP_READ_BUFFER_SIZE - bytes; } @@ -481,7 +466,7 @@ static int tr_peerIoTryWrite(tr_peerIo* io, size_t howmuch); static void utp_on_writable(tr_peerIo* io) { - logtrace(io, "libutp says this peer is ready to write"); + tr_logAddTraceIo(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); @@ -495,12 +480,12 @@ static void utp_on_state_change(void* vio, int state) if (state == UTP_STATE_CONNECT) { - logdbg(io, "utp_on_state_change -- changed to connected"); + tr_logAddDebugIo(io, "utp_on_state_change -- changed to connected"); io->utpSupported = true; } else if (state == UTP_STATE_WRITABLE) { - logdbg(io, "utp_on_state_change -- changed to writable"); + tr_logAddDebugIo(io, "utp_on_state_change -- changed to writable"); if ((io->pendingEvents & EV_WRITE) != 0) { @@ -516,12 +501,12 @@ static void utp_on_state_change(void* vio, int state) } else if (state == UTP_STATE_DESTROYING) { - logerr(io, "Impossible state UTP_STATE_DESTROYING"); + tr_logAddErrorIo(io, "Impossible state UTP_STATE_DESTROYING"); return; } else { - logerr(io, "Unknown state %d", state); + tr_logAddErrorIo(io, "Unknown state %d", state); } } @@ -531,7 +516,7 @@ static void utp_on_error(void* vio, int errcode) TR_ASSERT(tr_isPeerIo(io)); - logdbg(io, "utp_on_error -- errcode is %d", errcode); + tr_logAddDebugIo(io, "utp_on_error -- errcode is %d", errcode); if (io->gotError != nullptr) { @@ -546,7 +531,7 @@ static void utp_on_overhead(void* vio, bool send, size_t count, int /*type*/) TR_ASSERT(tr_isPeerIo(io)); - logtrace(io, "utp_on_overhead -- count is %zu", count); + tr_logAddTraceIo(io, "utp_on_overhead -- count is %zu", count); io->bandwidth->notifyBandwidthConsumed(send ? TR_UP : TR_DOWN, count, false, tr_time_msec()); } @@ -569,7 +554,7 @@ static void dummy_write(void* /*closure*/, unsigned char* buf, size_t buflen) { /* This can very well happen if we've shut down a peer connection that had unflushed buffers.Complain and send zeroes.*/ - tr_logAddNamedDbg("UTP", "On_write called on closed socket"); + tr_logAddNamedWarn("UTP", "On_write called on closed socket"); memset(buf, 0, buflen); } @@ -627,12 +612,12 @@ static tr_peerIo* tr_peerIoNew( io->socket = socket; io->bandwidth = new Bandwidth(parent); io->bandwidth->setPeer(io); - logtrace(io, "bandwidth is %p; its parent is %p", (void*)&io->bandwidth, (void*)parent); + tr_logAddTraceIo(io, "bandwidth is %p; its parent is %p", (void*)&io->bandwidth, (void*)parent); switch (socket.type) { case TR_PEER_SOCKET_TYPE_TCP: - logtrace(io, "socket (tcp) is %" PRIdMAX, (intmax_t)socket.handle.tcp); + tr_logAddTraceIo(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; @@ -640,14 +625,14 @@ static tr_peerIo* tr_peerIoNew( #ifdef WITH_UTP case TR_PEER_SOCKET_TYPE_UTP: - logtrace(io, "socket (utp) is %p", (void*)socket.handle.utp); + tr_logAddTraceIo(io, "socket (utp) is %p", (void*)socket.handle.utp); UTP_SetSockopt(socket.handle.utp, SO_RCVBUF, UTP_READ_BUFFER_SIZE); - logtrace(io, "%s", "calling UTP_SetCallbacks &utp_function_table"); + tr_logAddTraceIo(io, "%s", "calling UTP_SetCallbacks &utp_function_table"); UTP_SetCallbacks(socket.handle.utp, &utp_function_table, io); if (!is_incoming) { - logtrace(io, "%s", "calling UTP_Connect"); + tr_logAddTraceIo(io, "%s", "calling UTP_Connect"); UTP_Connect(socket.handle.utp); } @@ -699,8 +684,7 @@ tr_peerIo* tr_peerIoNewOutgoing( if (socket.type == TR_PEER_SOCKET_TYPE_NONE) { socket = tr_netOpenPeerSocket(session, addr, port, is_seed); - logdbg( - nullptr, + tr_logAddDebug( "tr_netOpenPeerSocket returned fd %" PRIdMAX, (intmax_t)(socket.type != TR_PEER_SOCKET_TYPE_NONE ? socket.handle.tcp : TR_BAD_SOCKET)); } @@ -733,7 +717,7 @@ static void event_enable(tr_peerIo* io, short event) if ((event & EV_READ) != 0 && (io->pendingEvents & EV_READ) == 0) { - logtrace(io, "enabling ready-to-read polling"); + tr_logAddTraceIo(io, "enabling ready-to-read polling"); if (need_events) { @@ -745,7 +729,7 @@ static void event_enable(tr_peerIo* io, short event) if ((event & EV_WRITE) != 0 && (io->pendingEvents & EV_WRITE) == 0) { - logtrace(io, "enabling ready-to-write polling"); + tr_logAddTraceIo(io, "enabling ready-to-write polling"); if (need_events) { @@ -772,7 +756,7 @@ static void event_disable(tr_peerIo* io, short event) if ((event & EV_READ) != 0 && (io->pendingEvents & EV_READ) != 0) { - logtrace(io, "disabling ready-to-read polling"); + tr_logAddTraceIo(io, "disabling ready-to-read polling"); if (need_events) { @@ -784,7 +768,7 @@ static void event_disable(tr_peerIo* io, short event) if ((event & EV_WRITE) != 0 && (io->pendingEvents & EV_WRITE) != 0) { - logtrace(io, "disabling ready-to-write polling"); + tr_logAddTraceIo(io, "disabling ready-to-write polling"); if (need_events) { @@ -839,7 +823,7 @@ static void io_close_socket(tr_peerIo* io) #endif default: - logdbg(io, "unsupported peer socket type %d", io->socket.type); + tr_logAddDebugIo(io, "unsupported peer socket type %d", io->socket.type); } io->socket = {}; @@ -863,7 +847,7 @@ static void io_dtor(tr_peerIo* const io) TR_ASSERT(tr_amInEventThread(io->session)); TR_ASSERT(io->session->events != nullptr); - logdbg(io, "in tr_peerIo destructor"); + tr_logAddDebugIo(io, "in tr_peerIo destructor"); event_disable(io, EV_READ | EV_WRITE); delete io->bandwidth; io_close_socket(io); @@ -881,7 +865,7 @@ static void tr_peerIoFree(tr_peerIo* io) { if (io != nullptr) { - logdbg(io, "in tr_peerIoFree"); + tr_logAddDebugIo(io, "in tr_peerIoFree"); io->canRead = nullptr; io->didWrite = nullptr; io->gotError = nullptr; @@ -893,7 +877,7 @@ void tr_peerIoRefImpl(char const* file, int line, tr_peerIo* io) { TR_ASSERT(tr_isPeerIo(io)); - logtrace(io, "%s:%d is incrementing the IO's refcount from %d to %d", file, line, io->refCount, io->refCount + 1); + tr_logAddTraceIo(io, "%s:%d is incrementing the IO's refcount from %d to %d", file, line, io->refCount, io->refCount + 1); ++io->refCount; } @@ -902,7 +886,7 @@ void tr_peerIoUnrefImpl(char const* file, int line, tr_peerIo* io) { TR_ASSERT(tr_isPeerIo(io)); - logtrace(io, "%s:%d is decrementing the IO's refcount from %d to %d", file, line, io->refCount, io->refCount - 1); + tr_logAddTraceIo(io, "%s:%d is decrementing the IO's refcount from %d to %d", file, line, io->refCount, io->refCount - 1); if (--io->refCount == 0) { @@ -922,6 +906,11 @@ tr_address const* tr_peerIoGetAddress(tr_peerIo const* io, tr_port* port) return &io->addr; } +std::string tr_peerIo::addrStr() const +{ + return tr_isPeerIo(this) ? this->addr.to_string(this->port) : "error"; +} + char const* tr_peerIoGetAddrStr(tr_peerIo const* io, char* buf, size_t buflen) { if (tr_isPeerIo(io)) @@ -1253,7 +1242,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(); - logtrace(io, "read %d from peer (%s)", res, res == -1 ? tr_net_strerror(e).c_str() : ""); + tr_logAddTraceIo(io, "read %d from peer (%s)", res, res == -1 ? tr_net_strerror(e).c_str() : ""); if (evbuffer_get_length(io->inbuf) != 0) { @@ -1269,7 +1258,13 @@ static int tr_peerIoTryRead(tr_peerIo* io, size_t howmuch) what |= BEV_EVENT_EOF; } - logtrace(io, "tr_peerIoTryRead err: res:%d what:%hd, errno:%d (%s)", res, what, e, tr_net_strerror(e).c_str()); + tr_logAddTraceIo( + 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); } @@ -1278,7 +1273,7 @@ static int tr_peerIoTryRead(tr_peerIo* io, size_t howmuch) } default: - logdbg(io, "unsupported peer socket type %d", io->socket.type); + tr_logAddDebugIo(io, "unsupported peer socket type %d", io->socket.type); } return res; @@ -1288,7 +1283,7 @@ static int tr_peerIoTryWrite(tr_peerIo* io, size_t howmuch) { auto const old_len = size_t{ evbuffer_get_length(io->outbuf) }; - logtrace(io, "in tr_peerIoTryWrite %zu", howmuch); + tr_logAddTraceIo(io, "in tr_peerIoTryWrite %zu", howmuch); howmuch = std::min(howmuch, old_len); howmuch = io->bandwidth->clamp(TR_UP, howmuch); if (howmuch == 0) @@ -1319,7 +1314,13 @@ static int tr_peerIoTryWrite(tr_peerIo* io, size_t howmuch) { short const what = BEV_EVENT_WRITING | BEV_EVENT_ERROR; - logtrace(io, "tr_peerIoTryWrite err: res:%d, what:%hd, errno:%d (%s)", n, what, e, tr_net_strerror(e).c_str()); + tr_logAddTraceIo( + 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); } @@ -1327,7 +1328,7 @@ static int tr_peerIoTryWrite(tr_peerIo* io, size_t howmuch) } default: - logdbg(io, "unsupported peer socket type %d", io->socket.type); + tr_logAddDebugIo(io, "unsupported peer socket type %d", io->socket.type); } return n; @@ -1339,7 +1340,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); - logtrace(io, "flushing peer-io, direction:%d, limit:%zu, byte_used:%d", (int)dir, limit, bytes_used); + tr_logAddTraceIo(io, "flushing peer-io, direction:%d, limit:%zu, byte_used:%d", (int)dir, limit, bytes_used); return bytes_used; } diff --git a/libtransmission/peer-io.h b/libtransmission/peer-io.h index 1ec3571f1..78e369b4d 100644 --- a/libtransmission/peer-io.h +++ b/libtransmission/peer-io.h @@ -88,6 +88,8 @@ public: evbuffer_free(inbuf); } + std::string addrStr() const; + tr_crypto crypto; tr_address const addr; diff --git a/libtransmission/peer-mgr.cc b/libtransmission/peer-mgr.cc index f14dde8a8..0127e4b37 100644 --- a/libtransmission/peer-mgr.cc +++ b/libtransmission/peer-mgr.cc @@ -225,9 +225,8 @@ struct tr_peerMgr event* atomTimer = nullptr; }; -#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__) +#define tr_logAddDebugSwarm(swarm, ...) tr_logAddNamedDebug(tr_torrentName((swarm)->tor), __VA_ARGS__) +#define tr_logAddTraceSwarm(swarm, ...) tr_logAddNamedTrace(tr_torrentName((swarm)->tor), __VA_ARGS__) /** *** tr_peer virtual functions @@ -447,7 +446,7 @@ static constexpr bool atomIsSeed(struct peer_atom const* atom) static void atomSetSeed(tr_swarm* s, struct peer_atom* atom) { - logtraceSwarm(s, "marking peer %s as a seed", tr_atomAddrStr(atom)); + tr_logAddTraceSwarm(s, "marking peer %s as a seed", tr_atomAddrStr(atom)); atom->flags |= ADDED_F_SEED_FLAG; s->poolIsAllSeedsDirty = true; } @@ -665,14 +664,14 @@ static void refillUpkeep(evutil_socket_t /*fd*/, short /*what*/, void* vmgr) static void addStrike(tr_swarm* s, tr_peer* peer) { - logtraceSwarm(s, "increasing peer %s strike count to %d", tr_atomAddrStr(peer->atom), peer->strikes + 1); + tr_logAddTraceSwarm(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; - logtraceSwarm(s, "banning peer %s", tr_atomAddrStr(atom)); + tr_logAddTraceSwarm(s, "banning peer %s", tr_atomAddrStr(atom)); } } @@ -848,14 +847,14 @@ static void peerCallbackFunc(tr_peer* peer, tr_peer_event const* e, void* vs) { /* some protocol error from the peer */ peer->doPurge = true; - logdbgSwarm( + tr_logAddDebugSwarm( s, "setting %s doPurge flag because we got an ERANGE, EMSGSIZE, or ENOTCONN error", tr_atomAddrStr(peer->atom)); } else { - logdbgSwarm(s, "unhandled error: %s", tr_strerror(e->err)); + tr_logAddDebugSwarm(s, "unhandled error: %s", tr_strerror(e->err)); } break; @@ -922,7 +921,7 @@ static struct peer_atom* ensureAtomExists( a->blocklisted = -1; tr_ptrArrayInsertSorted(&s->pool, a, compareAtomsByAddress); - logtraceSwarm(s, "got a new atom: %s", tr_atomAddrStr(a)); + tr_logAddTraceSwarm(s, "got a new atom: %s", tr_atomAddrStr(a)); } else { @@ -1012,7 +1011,7 @@ static bool on_handshake_done(tr_handshake_result const& result) if (!result.readAnythingFromPeer) { - logtraceSwarm( + tr_logAddTraceSwarm( s, "marking peer %s as unreachable... numFails is %d", tr_atomAddrStr(atom), @@ -1045,7 +1044,7 @@ static bool on_handshake_done(tr_handshake_result const& result) if ((atom->flags2 & MyflagBanned) != 0) { - logtraceSwarm(s, "banned peer %s tried to reconnect", tr_atomAddrStr(atom)); + tr_logAddTraceSwarm(s, "banned peer %s tried to reconnect", tr_atomAddrStr(atom)); } else if (tr_peerIoIsIncoming(result.io) && getPeerCount(s) >= getMaxPeerCount(s->tor)) { @@ -1091,7 +1090,7 @@ void tr_peerMgrAddIncoming(tr_peerMgr* manager, tr_address const* addr, tr_port if (tr_sessionIsAddressBlocked(session, addr)) { - tr_logAddDebug("Banned IP address \"%s\" tried to connect to us", tr_address_to_string(addr)); + tr_logAddTrace("Banned IP address \"%s\" tried to connect to us", tr_address_to_string(addr)); tr_netClosePeerSocket(session, socket); } else if (manager->incoming_handshakes.count(*addr) > 0) @@ -1206,7 +1205,7 @@ void tr_peerMgrGotBadPiece(tr_torrent* tor, tr_piece_index_t pieceIndex) if (peer->blame.test(pieceIndex)) { - logtraceSwarm( + tr_logAddTraceSwarm( s, "peer %s contributed to corrupt piece (%d); now has %d strikes", tr_atomAddrStr(peer->atom), @@ -1906,7 +1905,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; - logtraceSwarm( + tr_logAddTraceSwarm( s, "cancel rate is %.3f -- reducing the number of peers we're interested in by %.0f percent", cancelRate, @@ -1923,7 +1922,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; - logtraceSwarm( + tr_logAddTraceSwarm( s, "time since last cancel is %jd -- increasing the number of peers we're interested in by %d", (intmax_t)timeSinceCancel, @@ -2259,7 +2258,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) { - logtraceSwarm(s, "purging peer %s because its doPurge flag is set", tr_atomAddrStr(atom)); + tr_logAddTraceSwarm(s, "purging peer %s because its doPurge flag is set", tr_atomAddrStr(atom)); return true; } @@ -2284,7 +2283,7 @@ static bool shouldPeerBeClosed(tr_swarm const* s, tr_peer const* peer, int peerC if (idleTime > limit) { - logtraceSwarm( + tr_logAddTraceSwarm( s, "purging peer %s because it's been %d secs since we shared anything", tr_atomAddrStr(atom), @@ -2352,7 +2351,7 @@ static int getReconnectIntervalSecs(struct peer_atom const* atom, time_t const n } } - logtrace("reconnect interval for %s is %d seconds", tr_atomAddrStr(atom), sec); + tr_logAddTrace("reconnect interval for %s is %d seconds", tr_atomAddrStr(atom), sec); return sec; } @@ -2386,16 +2385,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) { - logtraceSwarm(s, "resetting atom %s numFails to 0", tr_atomAddrStr(atom)); + tr_logAddTraceSwarm(s, "resetting atom %s numFails to 0", tr_atomAddrStr(atom)); atom->numFails = 0; } else { ++atom->numFails; - logtraceSwarm(s, "incremented atom %s numFails to %d", tr_atomAddrStr(atom), int(atom->numFails)); + tr_logAddTraceSwarm(s, "incremented atom %s numFails to %d", tr_atomAddrStr(atom), int(atom->numFails)); } - logtraceSwarm(s, "removing bad peer %s", tr_atomAddrStr(peer->atom)); + tr_logAddTraceSwarm(s, "removing bad peer %s", tr_atomAddrStr(peer->atom)); removePeer(peer); } @@ -2760,7 +2759,7 @@ static void atomPulse(evutil_socket_t /*fd*/, short /*what*/, void* vmgr) tr_ptrArrayAppend(&s->pool, keep[i]); } - logtraceSwarm(s, "max atom count is %d... pruned from %d to %d\n", maxAtomCount, atomCount, keepCount); + tr_logAddTraceSwarm(s, "max atom count is %d... pruned from %d to %d\n", maxAtomCount, atomCount, keepCount); /* cleanup */ tr_free(test); @@ -3014,7 +3013,7 @@ static void initiateConnection(tr_peerMgr* mgr, tr_swarm* s, struct peer_atom* a utp = utp && (atom->flags & ADDED_F_UTP_FLAGS) != 0; } - logtraceSwarm(s, "Starting an OUTGOING%s connection with %s", utp ? " µTP" : "", tr_atomAddrStr(atom)); + tr_logAddTraceSwarm(s, "Starting an OUTGOING%s connection with %s", utp ? " µTP" : "", tr_atomAddrStr(atom)); tr_peerIo* const io = tr_peerIoNewOutgoing( mgr->session, @@ -3028,7 +3027,7 @@ static void initiateConnection(tr_peerMgr* mgr, tr_swarm* s, struct peer_atom* a if (io == nullptr) { - logtraceSwarm(s, "peerIo not created; marking peer %s as unreachable", tr_atomAddrStr(atom)); + tr_logAddTraceSwarm(s, "peerIo not created; marking peer %s as unreachable", tr_atomAddrStr(atom)); atom->flags2 |= MyflagUnreachable; atom->numFails++; } diff --git a/libtransmission/platform.cc b/libtransmission/platform.cc index 049e036dd..e23f6cbd6 100644 --- a/libtransmission/platform.cc +++ b/libtransmission/platform.cc @@ -316,7 +316,7 @@ static bool isWebClientDir(std::string_view path) { auto tmp = tr_strvPath(path, "index.html"); bool const ret = tr_sys_path_exists(tmp.c_str(), nullptr); - tr_logAddInfo(_("Searching for web interface file \"%s\""), tmp.c_str()); + tr_logAddTrace("Searching for web interface file \"%s\"", tmp.c_str()); return ret; } diff --git a/libtransmission/resume.cc b/libtransmission/resume.cc index 31a900648..8ade15576 100644 --- a/libtransmission/resume.cc +++ b/libtransmission/resume.cc @@ -77,14 +77,14 @@ static auto loadPeers(tr_variant* dict, tr_torrent* tor) if (tr_variantDictFindRaw(dict, TR_KEY_peers2, &str, &len)) { size_t const numAdded = addPeers(tor, str, len); - tr_logAddTorDbg(tor, "Loaded %zu IPv4 peers from resume file", numAdded); + tr_logAddTraceTor(tor, "Loaded %zu IPv4 peers from resume file", numAdded); ret = tr_resume::Peers; } if (tr_variantDictFindRaw(dict, TR_KEY_peers2_6, &str, &len)) { size_t const numAdded = addPeers(tor, str, len); - tr_logAddTorDbg(tor, "Loaded %zu IPv6 peers from resume file", numAdded); + tr_logAddTraceTor(tor, "Loaded %zu IPv6 peers from resume file", numAdded); ret = tr_resume::Peers; } @@ -174,7 +174,7 @@ static auto loadDND(tr_variant* dict, tr_torrent* tor) } else { - tr_logAddTorDbg( + tr_logAddDebugTor( tor, "Couldn't load DND flags. DND list (%p) has %zu" " children; torrent has %d files", @@ -564,7 +564,7 @@ static auto loadProgress(tr_variant* dict, tr_torrent* tor) if (std::size(mtimes) != n_files) { - tr_logAddTorErr(tor, "got %zu mtimes; expected %zu", std::size(mtimes), size_t(n_files)); + tr_logAddWarnTor(tor, "got %zu mtimes; expected %zu", std::size(mtimes), size_t(n_files)); // if resizing grows the vector, we'll get 0 mtimes for the // new items which is exactly what we want since the pieces // in an unknown state should be treated as untested @@ -613,7 +613,7 @@ static auto loadProgress(tr_variant* dict, tr_torrent* tor) if (err != nullptr) { - tr_logAddTorDbg(tor, "Torrent needs to be verified - %s", err); + tr_logAddDebugTor(tor, "Torrent needs to be verified - %s", err); } else { @@ -659,12 +659,12 @@ static auto loadFromFile(tr_torrent* tor, tr_resume::fields_t fieldsToLoad, bool nullptr, &error)) { - tr_logAddTorDbg(tor, "Couldn't read \"%s\": %s", filename.c_str(), error->message); + tr_logAddDebugTor(tor, "Couldn't read \"%s\": %s", filename.c_str(), error->message); tr_error_clear(&error); return fields_loaded; } - tr_logAddTorDbg(tor, "Read resume file \"%s\"", filename.c_str()); + tr_logAddDebugTor(tor, "Read resume file \"%s\"", filename.c_str()); auto boolVal = false; auto i = int64_t{}; diff --git a/libtransmission/session-id.cc b/libtransmission/session-id.cc index 250c74905..9290bdf86 100644 --- a/libtransmission/session-id.cc +++ b/libtransmission/session-id.cc @@ -91,7 +91,7 @@ static tr_sys_file_t create_session_id_lock_file(char const* session_id) if (error != nullptr) { - tr_logAddError("Unable to create session lock file (%d): %s", error->code, error->message); + tr_logAddWarn("Unable to create session lock file (%d): %s", error->code, error->message); tr_error_free(error); } @@ -194,7 +194,7 @@ bool tr_session_id_is_local(char const* session_id) if (error != nullptr) { - tr_logAddError("Unable to open session lock file (%d): %s", error->code, error->message); + tr_logAddWarn("Unable to open session lock file (%d): %s", error->code, error->message); tr_error_free(error); } } diff --git a/libtransmission/session.cc b/libtransmission/session.cc index 6f23be70d..329d74ccc 100644 --- a/libtransmission/session.cc +++ b/libtransmission/session.cc @@ -75,9 +75,6 @@ static auto constexpr DefaultPrefetchEnabled = bool{ true }; #endif static auto constexpr SaveIntervalSecs = int{ 360 }; -#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) { return tr_port(tr_rand_int_weak(s->randomPortHigh - s->randomPortLow + 1) + s->randomPortLow); @@ -232,7 +229,7 @@ static void accept_incoming_peer(evutil_socket_t fd, short /*what*/, void* vsess { 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_logAddTrace("new incoming connection %" PRIdMAX " (%s)", (intmax_t)clientSocket, addrstr); tr_peerMgrAddIncoming(session->peerMgr, &clientAddr, clientPort, tr_peer_socket_tcp_create(clientSocket)); } @@ -694,7 +691,7 @@ static void tr_sessionInitImpl(init_data* data) TR_ASSERT(tr_amInEventThread(session)); TR_ASSERT(tr_variantIsDict(clientSettings)); - logtrace("tr_sessionInit: the session's top-level bandwidth object is %p", (void*)&session->bandwidth); + tr_logAddTrace("tr_sessionInit: the session's top-level bandwidth object is %p", (void*)&session->bandwidth); tr_variant settings; @@ -1592,7 +1589,7 @@ unsigned int tr_sessionGetAltSpeed_KBps(tr_session const* s, tr_direction d) static void userPokedTheClock(tr_session* s, struct tr_turtle_info* t) { - tr_logAddDebug("Refreshing the turtle mode clock due to user changes"); + tr_logAddTrace("Refreshing the turtle mode clock due to user changes"); t->autoTurtleState = TR_AUTO_SWITCH_UNUSED; @@ -1928,18 +1925,15 @@ void tr_sessionClose(tr_session* session) time_t const deadline = time(nullptr) + ShutdownMaxSeconds; - logdbg( - "shutting down transmission session %p... now is %zu, deadline is %zu", - (void*)session, - (size_t)time(nullptr), - (size_t)deadline); + tr_logAddInfo("Shutting down transmission session %p", (void*)session); + tr_logAddDebug("now is %zu, deadline is %zu", (size_t)time(nullptr), (size_t)deadline); /* close the session */ tr_runInEventThread(session, sessionCloseImpl, session); while (!session->isClosed && !deadlineReached(deadline)) { - logtrace("waiting for the libtransmission thread to finish"); + tr_logAddTrace("waiting for the libtransmission thread to finish"); tr_wait_msec(10); } @@ -1951,7 +1945,7 @@ void tr_sessionClose(tr_session* session) session->announcer_udp != nullptr) && !deadlineReached(deadline)) { - logtrace( + tr_logAddTrace( "waiting on port unmap (%p) or announcer (%p)... now %zu deadline %zu", (void*)session->shared, (void*)session->announcer, @@ -1968,7 +1962,7 @@ void tr_sessionClose(tr_session* session) while (session->events != nullptr) { static bool forced = false; - logtrace( + tr_logAddTrace( "waiting for libtransmission thread to finish... now %zu deadline %zu", (size_t)time(nullptr), (size_t)deadline); @@ -1976,14 +1970,14 @@ void tr_sessionClose(tr_session* session) if (deadlineReached(deadline) && !forced) { - logtrace("calling event_loopbreak()"); + tr_logAddTrace("calling event_loopbreak()"); forced = true; event_base_loopbreak(session->event_base); } if (deadlineReached(deadline + 3)) { - logtrace("deadline+3 reached... calling break...\n"); + tr_logAddTrace("deadline+3 reached... calling break...\n"); break; } } diff --git a/libtransmission/torrent-metainfo.cc b/libtransmission/torrent-metainfo.cc index 440ebd225..32d9d3c84 100644 --- a/libtransmission/torrent-metainfo.cc +++ b/libtransmission/torrent-metainfo.cc @@ -538,11 +538,7 @@ bool tr_torrent_metainfo::migrateFile( if (old_filename_exists && tr_sys_path_rename(old_filename.c_str(), new_filename.c_str(), nullptr)) { auto const name_sz = std::string{ name }; - tr_logAddNamedError( - name_sz.c_str(), - "Migrated torrent file from \"%s\" to \"%s\"", - old_filename.c_str(), - new_filename.c_str()); + tr_logAddNamedError(name_sz, "Migrated torrent file from \"%s\" to \"%s\"", old_filename.c_str(), new_filename.c_str()); return true; } diff --git a/libtransmission/torrent.h b/libtransmission/torrent.h index 9a3d8dac5..e0073c719 100644 --- a/libtransmission/torrent.h +++ b/libtransmission/torrent.h @@ -27,6 +27,7 @@ #include "file.h" #include "file-piece-map.h" #include "interned-string.h" +#include "log.h" #include "session.h" #include "torrent-metainfo.h" #include "tr-macros.h" @@ -777,3 +778,10 @@ tr_torrent_metainfo&& tr_ctorStealMetainfo(tr_ctor* ctor); bool tr_ctorSetMetainfoFromFile(tr_ctor* ctor, std::string const& filename, tr_error** error); bool tr_ctorSetMetainfoFromMagnetLink(tr_ctor* ctor, std::string const& filename, tr_error** error); void tr_ctorSetLabels(tr_ctor* ctor, tr_labels_t&& labels); + +#define tr_logAddCriticalTor(tor, ...) tr_logAddNamed(TR_LOG_CRITICAL, (tor)->name(), __VA_ARGS__) +#define tr_logAddErrorTor(tor, ...) tr_logAddNamed(TR_LOG_ERROR, (tor)->name(), __VA_ARGS__) +#define tr_logAddWarnTor(tor, ...) tr_logAddNamed(TR_LOG_WARN, (tor)->name(), __VA_ARGS__) +#define tr_logAddInfoTor(tor, ...) tr_logAddNamed(TR_LOG_INFO, (tor)->name(), __VA_ARGS__) +#define tr_logAddDebugTor(tor, ...) tr_logAddNamed(TR_LOG_DEBUG, (tor)->name(), __VA_ARGS__) +#define tr_logAddTraceTor(tor, ...) tr_logAddNamed(TR_LOG_TRACE, (tor)->name(), __VA_ARGS__) diff --git a/libtransmission/tr-dht.cc b/libtransmission/tr-dht.cc index 49d5c427b..2ac46e600 100644 --- a/libtransmission/tr-dht.cc +++ b/libtransmission/tr-dht.cc @@ -46,6 +46,14 @@ #include "utils.h" #include "variant.h" +#define logdbg(...) tr_logAddNamed(TR_LOG_DEBUG, "dht", __VA_ARGS__) +#define logdbgTor(tor, ...) tr_logAddNamed(TR_LOG_DEBUG, tr_torrentName(tor), __VA_ARGS__) +#define loginfo(...) tr_logAddNamed(TR_LOG_INFO, "dht", __VA_ARGS__) +#define logtrace(...) tr_logAddNamed(TR_LOG_TRACE, "dht", __VA_ARGS__) +#define logtraceTor(tor, ...) tr_logAddNamed(TR_LOG_TRACE, tr_torrentName(tor), __VA_ARGS__) +#define logwarn(...) tr_logAddNamed(TR_LOG_WARN, "dht", __VA_ARGS__) +#define logwarnTor(tor, ...) tr_logAddNamed(TR_LOG_WARN, tr_torrentName(tor), __VA_ARGS__) + using namespace std::literals; static struct event* dht_timer = nullptr; @@ -109,7 +117,7 @@ static void bootstrap_from_name(char const* name, tr_port port, int af) addrinfo* info = nullptr; if (int const rc = getaddrinfo(name, pp, &hints, &info); rc != 0) { - tr_logAddNamedError("DHT", "%s:%s: %s", name, pp, gai_strerror(rc)); + logwarn("%s:%s: %s", name, pp, gai_strerror(rc)); return; } @@ -147,7 +155,7 @@ static void dht_boostrap_from_file(tr_session* session) } // format is each line has address, a space char, and port number - tr_logAddNamedInfo("DHT", "Attempting manual bootstrap"); + logtrace("Attempting manual bootstrap"); auto line = std::string{}; while (!bootstrap_done(session, 0) && std::getline(in, line)) { @@ -158,7 +166,7 @@ static void dht_boostrap_from_file(tr_session* session) if (line_stream.bad() || std::empty(addrstr) || port <= 0) { - tr_logAddNamedError("DHT", "Couldn't parse line: \"%s\"", line.c_str()); + logwarn("Couldn't parse line: \"%s\"", line.c_str()); } else { @@ -180,12 +188,12 @@ static void dht_bootstrap(void* closure) if (cl->len > 0) { - tr_logAddNamedInfo("DHT", "Bootstrapping from %d IPv4 nodes", num); + logdbg("Bootstrapping from %d IPv4 nodes", num); } if (cl->len6 > 0) { - tr_logAddNamedInfo("DHT", "Bootstrapping from %d IPv6 nodes", num6); + logdbg("Bootstrapping from %d IPv6 nodes", num6); } for (int i = 0; i < std::max(num, num6); ++i) @@ -256,7 +264,7 @@ static void dht_bootstrap(void* closure) if (i == 0) { - tr_logAddNamedInfo("DHT", "Attempting bootstrap from dht.transmissionbt.com"); + logdbg("Attempting bootstrap from dht.transmissionbt.com"); } bootstrap_from_name("dht.transmissionbt.com", 6881, bootstrap_af(session_)); @@ -274,7 +282,7 @@ static void dht_bootstrap(void* closure) } tr_free(closure); - tr_logAddNamedDbg("DHT", "Finished bootstrapping"); + logtrace("Finished bootstrapping"); } int tr_dhtInit(tr_session* ss) @@ -284,7 +292,7 @@ int tr_dhtInit(tr_session* ss) return -1; } - tr_logAddNamedDbg("DHT", "Initializing DHT"); + loginfo("Initializing DHT"); if (tr_env_key_exists("TR_DHT_VERBOSE")) { @@ -333,13 +341,13 @@ int tr_dhtInit(tr_session* ss) if (have_id) { - tr_logAddNamedInfo("DHT", "Reusing old id"); + logtrace("Reusing old id"); } else { /* Note that DHT ids need to be distributed uniformly, * so it should be something truly random. */ - tr_logAddNamedInfo("DHT", "Generating new id"); + logtrace("Generating new id"); tr_rand_buffer(myid, 20); } @@ -348,7 +356,7 @@ int tr_dhtInit(tr_session* ss) tr_free(nodes6); tr_free(nodes); - tr_logAddNamedDbg("DHT", "DHT initialization failed (errno = %d)", errno); + logdbg("DHT initialization failed (errno = %d)", errno); session_ = nullptr; return -1; } @@ -366,7 +374,7 @@ int tr_dhtInit(tr_session* ss) dht_timer = evtimer_new(session_->event_base, timer_callback, session_); tr_timerAdd(dht_timer, 0, tr_rand_int_weak(1000000)); - tr_logAddNamedDbg("DHT", "DHT initialized"); + logdbg("DHT initialized"); return 1; } @@ -378,7 +386,7 @@ void tr_dhtUninit(tr_session* ss) return; } - tr_logAddNamedDbg("DHT", "Uninitializing DHT"); + logtrace("Uninitializing DHT"); if (dht_timer != nullptr) { @@ -390,7 +398,7 @@ void tr_dhtUninit(tr_session* ss) don't know enough nodes. */ if (tr_dhtStatus(ss, AF_INET, nullptr) < TR_DHT_FIREWALLED && tr_dhtStatus(ss, AF_INET6, nullptr) < TR_DHT_FIREWALLED) { - tr_logAddNamedInfo("DHT", "Not saving nodes, DHT not ready"); + logtrace("Not saving nodes, DHT not ready"); } else { @@ -406,7 +414,7 @@ void tr_dhtUninit(tr_session* ss) int num = MaxNodes; int num6 = MaxNodes; int n = dht_get_nodes(sins, &num, sins6, &num6); - tr_logAddNamedInfo("DHT", "Saving %d (%d + %d) nodes", n, num, num6); + logtrace("Saving %d (%d + %d) nodes", n, num, num6); tr_variant benc; tr_variantInitDict(&benc, 3); @@ -448,7 +456,7 @@ void tr_dhtUninit(tr_session* ss) } dht_uninit(); - tr_logAddNamedDbg("DHT", "Done uninitializing DHT"); + logtrace("Done uninitializing DHT"); session_ = nullptr; } @@ -607,7 +615,7 @@ static void callback(void* /*ignore*/, int event, unsigned char const* info_hash auto const pex = event == DHT_EVENT_VALUES ? tr_peerMgrCompactToPex(data, data_len, nullptr, 0) : tr_peerMgrCompact6ToPex(data, data_len, nullptr, 0); tr_peerMgrAddPex(tor, TR_PEER_FROM_DHT, std::data(pex), std::size(pex)); - tr_logAddTorDbg(tor, "Learned %zu %s peers from DHT", std::size(pex), event == DHT_EVENT_VALUES6 ? "IPv6" : "IPv4"); + logdbgTor(tor, "Learned %zu %s peers from DHT", std::size(pex), event == DHT_EVENT_VALUES6 ? "IPv6" : "IPv4"); } } else if (event == DHT_EVENT_SEARCH_DONE || event == DHT_EVENT_SEARCH_DONE6) @@ -616,12 +624,12 @@ static void callback(void* /*ignore*/, int event, unsigned char const* info_hash { if (event == DHT_EVENT_SEARCH_DONE) { - tr_logAddTorInfo(tor, "%s", "IPv4 DHT announce done"); + logtraceTor(tor, "%s", "IPv4 DHT announce done"); tor->dhtAnnounceInProgress = false; } else { - tr_logAddTorInfo(tor, "%s", "IPv6 DHT announce done"); + logtraceTor(tor, "%s", "IPv6 DHT announce done"); tor->dhtAnnounce6InProgress = false; } } @@ -652,7 +660,7 @@ static AnnounceResult tr_dhtAnnounce(tr_torrent* tor, int af, bool announce) if (status < TR_DHT_POOR) { - tr_logAddTorDbg( + logtraceTor( tor, "%s DHT not ready (%s, %d nodes)", af == AF_INET6 ? "IPv6" : "IPv4", @@ -665,7 +673,7 @@ static AnnounceResult tr_dhtAnnounce(tr_torrent* tor, int af, bool announce) int const rc = dht_search(dht_hash, announce ? tr_sessionGetPeerPort(session_) : 0, af, callback, nullptr); if (rc < 0) { - tr_logAddTorErr( + logwarnTor( tor, "%s DHT announce failed (%s, %d nodes): %s", af == AF_INET6 ? "IPv6" : "IPv4", @@ -675,7 +683,7 @@ static AnnounceResult tr_dhtAnnounce(tr_torrent* tor, int af, bool announce) return AnnounceResult::FAILED; } - tr_logAddTorInfo( + logtraceTor( tor, "Starting %s DHT announce (%s, %d nodes)", af == AF_INET6 ? "IPv6" : "IPv4", @@ -743,7 +751,7 @@ void tr_dhtCallback(unsigned char* buf, int buflen, struct sockaddr* from, sockl } else { - tr_logAddNamedError("DHT", "dht_periodic failed: %s", tr_strerror(errno)); + logwarn("dht_periodic failed: %s", tr_strerror(errno)); if (errno == EINVAL || errno == EFAULT) { diff --git a/libtransmission/upnp.cc b/libtransmission/upnp.cc index f223587b9..2790a7a9f 100644 --- a/libtransmission/upnp.cc +++ b/libtransmission/upnp.cc @@ -29,6 +29,18 @@ namespace char constexpr Key[] = "Port Forwarding (UPnP)"; +#undef tr_logAddError +#undef tr_logAddWarn +#undef tr_logAddInfo +#undef tr_logAddDebug +#undef tr_logAddTrace + +#define tr_logAddError(...) tr_logAddNamedError(Key, __VA_ARGS__) +#define tr_logAddWarn(...) tr_logAddNamedWarn(Key, __VA_ARGS__) +#define tr_logAddInfo(...) tr_logAddNamedInfo(Key, __VA_ARGS__) +#define tr_logAddDebug(...) tr_logAddNamedDebug(Key, __VA_ARGS__) +#define tr_logAddTrace(...) tr_logAddNamedTrace(Key, __VA_ARGS__) + enum class UpnpState { IDLE, @@ -129,7 +141,7 @@ static struct UPNPDev* tr_upnpDiscover(int msec, char const* bindaddr) if (have_err) { - tr_logAddNamedDbg(Key, "upnpDiscover failed (errno %d - %s)", errno, tr_strerror(errno)); + tr_logAddDebug("upnpDiscover failed (errno %d - %s)", errno, tr_strerror(errno)); } return ret; @@ -215,13 +227,7 @@ static int tr_upnpAddPortMapping(tr_upnp const* handle, char const* proto, tr_po if (err != 0) { - tr_logAddNamedDbg( - Key, - "%s Port forwarding failed with error %d (errno %d - %s)", - proto, - err, - errno, - tr_strerror(errno)); + tr_logAddDebug("%s Port forwarding failed with error %d (errno %d - %s)", proto, err, errno, tr_strerror(errno)); } errno = old_errno; @@ -285,16 +291,16 @@ tr_port_forwarding tr_upnpPulse(tr_upnp* handle, tr_port port, bool isEnabled, b if (UPNP_GetValidIGD(devlist, &handle->urls, &handle->data, handle->lanaddr, sizeof(handle->lanaddr)) == UPNP_IGD_VALID_CONNECTED) { - tr_logAddNamedInfo(Key, _("Found Internet Gateway Device \"%s\""), handle->urls.controlURL); - tr_logAddNamedInfo(Key, _("Local Address is \"%s\""), handle->lanaddr); + tr_logAddInfo(_("Found Internet Gateway Device \"%s\""), handle->urls.controlURL); + tr_logAddInfo(_("Local Address is \"%s\""), handle->lanaddr); handle->state = UpnpState::IDLE; handle->hasDiscovered = true; } else { handle->state = UpnpState::FAILED; - tr_logAddNamedDbg(Key, "UPNP_GetValidIGD failed (errno %d - %s)", errno, tr_strerror(errno)); - tr_logAddNamedDbg(Key, "If your router supports UPnP, please make sure UPnP is enabled!"); + tr_logAddDebug("UPNP_GetValidIGD failed (errno %d - %s)", errno, tr_strerror(errno)); + tr_logAddDebug("If your router supports UPnP, please make sure UPnP is enabled!"); } freeUPNPDevlist(devlist); @@ -309,7 +315,7 @@ tr_port_forwarding tr_upnpPulse(tr_upnp* handle, tr_port port, bool isEnabled, b ((tr_upnpGetSpecificPortMappingEntry(handle, "TCP") != UPNPCOMMAND_SUCCESS) || (tr_upnpGetSpecificPortMappingEntry(handle, "UDP") != UPNPCOMMAND_SUCCESS))) { - tr_logAddNamedInfo(Key, _("Port %d isn't forwarded"), handle->port); + tr_logAddInfo(_("Port %d isn't forwarded"), handle->port); handle->isMapped = false; } @@ -318,8 +324,7 @@ tr_port_forwarding tr_upnpPulse(tr_upnp* handle, tr_port port, bool isEnabled, b tr_upnpDeletePortMapping(handle, "TCP", handle->port); tr_upnpDeletePortMapping(handle, "UDP", handle->port); - tr_logAddNamedInfo( - Key, + tr_logAddInfo( _("Stopping port forwarding through \"%s\", service \"%s\""), handle->urls.controlURL, handle->data.first.servicetype); @@ -353,8 +358,7 @@ tr_port_forwarding tr_upnpPulse(tr_upnp* handle, tr_port port, bool isEnabled, b handle->isMapped = err_tcp == 0 || err_udp == 0; } - tr_logAddNamedInfo( - Key, + tr_logAddInfo( _("Port forwarding through \"%s\", service \"%s\". (local address: %s:%d)"), handle->urls.controlURL, handle->data.first.servicetype, @@ -363,13 +367,13 @@ tr_port_forwarding tr_upnpPulse(tr_upnp* handle, tr_port port, bool isEnabled, b if (handle->isMapped) { - tr_logAddNamedInfo(Key, "%s", _("Port forwarding successful!")); + tr_logAddInfo("%s", _("Port forwarding successful!")); handle->port = port; handle->state = UpnpState::IDLE; } else { - tr_logAddNamedDbg(Key, "If your router supports UPnP, please make sure UPnP is enabled!"); + tr_logAddInfo("%s", _("If your router supports UPnP, please make sure UPnP is enabled!")); handle->port = -1; handle->state = UpnpState::FAILED; } diff --git a/libtransmission/utils.cc b/libtransmission/utils.cc index b6909c744..ff38f7b8d 100644 --- a/libtransmission/utils.cc +++ b/libtransmission/utils.cc @@ -41,6 +41,7 @@ #include "error-types.h" #include "error.h" +#include "file.h" #include "log.h" #include "mime-types.h" #include "net.h" // ntohl() @@ -51,8 +52,6 @@ using namespace std::literals; -#define logtrace(...) tr_logAddNamed(TR_LOG_TRACE, nullptr, __VA_ARGS__) - time_t __tr_current_time = 0; /*** @@ -227,21 +226,19 @@ void tr_timerAddMsec(struct event* timer, int msec) uint8_t* tr_loadFile(char const* path, size_t* size, tr_error** error) { - char const* const err_fmt = _("Couldn't read \"%1$s\": %2$s"); - /* try to stat the file */ auto info = tr_sys_path_info{}; tr_error* my_error = nullptr; if (!tr_sys_path_get_info(path, 0, &info, &my_error)) { - tr_logAddDebug(err_fmt, path, my_error->message); + tr_logAddError("Couldn't read \"%1$s\": %2$s", path, my_error->message); tr_error_propagate(error, &my_error); return nullptr; } if (info.type != TR_SYS_PATH_IS_FILE) { - tr_logAddError(err_fmt, path, _("Not a regular file")); + tr_logAddError("Couldn't read \"%1$s\": Not a regular file", path); tr_error_set(error, TR_ERROR_EISDIR, "Not a regular file"sv); return nullptr; } @@ -256,7 +253,7 @@ uint8_t* tr_loadFile(char const* path, size_t* size, tr_error** error) auto const fd = tr_sys_file_open(path, TR_SYS_FILE_READ | TR_SYS_FILE_SEQUENTIAL, 0, &my_error); if (fd == TR_BAD_SYS_FILE) { - tr_logAddError(err_fmt, path, my_error->message); + tr_logAddError("Couldn't read \"%1$s\": %2$s", path, my_error->message); tr_error_propagate(error, &my_error); return nullptr; } @@ -264,7 +261,7 @@ uint8_t* tr_loadFile(char const* path, size_t* size, tr_error** error) auto* buf = static_cast(tr_malloc(info.size + 1)); if (!tr_sys_file_read(fd, buf, info.size, nullptr, &my_error)) { - tr_logAddError(err_fmt, path, my_error->message); + tr_logAddError("Couldn't read \"%1$s\": %2$s", path, my_error->message); tr_sys_file_close(fd, nullptr); tr_free(buf); tr_error_propagate(error, &my_error); @@ -279,7 +276,6 @@ uint8_t* tr_loadFile(char const* path, size_t* size, tr_error** error) bool tr_loadFile(std::vector& setme, std::string const& path, tr_error** error) { - char const* const err_fmt = _("Couldn't read \"%1$s\": %2$s"); auto const* const path_sz = path.c_str(); /* try to stat the file */ @@ -287,14 +283,14 @@ bool tr_loadFile(std::vector& setme, std::string const& path, tr_error** e tr_error* my_error = nullptr; if (!tr_sys_path_get_info(path_sz, 0, &info, &my_error)) { - tr_logAddDebug(err_fmt, path_sz, my_error->message); + tr_logAddError(_("Couldn't read \"%1$s\": %2$s"), path_sz, my_error->message); tr_error_propagate(error, &my_error); return false; } if (info.type != TR_SYS_PATH_IS_FILE) { - tr_logAddError(err_fmt, path_sz, _("Not a regular file")); + tr_logAddError(_("Couldn't read \"%1$s\": Not a regular file"), path_sz); tr_error_set(error, TR_ERROR_EISDIR, "Not a regular file"sv); return false; } @@ -303,7 +299,7 @@ bool tr_loadFile(std::vector& setme, std::string const& path, tr_error** e auto const fd = tr_sys_file_open(path_sz, TR_SYS_FILE_READ | TR_SYS_FILE_SEQUENTIAL, 0, &my_error); if (fd == TR_BAD_SYS_FILE) { - tr_logAddError(err_fmt, path_sz, my_error->message); + tr_logAddError(_("Couldn't read \"%1$s\": %2$s"), path_sz, my_error->message); tr_error_propagate(error, &my_error); return false; } @@ -311,7 +307,7 @@ bool tr_loadFile(std::vector& setme, std::string const& path, tr_error** e setme.resize(info.size); if (!tr_sys_file_read(fd, std::data(setme), info.size, nullptr, &my_error)) { - tr_logAddError(err_fmt, path_sz, my_error->message); + tr_logAddError(_("Couldn't read \"%1$s\": %2$s"), path_sz, my_error->message); tr_sys_file_close(fd, nullptr); tr_error_propagate(error, &my_error); return false; @@ -364,7 +360,7 @@ bool tr_saveFile(std::string const& filename, std::string_view contents, tr_erro return false; } - logtrace("Saved \"%s\"", filename.c_str()); + tr_logAddTrace("Saved \"%s\"", filename.c_str()); return true; } diff --git a/libtransmission/verify.cc b/libtransmission/verify.cc index 01c8fb176..bdf6044f2 100644 --- a/libtransmission/verify.cc +++ b/libtransmission/verify.cc @@ -43,7 +43,7 @@ static bool verifyTorrent(tr_torrent* tor, bool const* stopFlag) auto buffer = std::vector(1024 * 256); auto sha = tr_sha1_init(); - tr_logAddTorDbg(tor, "%s", "verifying torrent..."); + tr_logAddDebugTor(tor, "%s", "verifying torrent..."); tor->verify_progress = 0; while (!*stopFlag && piece < tor->pieceCount()) @@ -144,7 +144,7 @@ static bool verifyTorrent(tr_torrent* tor, bool const* stopFlag) /* stopwatch */ time_t const end = tr_time(); - tr_logAddTorDbg( + tr_logAddDebugTor( tor, "Verification is done. It took %d seconds to verify %" PRIu64 " bytes (%" PRIu64 " bytes per second)", (int)(end - begin), @@ -225,7 +225,7 @@ static void verifyThreadFunc() } tr_torrent* tor = currentNode.torrent; - tr_logAddTorInfo(tor, "%s", _("Verifying torrent")); + tr_logAddTraceTor(tor, "%s", _("Verifying torrent")); tor->setVerifyState(TR_VERIFY_NOW); auto const changed = verifyTorrent(tor, &stopCurrent); tor->setVerifyState(TR_VERIFY_NONE); @@ -246,7 +246,7 @@ static void verifyThreadFunc() void tr_verifyAdd(tr_torrent* tor, tr_verify_done_func callback_func, void* callback_data) { TR_ASSERT(tr_isTorrent(tor)); - tr_logAddTorInfo(tor, "%s", _("Queued for verification")); + tr_logAddTraceTor(tor, "%s", _("Queued for verification")); auto node = verify_node{}; node.torrent = tor; diff --git a/macosx/Torrent.mm b/macosx/Torrent.mm index d53fe5a7e..95d0f7f4a 100644 --- a/macosx/Torrent.mm +++ b/macosx/Torrent.mm @@ -354,7 +354,7 @@ bool trashDataFile(char const* filename, tr_error** error) { if (self.fResumeOnWake) { - tr_logAddNamedInfo(tr_torrentName(self.fHandle), "restarting because of wakeUp"); + tr_logAddNamedTrace(tr_torrentName(self.fHandle), "restarting because of wakeUp"); tr_torrentStart(self.fHandle); } } diff --git a/utils/remote.cc b/utils/remote.cc index 5d91a5973..ca7b204ba 100644 --- a/utils/remote.cc +++ b/utils/remote.cc @@ -2000,7 +2000,7 @@ static int processResponse(char const* rpcurl, std::string_view response) if (!tr_variantFromBuf(&top, TR_VARIANT_PARSE_JSON | TR_VARIANT_PARSE_INPLACE, response)) { - tr_logAddNamedError(MyName, "Unable to parse response \"%" TR_PRIsv "\"", TR_PRIsv_ARG(response)); + tr_logAddNamedWarn(MyName, "Unable to parse response \"%" TR_PRIsv "\"", TR_PRIsv_ARG(response)); status |= EXIT_FAILURE; } else @@ -2172,7 +2172,7 @@ static int flush(char const* rpcurl, tr_variant** benc) auto const res = curl_easy_perform(curl); if (res != CURLE_OK) { - tr_logAddNamedError(MyName, " (%s) %s", rpcurl_http.c_str(), curl_easy_strerror(res)); + tr_logAddNamedWarn(MyName, " (%s) %s", rpcurl_http.c_str(), curl_easy_strerror(res)); status |= EXIT_FAILURE; } else