From f099f356c603db3b75bf7aab54d8d2605e806cee Mon Sep 17 00:00:00 2001 From: arvidn Date: Sun, 2 Feb 2020 20:09:27 +0100 Subject: [PATCH] improve tracker debug logging --- src/torrent.cpp | 116 +++++++++++++++++++++++++++++------------------- 1 file changed, 70 insertions(+), 46 deletions(-) diff --git a/src/torrent.cpp b/src/torrent.cpp index 9ece52b62..ba5711d02 100644 --- a/src/torrent.cpp +++ b/src/torrent.cpp @@ -2909,8 +2909,22 @@ bool is_downloading_state(int const st) // so that each one should get at least one announce std::vector listen_socket_states; +#ifndef TORRENT_DISABLE_LOGGING + int idx = -1; + if (should_log()) + { + debug_log("*** announce: " + "[ announce_to_all_tiers: %d announce_to_all_trackers: %d num_trackers: %d ]" + , settings().get_bool(settings_pack::announce_to_all_tiers) + , settings().get_bool(settings_pack::announce_to_all_trackers) + , int(m_trackers.size())); + } +#endif for (auto& ae : m_trackers) { +#ifndef TORRENT_DISABLE_LOGGING + ++idx; +#endif // update the endpoint list by adding entries for new listen sockets // and removing entries for non-existent ones std::size_t valid_endpoints = 0; @@ -2964,15 +2978,11 @@ bool is_downloading_state(int const st) #ifndef TORRENT_DISABLE_LOGGING if (should_log()) { - debug_log("*** tracker: \"%s\" " - "[ tiers: %d trackers: %d" - " i->tier: %d tier: %d" - " working: %d limit: %d" - " can: %d sent: %d ]" - , ae.url.c_str(), settings().get_bool(settings_pack::announce_to_all_tiers) - , settings().get_bool(settings_pack::announce_to_all_trackers) - , ae.tier, state.tier, aep.is_working(), ae.fail_limit - , aep.can_announce(now, is_seed(), ae.fail_limit), state.sent_announce); + debug_log("*** tracker: (%d) [ep: %s ] \"%s\" [ i->tier: %d tier: %d" + " working: %d limit: %d can: %d sent: %d ]" + , idx, print_endpoint(aep.local_endpoint).c_str() + , ae.url.c_str(), ae.tier, state.tier, aep.is_working() + , ae.fail_limit, aep.can_announce(now, is_seed(), ae.fail_limit), state.sent_announce); } #endif @@ -3026,7 +3036,7 @@ bool is_downloading_state(int const st) if (should_log()) { debug_log("==> TRACKER REQUEST \"%s\" event: %s abort: %d ssl: %p " - "port: %d ssl-port: %d fails: %d upd: %d" + "port: %d ssl-port: %d fails: %d upd: %d ep: %s" , req.url.c_str() , (req.event == tracker_request::stopped ? "stopped" : req.event == tracker_request::started ? "started" : "") @@ -3039,7 +3049,8 @@ bool is_downloading_state(int const st) , m_ses.listen_port() , m_ses.ssl_listen_port() , aep.fails - , aep.updating); + , aep.updating + , print_endpoint(aep.local_endpoint).c_str()); } // if we're not logging session logs, don't bother creating an @@ -8848,8 +8859,22 @@ bool is_downloading_state(int const st) std::vector listen_socket_states; +#ifndef TORRENT_DISABLE_LOGGING + int idx = -1; + if (should_log()) + { + debug_log("*** update_tracker_timer: " + "[ announce_to_all_tiers: %d announce_to_all_trackers: %d num_trackers: %d ]" + , settings().get_bool(settings_pack::announce_to_all_tiers) + , settings().get_bool(settings_pack::announce_to_all_trackers) + , int(m_trackers.size())); + } +#endif for (auto const& t : m_trackers) { +#ifndef TORRENT_DISABLE_LOGGING + ++idx; +#endif for (auto const& aep : t.endpoints) { auto aep_state_iter = std::find_if(listen_socket_states.begin(), listen_socket_states.end() @@ -8863,41 +8888,39 @@ bool is_downloading_state(int const st) if (state.done) continue; + if (settings().get_bool(settings_pack::announce_to_all_tiers) + && state.found_working + && t.tier <= state.tier + && state.tier != INT_MAX) + continue; + + if (t.tier > state.tier && !settings().get_bool(settings_pack::announce_to_all_tiers)) break; + if (aep.is_working()) { state.tier = t.tier; state.found_working = false; } + if (aep.fails >= t.fail_limit && t.fail_limit != 0) continue; + if (!aep.enabled) continue; + #ifndef TORRENT_DISABLE_LOGGING - if (should_log()) - { - debug_log("*** tracker: \"%s\" " - "[ tiers: %d trackers: %d" - " found: %d i->tier: %d tier: %d" - " working: %d fails: %d limit: %d upd: %d ]" - , t.url.c_str(), settings().get_bool(settings_pack::announce_to_all_tiers) - , settings().get_bool(settings_pack::announce_to_all_trackers), state.found_working - , t.tier, state.tier, aep.is_working(), aep.fails, t.fail_limit - , aep.updating); - } + if (should_log()) + { + debug_log("*** tracker: (%d) [ep: %s ] \"%s\" [ found: %d i->tier: %d tier: %d" + " working: %d fails: %d limit: %d upd: %d ]" + , idx, print_endpoint(aep.local_endpoint).c_str(), t.url.c_str() + , state.found_working, t.tier, state.tier, aep.is_working() + , aep.fails, t.fail_limit, aep.updating); + } #endif - if (settings().get_bool(settings_pack::announce_to_all_tiers) - && state.found_working - && t.tier <= state.tier - && state.tier != INT_MAX) - continue; - - if (t.tier > state.tier && !settings().get_bool(settings_pack::announce_to_all_tiers)) break; - if (aep.is_working()) { state.tier = t.tier; state.found_working = false; } - if (aep.fails >= t.fail_limit && t.fail_limit != 0) continue; - if (!aep.enabled) continue; - if (aep.updating) - { - state.found_working = true; - } - else - { - time_point32 const next_tracker_announce = std::max(aep.next_announce, aep.min_announce); - if (next_tracker_announce < next_announce - && (!state.found_working || aep.is_working())) - next_announce = next_tracker_announce; - } + if (aep.updating) + { + state.found_working = true; + } + else + { + time_point32 const next_tracker_announce = std::max(aep.next_announce, aep.min_announce); + if (next_tracker_announce < next_announce + && (!state.found_working || aep.is_working())) + next_announce = next_tracker_announce; + } if (aep.is_working()) state.found_working = true; if (state.found_working && !settings().get_bool(settings_pack::announce_to_all_trackers) @@ -8916,7 +8939,7 @@ bool is_downloading_state(int const st) debug_log("*** update tracker timer: next_announce < now %d" " m_waiting_tracker: %d next_announce_in: %d" , next_announce <= now, m_waiting_tracker - , int(total_seconds(now - next_announce))); + , int(total_seconds(next_announce - now))); #endif // don't re-issue the timer if it's the same expiration time as last time @@ -10997,7 +11020,8 @@ bool is_downloading_state(int const st) aep->message = msg; fails = aep->fails; #ifndef TORRENT_DISABLE_LOGGING - debug_log("*** increment tracker fail count [%d]", aep->fails); + debug_log("*** increment tracker fail count [ep: %s url: %s %d]" + , print_endpoint(aep->local_endpoint).c_str(), r.url.c_str(), aep->fails); #endif // don't try to announce from this endpoint again if (ec == boost::system::errc::address_family_not_supported @@ -11005,7 +11029,7 @@ bool is_downloading_state(int const st) { aep->enabled = false; #ifndef TORRENT_DISABLE_LOGGING - debug_log("*** disabling endpoint [%s] for tracker \"%s\"" + debug_log("*** disabling endpoint [ep: %s url: %s ]" , print_endpoint(aep->local_endpoint).c_str(), r.url.c_str()); #endif }